Investigate hiccups that make preloading slow

[ben-grande]

The problem you're addressing (if any)

This is a continuation of a discussion on #1512, opened as a separate issue for the contents to not be lost behind hudreds of "load more" buttons meant as a feature request to to improve preload time.

I wrote:

The disposable stages that make the usage a bit long is the following:

Preload:

• start (offloaded with preloaded disposable)
• pause if preloaded (offlaoded with preloaded disposable)

Using:

• unpause if preloaded (didn't time this)
• preloads another disposable (this event is fired after a preload is marked as used, it uses asyncio.ensure_future(), it doesn't impact retrieving the preloaded disposable because of this, but it impacts on other operations, such as the execution and/or cleanup as these are coroutines)
• execution
• cleanup

user@dom0:~$ time qvm-run -p --no-gui --no-color-stder --no-color-output --dispvm -- 'echo $HOSTNAME'
Starting: 01:32.145448
Starting run_command_single: 01:32.145906
Creating proc: 01:32.145941
disp3991
Finished proc: 01:32.908777
Before cleanup: 01:32.909267
After cleanup: 01:34.905010

real    0m2.902s
user    0m0.094s
sys     0m0.075s

If I add a 3 seconds delay to domain-preload-dispvm-start in DispVM.use_preload():

user@dom0:~$ time qvm-run -p --no-gui --no-color-stder --no-color-output --dispvm -- 'echo $HOSTNAME'
Starting: 03:23.699683
Starting run_command_single: 03:23.700117
Creating proc: 03:23.700142
disp4272
Finished proc: 03:24.456369
Before cleanup: 03:24.456697
After cleanup: 03:25.677925

real    0m2.117s
user    0m0.097s
sys     0m0.064s

The major issues are:

• 1 second without load: cleanup, which on qubesadmin just calls kill() and the server is responsible for the rest.
• 1 second without load: preloading, because the DispVM.use_preload() is called right

But I am not sure if it is useful to add a delay by default. Some things do not benefit from adding a delay to preload, such as commands run in the background and the user is not aware it is still running, such as clicking on app menu or applications from qui-domains. If you add a 1-3 seconds delay and have workflows with multiple iterations, it actually worsens the time because some iterations will take longer as the preload is not ready yet.

This discussion is related to the preloading benchmark and visualization. Therefore, the current average that calls right after a call finish is useful for workflows that require a lot of preloaded disposables, but it doesn't reflect the average from a "cold" request, which is fast as there is no load on the system compared to a "warm/hot" start, where there are multiple preloads being created, used and cleaned simultaneously. The value that best reflect how fast a preload can be used is a single metric, the execution and total from the first iteration.

If you know you will only need a certain amount of preloaded disposables and the time to use each one is long (at least longer than the time to preload a disposable), there is value in a setting: preload-dispvm-delay: int. Suppose there is a workflow that requires 4 qubes and takes 15s or longer (suppose also that the time to preload is 8s), the fastest way to execute and cleanup each qube would be to use concurrency and a delay of 3s (I guesstimated these numbers). There is a problem, this is such a specialized workflow that I am not sure it is widely applicable and easily to write a documentation for, it is a possible future improvement though. Let's see some workflows:

• You have a workflow with a limited number of operations, such as opening mail attachments, that for some people, may be 4 attachements. If you can preload 4 and with the preload-dispvm-delay to 3s, you'd get the fastest usage/display of the 4 attachments.
• You have a workflow with a lot of operations, converting 50 PDFs to trusted PDFs, preloading 50 qubes is not really "nice" to your system, but preloading 4 with a preload-dispvm-delay of 0 would bring the best results.

I hope I made it easier to understand with these examples.

@marmarek wrote:

Generally, the main reason for the preloaded feature is to lower the time between user action that requires disposable and getting that action done. If that's a PDF conversion, it's mostly full call time (but not really cleanup). But if that's opening a file in a disposable, it's just the wait time for the application to open. Bulk processing may be improved by preloaded a bit, but it's not the main focus. It shouldn't get worse, though.

It would be useful to measure time until user application (fully) starts, not until it completes (and dom0 gets that info). The latter may include some clean steps that are less relevant for user experience really - especially, I hope preloading next disposable in the background affect application start only in a small way, but may affect cleanup more. What if you use date as the command and compare timestamp this way? This assumes preloaded disposable has accurate clock, but I hope this is the case...
If preloading next one indeed affects the current startup, then having default non-zero delay IMO makes sense.

Check also if calling from a VM makes any difference in startup time - you'll likely get less detailed timing info, but I think overall time should be similar, right? Maybe qvm-run-vm --dispvm date ?

You have a workflow with a lot of operations, converting 50 PDFs to trusted PDFs, preloading 50 qubes is not really "nice" to your system, but preloading 4 with a preload-dispvm-delay of 0 would bring the best results.

For the use case like this, I'm not convinced preloading will help that much... it may help with the first PDF (latency to start conversion), but you'll run out of preloaded pretty soon. And if the conversion is fast, preloading will not speed it up much, but may slow down the actual conversion happening in the meantime (depending on available CPU cores).
Maybe it's worth doing a test like this and see how actually it behaves? (but don't enable it in CI, too long to execute every time)

What happens if preload-dispvm-delay is set to some time, and a dispvm is requested earlier? Does it wait for that time to expire, or start a non-preloaded before that?

The solution you'd like

Decrease total preload usage time.

The value to a user and who that user might be

Users of preloaded disposables will have a faster usage.

Completion criteria checklist

No response

[ben-grande]

Not considering arbitrary delays from the first post or messing with cleanup, there are also other things that can make preload slow: how many qubes you choose to preload. More is not always better, it depends on the intended use case.

These tests were conducted on a machine with 32GB of RAM, Xen 4.19.3, Kernel 6.15.10-1, Intel Ultra 7 155H with default autostarted qubes running. The test uses variations of
qubes.tests.integ.dispvm_perf/TC_00_DispVMPerf_fedora-42-xfce/test_404_dom0_dispvm_preload_api, using the preload-reader branch.

2 preloads: Run time (iterations=12 mean=8.070): 96.837s

iter	dom	disp	exec	clean	total	dom%	disp%	exec%	clean%
1	0.032	0.000	0.500	1.999	2.531	1%	0%	20%	79%
2	0.044	0.000	0.436	2.026	2.506	2%	0%	17%	81%
3	0.025	0.000	13.562	2.278	15.865	0%	0%	85%	14%
4	0.047	0.000	3.517	1.833	5.397	1%	0%	65%	34%
5	0.041	0.000	11.094	2.311	13.447	0%	0%	83%	17%
6	0.043	0.000	1.867	1.848	3.758	1%	0%	50%	49%
7	0.022	0.000	12.237	1.898	14.157	0%	0%	86%	13%
8	0.040	0.000	1.256	2.301	3.598	1%	0%	35%	64%
9	0.029	0.000	12.156	2.022	14.208	0%	0%	86%	14%
10	0.037	0.000	1.376	2.404	3.817	1%	0%	36%	63%
11	0.040	0.000	11.667	2.242	13.948	0%	0%	84%	16%
12	0.042	0.000	1.590	1.972	3.604	1%	0%	44%	55%

• 3 preloads: Run time (iterations=12 mean=5.372): 64.466s

iter	dom	disp	exec	clean	total	dom%	disp%	exec%	clean%
1	0.025	0.000	0.288	1.982	2.295	1%	0%	13%	86%
2	0.023	0.000	0.345	2.184	2.552	1%	0%	14%	86%
3	0.029	0.000	0.980	1.897	2.906	1%	0%	34%	65%
4	0.025	0.000	10.285	2.063	12.373	0%	0%	83%	17%
5	0.033	0.000	0.794	2.246	3.074	1%	0%	26%	73%
6	0.033	0.000	3.361	2.165	5.558	1%	0%	60%	39%
7	0.039	0.000	7.195	2.166	9.399	0%	0%	77%	23%
8	0.043	0.000	1.408	1.942	3.393	1%	0%	41%	57%
9	0.025	0.000	2.892	2.252	5.169	0%	0%	56%	44%
10	0.044	0.000	7.135	1.909	9.088	0%	0%	79%	21%
11	0.032	0.000	1.356	2.028	3.416	1%	0%	40%	59%
12	0.043	0.000	2.931	2.268	5.242	1%	0%	56%	43%

• 4 preloads: Run time (iterations=12 mean=4.660): 55.920s

iter	dom	disp	exec	clean	total	dom%	disp%	exec%	clean%
1	0.016	0.000	0.290	1.951	2.258	1%	0%	13%	86%
2	0.023	0.000	0.806	2.094	2.923	1%	0%	28%	72%
3	0.024	0.000	1.048	2.589	3.660	1%	0%	29%	71%
4	0.037	0.000	1.347	2.077	3.461	1%	0%	39%	60%
5	0.025	0.000	5.778	2.497	8.300	0%	0%	70%	30%
6	0.028	0.000	0.651	2.193	2.872	1%	0%	23%	76%
7	0.045	0.000	3.446	1.122	4.613	1%	0%	75%	24%
8	0.022	0.000	2.451	2.647	5.120	0%	0%	48%	52%
9	0.031	0.000	3.467	2.131	5.629	1%	0%	62%	38%
10	0.046	0.000	0.453	2.390	2.889	2%	0%	16%	83%
11	0.048	0.000	6.610	2.006	8.663	1%	0%	76%	23%
12	0.044	0.000	3.483	2.004	5.531	1%	0%	63%	36%

5 preloads: Run time (iterations=12 mean=3.755): 45.064s

iter	dom	disp	exec	clean	total	dom%	disp%	exec%	clean%
1	0.027	0.000	0.951	2.043	3.021	1%	0%	31%	68%
2	0.025	0.000	0.695	2.035	2.755	1%	0%	25%	74%
3	0.035	0.000	0.982	2.117	3.134	1%	0%	31%	68%
4	0.027	0.000	1.566	1.920	3.513	1%	0%	45%	55%
5	0.028	0.000	1.289	2.282	3.600	1%	0%	36%	63%
6	0.024	0.000	2.590	2.308	4.922	0%	0%	53%	47%
7	0.049	0.000	0.892	2.613	3.554	1%	0%	25%	74%
8	0.033	0.000	3.373	1.049	4.456	1%	0%	76%	24%
9	0.027	0.000	2.011	2.069	4.107	1%	0%	49%	50%
10	0.030	0.000	2.920	2.270	5.220	1%	0%	56%	43%
11	0.027	0.000	1.771	2.032	3.831	1%	0%	46%	53%
12	0.029	0.000	0.561	2.361	2.951	1%	0%	19%	80%

6 preloads: Run time (iterations=12 mean=3.588): 43.055s

iter	dom	disp	exec	clean	total	dom%	disp%	exec%	clean%
1	0.036	0.000	0.856	2.015	2.907	1%	0%	29%	69%
2	0.023	0.000	0.638	1.734	2.396	1%	0%	27%	72%
3	0.022	0.000	1.319	1.808	3.149	1%	0%	42%	57%
4	0.031	0.000	1.847	1.595	3.473	1%	0%	53%	46%
5	0.037	0.000	1.603	2.109	3.750	1%	0%	43%	56%
6	0.049	0.000	0.931	2.269	3.249	2%	0%	29%	70%
7	0.093	0.000	3.355	1.129	4.578	2%	0%	73%	25%
8	0.052	0.000	1.704	2.138	3.894	1%	0%	44%	55%
9	0.040	0.000	2.834	2.321	5.196	1%	0%	55%	45%
10	0.030	0.000	2.955	2.318	5.303	1%	0%	56%	44%
11	0.053	0.000	0.339	1.533	1.925	3%	0%	18%	80%
12	0.032	0.000	1.154	2.049	3.235	1%	0%	36%	63%

---

With few preloads, 2-3, it gives the best performance on the time of the first 2-3 executions, specially for the important stages exec and total. They of course are not the best on long run because there will be times that calls are completed and preloads will be still preloading (incomplete), thus the higher mean and total run time and high deviation in exec and total stages.

We can also notice that for this specific workflow of running qubes.WaitForRunningSystem after 5 preloads, there is not much benefit, but if doesn't cost much in resources on your machine to preload, still brings a bit of value (run time decrease).

Some tests run on a 16GB RAM system with kernel 6.12.47-1, (results), which gave different results for the tests of 1-3 preloads, maybe kernel version made a difference... I will rerun the tests using 6.12.47 and 6.15.11.

Edit: It seems that there was a decrease in time with kernel upgrade, testing the with 4 preloaded disposables the main test_404 yields:

• 6.12.47: 4.941
• 6.15.10: 4.66
• 6.15.11: 4.277

[ben-grande]

Another point to consider is that preloaded disposable is also intended for graphical applications, unfortunately they are some seconds slower because of late GUID. Marek proposed various options, but one that seems easy is to modify the GUI agent to not wait for GUI connection, for that, it must get some info:

• domid (probably set on boot already); and
• GUIVM resolution (resolution refresh is already done).

Then, when the GUID connects, the time to run qubes.WaitForSession will be the same time as the one to run qubes.WaitForRunningSystem when using a preloaded disposable.

• https://github.com/QubesOS/qubes-gui-daemon
• https://github.com/QubesOS/qubes-gui-common/tree/main/include
• https://github.com/QubesOS/qubes-gui-agent-linux