CI timeout (test-llava-runner-linux) since #7922

[swolchok]

🐛 Describe the bug

Changing from nightly wheel to --use-pt-pinned-commit (from-source build of PyTorch pinned commit, which matches nightly) caused CI timeouts for long jobs, apparently with large timestamp "gaps" in logs

• HUD page illustrating when test-llava-runner-linux went red
• Blame PR, executorch/7922

In the raw logs for the first test-llava-runner-linux timeout on main, there are almost 40 minutes (EDIT: actually 83 minutes, see 43-minute gap below) of "gaps" in the logs with no timestamps. Specifically:

• 14 minute "gap" in logs, jump from 2025-01-31T23:11:50.6702881Z to 2025-01-31T23:25:21.0383351Z, during export.
• 25 minute "gap" in logs from 2025-01-31T23:25:21.2243143Z to 2025-01-31T23:42:40.6914293Z , and the second message is just a job timeout. Seems to also be during export; not sure why we are exporting multiple times offhand, but that's a separate problem regardless.

@metascroy found that increasing the timeout to 180 minutes causes the job in question to succeed after 150 minutes.

I've ruled out safetensors download being the cause; it took about 6.5 minutes in the last good run and about 6 minutes in the first bad run.

Versions

N/A

[swolchok]

The first log gap is also strange -- the "internal" timestamp of the log mesage after the gap is from before the gap!

2025-01-31T23:11:50.6701775Z [INFO 2025-01-31 23:11:50,659 builder.py:211] Exporting with:
2025-01-31T23:11:50.6702881Z [INFO 2025-01-31 23:11:50,660 builder.py:212] inputs: (tensor([0]), tensor([[[ 0.0045, -0.0038,  0.0017,  ..., -0.0088,  0.0025, -0.0025],
2025-01-31T23:25:21.0383351Z          [-0.0112, -0.0129, -0.0121,  ...,  0.0090,  0.0118, -0.0081],
2025-01-31T23:25:21.0384234Z          [ 0.0195, -0.0058,  0.0061,  ...,  0.0171, -0.0052, -0.0212],
2025-01-31T23:25:21.0384805Z          ...,
2025-01-31T23:25:21.0386617Z          [-0.0187, -0.0017,  0.0177,  ...,  0.0238,  0.0052,  0.0101],
2025-01-31T23:25:21.0387267Z          [ 0.0066, -0.0161,  0.0117,  ..., -0.0103,  0.0148,  0.0073],
2025-01-31T23:25:21.0388147Z          [ 0.0039,  0.0015,  0.0055,  ..., -0.0042,  0.0151,  0.0024]]],
2025-01-31T23:25:21.0388845Z        grad_fn=<CatBackward0>))
2025-01-31T23:25:21.0389468Z [INFO 2025-01-31 23:11:50,660 builder.py:213] kwargs: None
2025-01-31T23:25:21.0390782Z [INFO 2025-01-31 23:11:50,660 builder.py:214] dynamic shapes: ({0: 1}, {1: <class 'executorch.examples.models.llava.model.token_dim'>})
2025-01-31T23:25:21.0392301Z [INFO 2025-01-31 23:12:18,280 builder.py:321] Using pt2e [] to quantizing the model...
2025-01-31T23:25:21.0393555Z [INFO 2025-01-31 23:12:18,280 builder.py:366] No quantizer provided, passing...

definitely wondering if we are swapping.

[swolchok]

Found another 43-minute gap in the logs before the first one I identified previously:

2025-01-31T22:25:17.0525537Z [WARNING 2025-01-31 22:25:17,042 quantized_kv_cache.py:273] Replacing KVCache with CustomKVCache. This modifies the model in place.
2025-01-31T23:08:22.3657932Z [WARNING 2025-01-31 22:25:17,042 quantized_kv_cache.py:273] Replacing KVCache with CustomKVCache. This modifies the model in place.

[swolchok]

There are also timestamp gaps in the "good" logs!

2025-01-31T22:29:01.0922046Z [INFO 2025-01-31 22:29:00,968 GPTQ.py:1139] linear: text_model.layers.29.feed_forward.w2, in=11008, out=4096
2025-01-31T22:44:55.4846123Z [INFO 2025-01-31 22:29:01,082 GPTQ.py:1139] linear: text_model.layers.29.feed_forward.w3, in=4096, out=11008

[swolchok]

swapping

c5.24xlarge instances, which these jobs run in, have 192 GB of RAM. If we are swapping, something is wrong.

[swolchok]

after we're done here we should revert #8173 , which raised the timeout to 180 minutes so that the job can at least succeed despite now taking 150 minutes

[swolchok]

Llava export was taking longer than advertised even before the job started timing out. In the last good log, from https://github.com/pytorch/executorch/blame/main/.ci/scripts/test_llava.sh#L105 ("Starting to export Llava. This will take about 6 mins") to the export finishing (prepare_image_tensor) is actually around 15 minutes. The bad log is not starting the second export.

[swolchok]

Just watching free while running test_llava, it appears to take at least 80 GB of RAM, which seems like a lot (but not enough to exhaust the 192 GB of RAM in a 24xlarge runner...)

[swolchok]

my theory is we're swapping during export both before and after the change to --use-pt-pinned-commit, and something about the change made our memory usage worse. So, I've spent the last hour or so trying out a couple Python heap profiling tools (guppy and tracemalloc), but they only show Python-interpreter allocations, which is not helpful for PyTorch where I would very much also like to know how much memory is allocated in Tensors

we're swapping

and, to be clear, if true that would be a big engineering problem with export/lowering/quantization, since the model safetensors size is only 15 GB and the CI machine in question has 192 GB of RAM. we have some anecdotal evidence that this phase uses "too much" memory (machines can't quantize models they should be able to run) but I believe swapping would require "way way too much" memory to be in use...

[swolchok]

@atalman from PyTorch dev infra agreed that the --use-pt-pinned-commit build should not be worse offhand.

[swolchok]

@huydhn , I think you worked on putting --use-pt-pinned-commit in place, any reason you're aware of that that build should perform worse or use more memory than a nightly wheel?

[swolchok]

#8193 finished test-llava-runner-linux in 67 minutes, so we can be reasonably confident that --use-pt-pinned-commit is causing the excessive running times

[huydhn]

@huydhn , I think you worked on putting --use-pt-pinned-commit in place, any reason you're aware of that that build should perform worse or use more memory than a nightly wheel?

Nothing obvious comes to mind. Let me compare the two wheels to see if I can spot anything there.

[swolchok]

#8192 seems to indicate that we're not swapping. I'm hesitant to continue to speculate-and-test about possible sources of the gaps in timestamps, since that could consume a lot of time, but I'm not sure how else to make progress here...

[swolchok]

assigning to @huydhn for now because he found the likely source of regression