1608370 - No startup/shutdown profile written for Marionette based test jobs

Status: RESOLVED FIXED

(Testing :: Marionette, defect, P1)

Description

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

I tried to create a Gecko profile for a locally build artifact build by running some marionette tests. After the tests have been finished I expected the profile to be written to the file as specified but that file is not present on disk. Here an example command which at least demonstrates the problem on my MBP:

$ MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_SHUTDOWN=/code/gecko/profile.json mach test testing/marionette/harness/marionette_harness/tests/unit/test_pagesource.py

I also tried it for browser chrome tests under /remote/tests/browser but the same behavior is visible. Finally I started Firefox via MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_SHUTDOWN=/code/gecko/profile.json mach run, and manually quit Firefox. Now the profile is written to disk.

Not sure what specific code path triggers the write of the profile but it would be great to get it always working.

Comment 1

[Florian Quèze [:florian]]

Afaik MOZ_PROFILER_SHUTDOWN expects a filename, not a full path, the file will be written in $(pwd)/<filename>

Comment 2

[Florian Quèze [:florian]]

That said, enough people have been confused by this (myself included), that it's probably a good idea to see if we could change the behavior to make that variable accept a path.

Comment 3

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

No, it needs an absolute path. If only a filename is specified, I don't know where the file gets saved. It's at least not in the current working directory.

But as said above... this problem is not related to the path format.

Comment 4

[Florian Quèze [:florian]]

If I run MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_SHUTDOWN=mp.json ./mach test browser/base/content/test/pageinfo/browser_pageinfo_image_info.js, I get the profile in ./obj-artifact/_tests/testing/mochitest/mp.json which seems to be the folder the mochitest harness sets as the current directory.

From looking at the output of running your marionette command on my local artifact build on OSX, I suspect the marionette harness changes the current directory to a temporary folder that gets deleted at the end of the run. If I was I running this on Linux, I would use strace to verify this assumption.

Comment 5

[Gerald Squelart [:gerald] (he/him)]

We do std::ofstream stream; stream.open(aFilename);, with aFilename being the contents of MOZ_PROFILER_SHUTDOWN:
https://searchfox.org/mozilla-central/rev/d4d6f81e0ab479cde192453bae83d5e3edfb39d6/tools/profiler/core/platform.cpp#3948
An absolute path should work; a relative path would be relative to the "current directory" where the ./mach command is run.

(Weekend here, I'll come back to this next week...)

Comment 6

[Gerald Squelart [:gerald] (he/him)]

Update:
I've tried running MOZ_LOG=prof:5 MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_SHUTDOWN="profile_marionette_20200113.json" mach marionette-test -vv --gecko-log - testing/marionette/harness/marionette_harness/tests/unit/test_pagesource.py
MOZ_LOG=prof:5 and --gecko-log - output the profiler's logging to stdout.

I could see normal logs during startup, including "profiler_init" (called from main()), "profiler_locked_start" (showing the profiler is turned on); and other runtime logs.
And I added a bit of logging to a local build, and I could verify that "MOZ_PROFILER_SHUTDOWN" contained the filename from the command line.

However at the end there were none of the expected end-of-life logs; I would have expected "profiler_stop", or at the very least "profiler_shutdown", which is called by the destructor of AutoProfilerInit (the object that called "profiler_init" when created in the main())!?
"profiler_shutdown" is where we would store the shutdown profile.

So at the moment I'm thinking that maybe Marionette just kills Firefox when its tests are finished?

Henrik:
I don't know much about Marionette, so I may be wrong of course, but could you please let me know what you think about my theory above?
Is there some way you/I could attach a debugger to the target Firefox, and know what happens after the marionette test ends?

Comment 7

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

Ok, this seems to be indeed a problem with Marionette and how the test harness closes Firefox. Even we can safely shutdown Firefox it's not done but a kill is triggered via mozrunner. I will have a look and we surely have to get Marionette to safely quit Firefox after the last test has been ran.

With a temporary fix I can also get the browser chrome tests under /remote to create a profile.json file on disk.

Comment 8

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

Attachment: Bug 1608370 - [marionette] No startup/shutdown profile written for Marionette based test jobs.

This forces a safe shutdown of the application after the last
test if the process is still up and running. Because the
testcase class already deleted the session a new one needs
to be created.

A more elegant solution might be possible but would involve
a fair amount of refactoring, which at this point is not
worse our time.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9d1a99b3b507
[marionette] No startup/shutdown profile written for Marionette based test jobs. r=marionette-reviewers,ato

Comment 10

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/9d1a99b3b507