Unaccounted lost time in Helix workitem processing

[MichalStrehovsky]

• This issue is blocking
• This issue is causing unreasonable pain

I was looking at logs from job https://helix.dot.net/api/jobs/fb0d553f-40cc-48b8-8ff2-5e7ca6762430/workitems?api-version=2019-06-17 that ran on the ARM64 queue.

I found it surprising that each of these workitems took minutes to finish, even though I know most of these tests complete in seconds.

We're losing machine time somewhere I couldn't pinpoint where from the logs:

The console log for the System.Collections.Tests workitem has this:

Console log: 'System.Collections.Tests' from job fb0d553f-40cc-48b8-8ff2-5e7ca6762430 workitem 35fcc6c3-ed55-4c7f-9b23-953d667f7502 (windows.10.arm64.open) executed on machine DDARM64S-033

C:\h\w\B668097B\w\B5910958\e>taskkill.exe /f /im corerun.exe 
ERROR: The process "corerun.exe" not found.

C:\h\w\B668097B\w\B5910958\e>call RunTests.cmd --runtime-path C:\h\w\B668097B\p 
----- start Wed 07/27/2022  2:41:39.11 ===============  To repro directly: ===================================================== 
pushd C:\h\w\B668097B\w\B5910958\e\
System.Collections.Tests.exe -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing -xml testResults.xml 
popd
===========================================================================================================

C:\h\w\B668097B\w\B5910958\e>System.Collections.Tests.exe -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing -xml testResults.xml  

/* Skipping for brevity */

Finished System.Collections.Tests, Version=7.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51

Tests run: 32511, Errors: 0, Failures: 0, Skipped: 109. Time: 5.1977535s
----- end Wed 07/27/2022  2:41:48.11 ----- exit code 0 ----------------------------------------------------------
2022-07-27T09:41:50.817Z	INFO   	run.py	run(48)	main	Beginning reading of test results.
2022-07-27T09:41:50.833Z	INFO   	run.py	__init__(42)	read_results	Searching 'C:\h\w\B668097B\w\B5910958\e' for test results files
2022-07-27T09:41:50.833Z	INFO   	run.py	__init__(48)	read_results	Found results file C:\h\w\B668097B\w\B5910958\e\testResults.xml with format xunit
2022-07-27T09:41:53.301Z	INFO   	run.py	__init__(42)	read_results	Searching 'C:\h\w\B668097B\w\B5910958\uploads' for test results files
2022-07-27T09:41:53.301Z	INFO   	run.py	packing_test_reporter(30)	report_results	Packing 32511 test reports to 'C:\h\w\B668097B\w\B5910958\e\__test_report.json'
2022-07-27T09:41:53.848Z	INFO   	run.py	packing_test_reporter(33)	report_results	Packed 12542843 bytes
Did not find dumps, skipping dump docs generation.

So we know the "useful work" finished in less than 20 seconds. Of course I expect some overhead due to downloading and uploading, but it doesn't explain the "Queued":"2022-07-27T07:27:47.745+00:00","Started":"2022-07-27T09:41:09.609+00:00","Finished":"2022-07-27T09:47:58.545+00:00","Delay":"02:13:21.8640000","Duration":"00:06:48.9360000". Where did we spend the other 6 minutes?

Digging into the run_client.py log, I see:

