1921725 - Investigate why test_profile_management.py tests are running very slow on Windows ASAN builds

Status: NEW

(Testing :: Marionette Client and Harness, defect, P2)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Recently I noticed that especially the profile management unit tests are running quite a long time for ASAN builds. In the following you can see an example from a Windows job:

TEST-START | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_clean_creates_new_profile
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_clean_creates_new_profile | took 25249ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_keeps_same_profile_forced
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_keeps_same_profile_forced | took 24946ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_keeps_same_profile_safe
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_keeps_same_profile_safe | took 25841ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_clean_creates_new_profile
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_clean_creates_new_profile | took 25431ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_keeps_same_profile_forced
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_keeps_same_profile_forced | took 24726ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_keeps_same_profile_safe
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_keeps_same_profile_safe | took 25474ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_quit_clean_creates_new_profile
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_quit_clean_creates_new_profile | took 25673ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_quit_keeps_same_profile_forced
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_quit_keeps_same_profile_forced | took 24740ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_quit_keeps_same_profile_safe
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_quit_keeps_same_profile_safe | took 25477ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_clean_creates_new_profile
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_clean_creates_new_profile | took 25383ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_keeps_same_profile_forced
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_keeps_same_profile_forced | took 24654ms
TEST-START | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_keeps_same_profile_safe
TEST-PASS | unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_keeps_same_profile_safe | took 25088ms
TEST-START | unit/test_profile_management.py TestSwitchProfileFailures.test_raise_for_switching_profile_while_instance_is_running
TEST-PASS | unit/test_profile_management.py TestSwitchProfileFailures.test_raise_for_switching_profile_while_instance_is_running | took 12778ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_clone_existing_profile
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_clone_existing_profile | took 29758ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_new_named_profile
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_new_named_profile | took 30445ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_new_random_profile_name
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_new_random_profile_name | took 30155ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_clone_existing_profile
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_clone_existing_profile | took 30389ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_do_not_call_cleanup_of_profile_for_path_only
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_do_not_call_cleanup_of_profile_for_path_only | took 16796ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile | took 30288ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile_unicode
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile_unicode | took 29674ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile_unicode_escape_characters
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile_unicode_escape_characters | took 28712ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_random_profile_name
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_random_profile_name | took 29065ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_replace_with_current_profile
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_replace_with_current_profile | took 25468ms
TEST-START | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_replace_with_external_profile
TEST-PASS | unit/test_profile_management.py TestSwitchProfileWithoutWorkspace.test_replace_with_external_profile | took 33480ms

This happens while the quit and restart tests are only taking half the time for each. So I assume that this might have to do with the new profile that is created for these tests. Also this is Windows only because on Linux the times are looking fine:

INFO - TEST-START | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_clean_creates_new_profile
INFO - TEST-PASS | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_clean_creates_new_profile | took 15343ms
INFO - TEST-START | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_keeps_same_profile_forced
INFO - TEST-PASS | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_keeps_same_profile_forced | took 15017ms
INFO - TEST-START | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_keeps_same_profile_safe
INFO - TEST-PASS | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_keeps_same_profile_safe | took 14332ms
INFO - TEST-START | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_clean_creates_new_profile
INFO - TEST-PASS | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_clean_creates_new_profile | took 15449ms
INFO - TEST-START | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_keeps_same_profile_forced
INFO - TEST-PASS | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_keeps_same_profile_forced | took 15708ms
INFO - TEST-START | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_keeps_same_profile_safe
INFO - TEST-PASS | /unit/test_profile_management.py TestQuitRestartWithWorkspace.test_restart_keeps_same_profile_safe | took 14814ms

Also the tests as run in each job (Mn1, Mn2) are different to the ones from Windows. That's mostly something different but I thought that we basically have the same kind of tests per chunk. Joel, do you have any idea for that?

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

so these take roughly 15 seconds longer on windows. Typically file copy takes a lot longer on windows, I am not sure if asan tests in general are slower on windows vs linux. On debug builds these same tests are about the same duration, there is no 15 second across the board difference. This tells me that given the same testcase windows/linux can be run the same duration but on an asan build they are not.

Comment 2

[Joel Maher ( :jmaher ) (UTC -8)]

in the windows asan logs, I see 2 instances of:

[task 2024-09-30T16:26:03.705Z] 16:26:03     INFO -  1727713563709	Marionette	DEBUG	Waiting for initial application window
[task 2024-09-30T16:26:11.710Z] 16:26:11     INFO -  1727713571710	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished

that would account for the time difference.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Yes, there is a ~9s delay here before the browser-idle-startup-tasks-finished notification is received. But this only happens when Firefox starts up the very first time for a new profile. As such I assume that this happens due to the missing startup cache. And I assume it should not only happen for Marionette jobs.

It would be good to have a startup Gecko profile created for such an ASAN build on Windows. Joel, I assume there is no available job in CI that supports a profile to be recorded? Raptor/Browsertime does but those jobs don't run with ASAN builds. At least I cannot find anything when trying to add new jobs on Treeherder.

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:whimboo, could you have a look please?

For more information, please visit BugBot documentation.

Comment 5

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:whimboo, could you have a look please?

For more information, please visit BugBot documentation.