1914388 - On Windows, profiler doesn't capture gecko log properly in MFCDM process

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P2)

Description

[Alastor Wu [:alwu]]

When opening about:support on Widows Nightly, you can see a section called "Content Decryption Modules Information". That triggers this part of code, which should result in printing logs in the BackgroundThreadPool thread. But if you use media playback in about:logging to profile this behavior, there is NO log at all on that thread.

STR.

1. go to about:logging
2. select media playback preset and start profiling
3. go to about:support and wait until Content Decryption Modules Information shows some results
4. stop profiling

Expected.
5. log should be captured on BackgroundThreadPool in the MFCDM process

Actual.
5. no log at all

Comment 1

[Alastor Wu [:alwu]]

FYI we also received different several profiled results from Windows users before, and also no the log message in their profiled result. There must be something wrong on Windows.

Comment 2

[Paul Adenot (:padenot)]

I started debugging this and saw the prefs are propagated to the child process, and everything seemed fine, but then then logging I saw the level at 0 (disabled), and got confused and had to switch to something else.

Comment 3

[Alastor Wu [:alwu]]

On today's Nightly, this bug still persists and I still can't see any log in BackgroundThreadPool. However, another user captured a profile on build id 20241024094434, his profile can capture logs successfully, not sure why...

Comment 4

[Paul Adenot (:padenot)]

There is a race somewhere, this needs more debugging.

Comment 5

[Julien Wajsberg [:julienw]]

Alastor I don't see any log message on the main thread either, but maybe that's expected because there's no moz_log call there, can you please confirm?

Also can you confirm you see these logs in the console even when they're not showing up in the profile?
Thanks

Registering the modules is done in LogModulePrefWatcher.cpp:
https://searchfox.org/mozilla-central/rev/a547d790fa7facb8d0addb9197797dc52b31e8f2/xpcom/base/LogModulePrefWatcher.cpp#158-170
Adding the marker is done in https://searchfox.org/mozilla-central/rev/a547d790fa7facb8d0addb9197797dc52b31e8f2/xpcom/base/Logging.cpp#675-681

Adding a breakpoint with printing at these locations could maybe help debugging?

Comment 6

[Alastor Wu [:alwu]]

Alastor I don't see any log message on the main thread either, but maybe that's expected because there's no moz_log call there, can you please confirm?

Yes, logs are not in the main thread. They are mostly on BackgroundThreadPool, MediaSupervisor and MediaPDecoder.

Also can you confirm you see these logs in the console even when they're not showing up in the profile?

No.

---

After doing some more testing, it seems like the issue with missing logs only occurs when the MFCDM process hasn't been started before starting the profiler. Once the MFCDM process has already been created, the profiler is able to capture logs normally.

This suggests that when the MFCDM process is created after profiling starts, the profiler might not be registering the log modules correctly within that process.

You can reproduce the issue using the following STR (on Windows):

1. Start Firefox
2. Go to about:logging, select the Media Playback preset, and start capturing
3. Visit about:support
4. Once the page finishes loading, stop profiling
5. In the profile, you should see the MF Media Engine CDM process, but no logs in the BackgroundThreadPool thread
6. Start a new profiling via about:logging again
7. Refresh the about:support page
8. Once it finishes loading, stop profiling
9. In the new profile, you should now see the MF Media Engine CDM process with logs under BackgroundThreadPool

Comment 7

[Julien Wajsberg [:julienw]]

(In reply to Alastor Wu [:alwu] from comment #6)

Alastor I don't see any log message on the main thread either, but maybe that's expected because there's no moz_log call there, can you please confirm?

Yes, logs are not in the main thread. They are mostly on BackgroundThreadPool, MediaSupervisor and MediaPDecoder.

Also can you confirm you see these logs in the console even when they're not showing up in the profile?

No.

Then I think it's not related to the profiler at all, but to the more generic log system.

All about:logging does is setting some preferences.

Does that all work when you use the MOZ_LOG env variable?

Comment 8

[Alastor Wu [:alwu]]

(In reply to Julien Wajsberg [:julienw] from comment #7)

Then I think it's not related to the profiler at all, but to the more generic log system.

All about:logging does is setting some preferences.

Does that all work when you use the MOZ_LOG env variable?

Yes, using MOZ_LOG works, but adding logging.XXX doesn't. It does sound like a MOZLOG problem, do you know who the right person is to ask for checking this issue? Thanks!

Comment 9

[Paul Adenot (:padenot)]

More or less me. I would set breakpoints around here: https://searchfox.org/mozilla-central/source/xpcom/base/LogModulePrefWatcher.cpp#175. This is the code that is responsible for catching any modification to logging.xxx and set the log module appropriately.

Comment 10

[Julien Wajsberg [:julienw]]

Yeah, I would do exactly this.

Comment 11

[Alastor Wu [:alwu]]

Okay, I found the issue. The log modules are correctly created and initialized with the appropriate log level when the MFCDM process is launched. However, the log level gets cleared by this code afterward. The subsequent code that sets the log level only considers the MOZ_LOG environment variable and the preference, and doesn’t reapply the levels set via about:logging. As a result, any modules configured through about:logging aren't properly restored.

This issue might also explain why we sometimes don’t see media logs from users, even when they’ve reported capturing the profile using the media preset.

Comment 12

[Alastor Wu [:alwu]]

Attachment: Bug 1914388 – Don’t reset log modules if logging.config.modules is empty

If the logging.config.modules preference is empty, we should avoid clearing
the existing log modules. Resetting them unnecessarily can result in losing log
levels previously set via about:logging.

Comment 13

[Julien Wajsberg [:julienw]]

ah right, good find!

Moving forward I'd like to make about:logging use logging.config.modules directly, which would also prevent the issue.
But developers might still use the individual prefs for reasons so I think this fix makes sense anyway, even in the long run.

Comment 14

[Alastor Wu [:alwu]]

Attachment: Bug 1914388 - part1 : revert changes from D209249 in order to remove the support of 'logging.config.modules'.

Comment 15

[Alastor Wu [:alwu]]

Attachment: Bug 1914388 - part2 : remove related prefs and modify documentations.

Comment 16

[Gregory Pappas [:gregp]]

These prefs are removed:

• logging.config.modules

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/13e4579e8765
https://hg.mozilla.org/integration/autoland/rev/4a6f86123276
part1 : revert changes from D209249 in order to remove the support of 'logging.config.modules'. r=julienw
https://github.com/mozilla-firefox/firefox/commit/298b54b3ec31
https://hg.mozilla.org/integration/autoland/rev/bd4a1034914b
part2 : remove related prefs and modify documentations. r=geckoview-reviewers,julienw,owlish

Comment 18

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/4a6f86123276
https://hg.mozilla.org/mozilla-central/rev/bd4a1034914b