Unexpected time delays

[petemoore]

Strangely, at the moment when I run tup natively on my M1 Mac, I consistently have ~ 4.5s overhead for some tasks, compared to the time when running the same tasks under docker on the same Mac.

I profiled a tup run to see if I could find where the time is being spent.

This is the output of the tup run:

Timestamp	Text	
00:00.361.715	[ tup ] [0.000s] Scanning filesystem...	
00:00.367.681	[ tup ] [0.008s] Reading in new environment variables...	
00:00.367.764	[ tup ] [0.008s] No Tupfiles to parse.	
00:00.367.764	[ tup ] [0.008s] No files to delete.	
00:00.367.764	[ tup ] [0.008s] Executing Commands...	
00:05.003.202	  22% 10) [4.532s] src/spectrum128k/tests: cat test_po_any.custom.s | ../../../utils/asm-format/asm-format check	
00:05.003.202	2024/01/16 19:00:56.361039 Starting	
00:05.003.202	2024/01/16 19:00:56.361533 Stopping	
00:05.033.736	  45%  9) [4.563s] src/spectrum128k/tests: ./tests.sh test_po_any.custom.s > test_po_any.custom.runner	
00:05.033.736	2024/01/16 19:00:56.379731 Starting	
00:05.033.736	2024/01/16 19:00:56.380849 Stopping	
00:05.066.976	  58%  7) [0.033s] src/spectrum128k/tests: z80-unknown-elf-as -o test_po_any.custom.o test_po_any.custom.runner	
00:05.068.071	[ tup ] [4.713s] Updated.	

I also added 'Starting' and 'Stopping' messages to the asm-format code at the start and end of the code.
Here we see that both tasks took in excess of 4.5s to run, even though between 'Starting' and 'Stopping' there were 0.5ms and 1ms. So the 4.5s overhead seems to be external to the code being called. Note, the tup id 9) calls a bash script which calls asm-format, so its Starting/Stopping numbers do not include the rest of the bash script - but for the sake of this report, tup id 10) is the one that demonstrates the issue best.

I've created a recording in macOS Instruments which includes os_log, stdout/stderr, dyld Activity, Hangs, CPU Usage, and Time Profiler. It is 11MB in size - happy to provide it. Not sure if it contains sensitive data, so haven't attached it here, but can provide it via some other means if required.

Note, I compiled from HEAD (8739d02) for this test, to make sure the issue is still present in development version.

I'm also fully aware, it could be a problem with my system rather than with tup. Certainly, the profile timings from this screenshot look pretty reasonable, and don't account for the 4.5 second lag, only accounting for some ms of the total 4.7s end-to-end time.

One thing that appears strange to me is when I look at the samples that Instruments took, it seems to have stopped taking samples exactly when the freezes appear to have happened:

Anyway, let me know if I should provide any other information, or if you'd like the 11MB Instruments recording. Thanks!