2022-07-27T09:41:38.864Z	INFO   	executor(833)	_execute_command	running %HELIX_CORRELATION_PAYLOAD%\scripts\0f507811259646bf86fd7d51a4ddb483\execute.cmd in C:\h\w\B668097B\w\B5910958\e max 2700 seconds
2022-07-27T09:41:54.411Z	INFO   	job(38)	wait	Work item's process exited normally.
2022-07-27T09:42:41.259Z	INFO   	interval(82)	event	Invoke callback for timer, arguments: None
2022-07-27T09:42:41.259Z	INFO   	servicebusrepository(106)	renew_workitem_lock	Renewing lock for ServiceBus item MessageId 'ed43292dcc4840348b0966a2025fd012' with url 'https://nethelix.servicebus.windows.net/windows.10.arm64.open/messages/3732380/d8ac9553-6b65-4f19-b839-66ab560b90d4'
2022-07-27T09:42:41.406Z	INFO   	saferequests(87)	request_with_retry	Response complete with status code '200'
2022-07-27T09:42:41.406Z	INFO   	servicebusrepository(116)	renew_workitem_lock	Renewed work item lock. Status Code: 200
2022-07-27T09:42:41.406Z	INFO   	interval(54)	setup_timer	Timer set to 90 seconds
2022-07-27T09:44:11.418Z	INFO   	interval(82)	event	Invoke callback for timer, arguments: None
2022-07-27T09:44:11.418Z	INFO   	servicebusrepository(106)	renew_workitem_lock	Renewing lock for ServiceBus item MessageId 'ed43292dcc4840348b0966a2025fd012' with url 'https://nethelix.servicebus.windows.net/windows.10.arm64.open/messages/3732380/d8ac9553-6b65-4f19-b839-66ab560b90d4'
2022-07-27T09:44:11.559Z	INFO   	saferequests(87)	request_with_retry	Response complete with status code '200'
2022-07-27T09:44:11.559Z	INFO   	servicebusrepository(116)	renew_workitem_lock	Renewed work item lock. Status Code: 200
2022-07-27T09:44:11.559Z	INFO   	interval(54)	setup_timer	Timer set to 90 seconds
2022-07-27T09:45:28.108Z	INFO   	interval(70)	cancel_abort_after	Cancel abort_after for timer
2022-07-27T09:45:28.108Z	INFO   	interval(67)	set_abort_after_timer	Set the timer's abort_after to 660 seconds from now: abort_after = 2022-07-27 02:56:28.108918
2022-07-27T09:45:28.108Z	INFO   	executor(759)	_dump_file_upload	No dump files to upload.
2022-07-27T09:45:28.108Z	INFO   	interval(67)	set_abort_after_timer	Set the timer's abort_after to 180 seconds from now: abort_after = 2022-07-27 02:48:28.108918
2022-07-27T09:45:28.108Z	INFO   	executor(959)	_upload_files	Allowing maximum 0.0 seconds to upload 0 bytes of files.
2022-07-27T09:45:28.108Z	INFO   	interval(67)	set_abort_after_timer	Set the timer's abort_after to 60.0 seconds from now: abort_after = 2022-07-27 02:46:28.108918
2022-07-27T09:45:28.108Z	INFO   	executor(877)	_execute_command	Finished _execute_command, exit code: 0
2022-07-27T09:45:28.108Z	INFO   	executor(920)	_upload_single_file	Uploading the file console.6425316b.log

So we see that the workitem exited at 09:41:54 but it looks like we spent three and a half minutes until 09:45:28 doing nothing?

Then we spend another 2 minutes publishing the results:

2022-07-27T09:45:53.168Z	INFO   	azure_devops_result_publisher(153)	_process	uploaded 997 results
2022-07-27T09:46:11.535Z	INFO   	azure_devops_result_publisher(153)	_process	uploaded 1962 results
2022-07-27T09:46:38.378Z	INFO   	azure_devops_result_publisher(153)	_process	uploaded 2959 results
2022-07-27T09:47:05.906Z	INFO   	azure_devops_result_publisher(153)	_process	uploaded 3957 results
2022-07-27T09:47:12.438Z	INFO   	interval(82)	event	Invoke callback for timer, arguments: None
2022-07-27T09:47:12.516Z	INFO   	servicebusrepository(106)	renew_workitem_lock	Renewing lock for ServiceBus item MessageId 'ed43292dcc4840348b0966a2025fd012' with url 'https://nethelix.servicebus.windows.net/windows.10.arm64.open/messages/3732380/d8ac9553-6b65-4f19-b839-66ab560b90d4'
2022-07-27T09:47:13.156Z	INFO   	saferequests(87)	request_with_retry	Response complete with status code '200'
2022-07-27T09:47:13.344Z	INFO   	servicebusrepository(116)	renew_workitem_lock	Renewed work item lock. Status Code: 200
2022-07-27T09:47:13.438Z	INFO   	interval(54)	setup_timer	Timer set to 90 seconds
2022-07-27T09:47:27.007Z	INFO   	azure_devops_result_publisher(153)	_process	uploaded 4860 results
2022-07-27T09:47:44.195Z	INFO   	azure_devops_result_publisher(153)	_process	uploaded 5600 results

It feels like we should be able to do something to make this more efficient.

[MattGal]

This is an interesting find. I believe this all relates to how we run python on ARM64 windows. Unfortunately, until a native ARM64 version of Python exists (and likely, some of our dependencies publish compatible updates) this will remain a problem for ARM64 windows machines. Note that all x86 processes on ARM64 windows machines are human-visibly slower in general, and this is the only way to run python on this platform today.

