Synapse Workers in Complement tests are slow (in CI)

[reivilibre]

Complement tests against Workerised Synapse are slow; a full suite takes about 52 minutes (before being split into 4 alphabetical groups to make it tolerable whilst still giving us the coverage immediately).

Complement starts a new homeserver for each test, which likely explains why SyTest doesn't have this problem (though apparently it's possible for state to leak between tests in SyTest).

Currently, that involves about 13 workers (Synapse processes) being started up, a Postgres, a Redis and an Nginx. We would do well to figure out what improvements we can make to cut down the time it takes to run a full test suite.

N.B. GitHub Actions runners have 2 cores if I remember. This problem is not so evident on a machine with many cores (a local run for me takes about 11 minutes).
However, the time that CI takes is probably the most important to consider (it should be no worse than existing tests; let's call it less than 25 minutes, which is the runtime of 'trial (3.7, postgres, all, 10)'), so that's where '52 minutes' comes from.

[reivilibre]

Workers take a shockingly long time to start up:

Two cherry-picked lines from a CI log:

2022-05-23 17:05:31,417 INFO spawned: 'synapse_appservice1' with pid 31
...
synapse_appservice1 | 2022-05-23 17:05:54,654 - root - 348 - WARNING - main - ***** STARTING SERVER *****

20 seconds are going missing!

This isn't just isolated to one worker

Details

$ rg 'spawned|STARTING' /tmp/aaa 
4:  2022-05-23 17:05:31,380 INFO spawned: 'postgres' with pid 21
5:  2022-05-23 17:05:31,383 INFO spawned: 'redis' with pid 22
6:  2022-05-23 17:05:31,388 INFO spawned: 'synapse_main' with pid 25
7:  2022-05-23 17:05:31,394 INFO spawned: 'nginx' with pid 26
8:  2022-05-23 17:05:31,417 INFO spawned: 'synapse_appservice1' with pid 31
9:  2022-05-23 17:05:31,432 INFO spawned: 'synapse_background_worker1' with pid 32
10:  2022-05-23 17:05:31,447 INFO spawned: 'synapse_event_creator1' with pid 39
11:  2022-05-23 17:05:31,497 INFO spawned: 'synapse_event_persister1' with pid 43
12:  2022-05-23 17:05:31,560 INFO spawned: 'synapse_event_persister2' with pid 59
13:  2022-05-23 17:05:31,576 INFO spawned: 'synapse_federation_inbound1' with pid 64
14:  2022-05-23 17:05:31,610 INFO spawned: 'synapse_federation_reader1' with pid 70
15:  2022-05-23 17:05:31,658 INFO spawned: 'synapse_federation_sender1' with pid 71
16:  2022-05-23 17:05:31,690 INFO spawned: 'synapse_frontend_proxy1' with pid 82
17:  2022-05-23 17:05:31,695 INFO spawned: 'synapse_media_repository1' with pid 84
18:  2022-05-23 17:05:31,762 INFO spawned: 'synapse_pusher1' with pid 89
19:  2022-05-23 17:05:31,798 INFO spawned: 'synapse_synchrotron1' with pid 95
20:  2022-05-23 17:05:31,854 INFO spawned: 'synapse_user_dir1' with pid 99
42:  synapse_background_worker1 | 2022-05-23 17:05:54,318 - root - 348 - WARNING - main - ***** STARTING SERVER *****
70:  synapse_frontend_proxy1 | 2022-05-23 17:05:54,682 - root - 348 - WARNING - main - ***** STARTING SERVER *****
98:  synapse_federation_sender1 | 2022-05-23 17:05:54,829 - root - 348 - WARNING - main - ***** STARTING SERVER *****
126:  synapse_appservice1 | 2022-05-23 17:05:54,654 - root - 348 - WARNING - main - ***** STARTING SERVER *****
155:  synapse_federation_inbound1 | 2022-05-23 17:05:54,752 - root - 348 - WARNING - main - ***** STARTING SERVER *****
182:  synapse_event_persister2 | 2022-05-23 17:05:54,736 - root - 348 - WARNING - main - ***** STARTING SERVER *****
210:  synapse_media_repository1 | 2022-05-23 17:05:55,064 - root - 348 - WARNING - main - ***** STARTING SERVER *****
238:  synapse_event_creator1 | 2022-05-23 17:05:55,223 - root - 348 - WARNING - main - ***** STARTING SERVER *****
266:  synapse_synchrotron1 | 2022-05-23 17:05:55,331 - root - 348 - WARNING - main - ***** STARTING SERVER *****
322:  synapse_event_persister1 | 2022-05-23 17:05:55,786 - root - 348 - WARNING - main - ***** STARTING SERVER *****
453:  synapse_federation_reader1 | 2022-05-23 17:05:56,336 - root - 348 - WARNING - main - ***** STARTING SERVER *****
481:  synapse_user_dir1 | 2022-05-23 17:05:56,274 - root - 348 - WARNING - main - ***** STARTING SERVER *****
510:  synapse_pusher1 | 2022-05-23 17:05:56,267 - root - 348 - WARNING - main - ***** STARTING SERVER *****
540:  synapse_main | 2022-05-23 17:05:56,926 - root - 348 - WARNING - main - ***** STARTING SERVER *****

Rich suggested that it might be time spent reading the .pyc files or something like that; I'll have a look at that.

[richvdh]

https://docs.python.org/3/using/cmdline.html#envvar-PYTHONPROFILEIMPORTTIME may be helpful

[reivilibre]

This has been improved (roughly 0.5× time) by #13051, which is good enough for now but it's likely we'll have to come up with some more performance gains as Complement gains more tests.
Removed from Q2 milestone & project board.

[richvdh]

Let's consider this done for now! 🎉