Picking apart one piece of this slowness, from a recent AMD version of this same workitem

2022-07-28T17:02:21.048Z	INFO   	job(38)	wait	Work item's process exited normally.
...
2022-07-28T17:02:21.064Z	INFO   	executor(897)	_execute_command	Finished _execute_command, exit code: 0

The delta between when the work item exits and the executor logs that this happened is a scorching 0.016 seconds, pretty darn fast.

The same time delta, as you noticed, in ARM64 windows is a whopping 3:53.

2022-07-28T11:43:23.685Z	INFO   	job(38)	wait	Work item's process exited normally.
...
2022-07-28T11:47:14.239Z	INFO   	executor(897)	_execute_command	Finished _execute_command, exit code: 0

Note identical python code is used for both logs here. I reviewed what happens between these lines, and a quick summary:

• Executor calls Job.wait, which logs the first line; the process exited without having to be told to.
• Inside wait():
  • Timer object is nulled out
  • Job checks if the work item timed out and was killed; it was not so no action taken
  • kill_any_leaked_workitem_processes() is called; this walks every process on the machine and is clearly fast on AMD64, but due to the abstraction layer (x86 emulation is often very noticeably slow) this process seems to take a VERY long time.
• Executor nulls out a timer object (nigh instantaneous)
• Executor checks exit code and decides not to sleep at all since it’s 0 (would otherwise wait for some dumps)
• Executor checks for whether dump files exist (they don’t) so it does nothing.
• Executor uploads log file (in your case, almost instant, 14 KB file)
• Executor logs the 2nd line.

The only interesting work that actually happens at all here is the process walk, and an x86 process running on an emulation layer walking the ARM, ARM64, and x86 processes of a machine is just slow.

It would be pretty easy to introduce a workaround here to skip kill_any_leaked_workitem_processes() if we are running on an ARM64 windows machine, but this function more or less exists to serve on-premises machines since they live much, much longer than our ephemeral AMD64 VMs and processes can and do leak.

Eventually we will have both ARM64 Azure capacity (so the machines become ephemeral) and we’ll have native-Windows-ARM64 python (rumors say in 3.11) and this problem won’t exist. Until then, I don’t think this can be made better without removing the leaked work item check.

[MichalStrehovsky]

Thank you for the analysis! This is very puzzling.

@marek-safar do you know what's the status of ARM64 Windows Python? This also looks like something that might be worth investigating by the Windows team too - an action that takes less than a second natively takes minutes under emulation on ARM64. We're running into something pathological. Marek - do you have any contacts for that?

[vitek-karas]

FYI @pragmanomos - who might have some insights into this

[marek-safar]

@pragmanomos please try to help here.

[pragmanomos]

Hello, you can find experimental pre-release builds of WoARM64 Python here. Official support will be introduced starting with 3.11 (see here). Email thread ongoing.

[MattGal]

Doing a few experiments, I realized this doesn't always happen. From the separate email thread, I think we'll hold off on trying ARM64 python until it's ready to go (experimentally trying, the one above can't install our dependency list) but I will convert the machines in the staging environment over to AMD64 manually and see if this poses any problems; if it doesn't, we might as well move all our Windows machines over to 64-bit python3 anyways.

[MattGal]

I realized that this doesn't seem to happen on the closed queue (see work item 5303d8f1-e9a7-4096-bf7b-64941d9952ad for an example of near identical jobs not hitting it; nor did staging). One interesting variance between the machines with the slowdown and not is that the ones in the .open queue (the slow ones) are running Windows 10 20H1, which is end of life anyways.

I filed https://portal.microsofticm.com/imp/v3/incidents/details/324098710/home to track reimaging them to a supported OS; if this solves the problem, great (it certainly seems to be correlated with this taking less time). Putting this issue into tracking while that is ongoing.

[MattGal]

I spent some time checking out the reimaged machines today. They definitely have newer Windows on them but hit the same symptom.

However, given that the version of Windows 10 these machines have still cannot run AMD64 executables, and the ARM64 version of Windows python3 is still not compatible with the libraries the helix client we need, I don't think there's anything we can do beyond updating the OS to a non-expired version; we do not want to have the process-walking behavior change for a specific queue, especially one which needs such functionality.