1612309 - nativeallocations is disabled when running mochitests

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P2)

Description

[Alexandre Poirot [:ochameau]]

I'm currently trying to record allocations of a mochitest, in a quest to try to understand a leak.
Unfortunately, the recorded profile doesn't contain native allocations.

Here is how I try to record a profile while running a mochitest:
MOZ_PROFILER_STARTUP_FEATURES=nativeallocations MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_SHUTDOWN=mochitestprofile.json ./mach mochitest --headless devtools/client/debugger/test/mochitest/browser_dbg-asm.js

This command works, you will find the profile in ./obj-firefox-artifact/_tests/testing/mochitest/mochitestprofile.json But it doesn't contain allocations.

I tracked it down to Services.profiler.GetFeatures() which doesn't return nativeallocations.

Here is an helpful command to debug this:
./mach mochitest devtools/client/debugger/test/mochitest/browser_dbg-asm.js --no-autorun --keep-open
This will allow you to open the Browser Console from a mochitest run, as well as opening about:config to see if that relates to any pref.

Comment 1

[Alexandre Poirot [:ochameau]]

FYI, I did it a bit and you may want to apply the following diff:

diff --git a/testing/mochitest/runtests.py b/testing/mochitest/runtests.py
index b2928f65a7ee..11bd0d4de6fe 100644
--- a/testing/mochitest/runtests.py
+++ b/testing/mochitest/runtests.py
@@ -1681,7 +1681,7 @@ toolbar#nav-bar {
             self.log.error(str(e))
             return None
 
-        browserEnv["XPCOM_MEM_BLOAT_LOG"] = self.leak_report_file
+        #browserEnv["XPCOM_MEM_BLOAT_LOG"] = self.leak_report_file
 
         try:
             gmp_path = self.getGMPPluginPath(options)

As we explicitely disable nativeallocations when this environment variable is set:
https://searchfox.org/mozilla-central/source/tools/profiler/core/platform.cpp#219-225
And we do set XPCOM_MEM_BLOAT_LOG while running mochitests.

But for some reason, this isn't enough to enable allocation records.

Comment 2

[Alexandre Poirot [:ochameau]]

Note also that when running the exact same build, the native allocations works ./mach run

Comment 3

[Greg Tatum [:gregtatum]]

I can reproduce this on my machine. Thanks for the detailed STR. I'm not sure why this is happening, and I'll need to debug the C++ code. It's hard to reason with the bitfield operations going on in the implementation. With everyone's PTO it'll be after next week before we can really look at fixing this.

Help output:

    Features: (x=unavailable, D/d=default/unavailable,
               S/s=MOZ_PROFILER_STARTUP extra default/unavailable)
    d     1: "java" (Profile Java code, Android only)
    D     2: "js" (Get the JS engine to expose the JS stack to the profiler)
    D     4: "leaf" (Include the C++ leaf node if not stackwalking)
    S     8: "mainthreadio" (Add main thread I/O to the profile)
    -    16: "privacy" (Do not include user-identifiable information)
    -    32: "screenshots" (Take a snapshot of the window on every composition)
    -    64: "seqstyle" (Disable parallel traversal in styling)
    D   128: "stackwalk" (Walk the C++ stack, not available on all platforms)
    x   256: "tasktracer" (Start profiling with feature TaskTracer)
    D   512: "threads" (Profile the registered secondary threads)
    -  1024: "trackopts" (Have the JavaScript engine track JIT optimizations)
    x  2048: "jstracer" (Enable tracing of the JavaScript engine)
    -  4096: "jsallocations" (Have the JavaScript engine track allocations)
    - 16384: "nostacksampling" (Disable all stack sampling: Cancels "js", "leaf", "stackwalk" and labels)
    - 32768: "preferencereads" (Track when preferences are read)
    - 65536: "nativeallocations" (Collect the stacks from a smaller subset of all native allocations, biasing towards collecting larger allocations)
    - 131072: "ipcmessages" (Have the IPC layer track cross-process messages)

Profile generated using the STR:
https://perfht.ml/2uaq9VQ

In that profile I toggled the "js" feature, which I could turn on, but the "nativeallocations" was not toggled on. I confirmed this in the profile meta information.

Comment 4

[Alexandre Poirot [:ochameau]]

ping. I wanted to use the profiler to figure out a leak reported by mochitest.
But because of this, I could not benefit from your awesome work on allocations!

Comment 5

[Greg Tatum [:gregtatum]]

Let me look into this.

Comment 6

[Greg Tatum [:gregtatum]]

I did some investigations into this. It looks like XPCOM_MEM_BLOAT_LOG is being set on my mochitest on non-debug builds. For some reason I thought it was debug only. I was able to get a profile using the steps above with native allocations turned on. :ochameau, would you mind checking the STR again on your computer with the change on testing/mochitest/runtests.py. I'll need to think of the strategy for how to ensure that XPCOM_MEM_BLOAT_LOG doesn't get in the way.

diff --git a/testing/mochitest/runtests.py b/testing/mochitest/runtests.py
--- a/testing/mochitest/runtests.py
+++ b/testing/mochitest/runtests.py
@@ -1697,17 +1697,17 @@ toolbar#nav-bar {
                 dict(
                     parse_key_value(
                         options.environment,
                         context='--setenv')))
         except KeyValueParseError as e:
             self.log.error(str(e))
             return None
 
-        browserEnv["XPCOM_MEM_BLOAT_LOG"] = self.leak_report_file
+        # browserEnv["XPCOM_MEM_BLOAT_LOG"] = self.leak_report_file
 
         try:
             gmp_path = self.getGMPPluginPath(options)
             if gmp_path is not None:
                 browserEnv["MOZ_GMP_PATH"] = gmp_path
         except EnvironmentError:
             self.log.error('Could not find path to gmp-fake plugin!')
             return None
diff --git a/tools/profiler/core/platform.cpp b/tools/profiler/core/platform.cpp
--- a/tools/profiler/core/platform.cpp
+++ b/tools/profiler/core/platform.cpp
@@ -212,16 +212,17 @@ static uint32_t AvailableFeatures() {
 #if !defined(HAVE_NATIVE_UNWIND)
   ProfilerFeature::ClearStackWalk(features);
 #endif
 #if !defined(MOZ_TASK_TRACER)
   ProfilerFeature::ClearTaskTracer(features);
 #endif
 #if defined(MOZ_REPLACE_MALLOC) && defined(MOZ_PROFILER_MEMORY)
   if (getenv("XPCOM_MEM_BLOAT_LOG")) {
+    DEBUG_LOG("XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.");
     // The memory hooks are available, but the bloat log is enabled, which is
     // not compatible with the native allocations tracking. See the comment in
     // enable_native_allocations() (tools/profiler/core/memory_hooks.cpp) for
     // more information.
     ProfilerFeature::ClearNativeAllocations(features);
   }
 #else
   // The memory hooks are not available.

Here is the profile:

https://perfht.ml/3bGmNdt

Here is the active configuration:

{
  "features": [
    "threads",
    "nativeallocations"
  ],
  "threads": [
    "GeckoMain",
    "Compositor",
    "DOM Worker"
  ],
  "interval": 1,
  "capacity": 4194304,
  "activeBrowsingContextID": 0
}

Comment 7

[Alexandre Poirot [:ochameau]]

(In reply to Greg Tatum [:gregtatum] from comment #6)

I was able to get a profile using the steps above with native allocations turned on. :ochameau, would you mind checking the STR again on your computer with the change on testing/mochitest/runtests.py.

Thanks a lot for testing!
Yes, it works now!

But:

1. I had to tweak the buffer size, by using MOZ_PROFILER_STARTUP_ENTRIES=10000000, otherwise we only see the very end of the records in the parent process. This is visible in your profile. It would be nice to have tweaked default values when running mochitests. This may be part of bug 1421972.

2. The profile looks broken. I haven't tried to investigate if this was specific to mochitest or when turning nativeallocations.
   When you filter with devtools, all views are showing very few information. You see lots of component loader load module without much details.
   This is the same between Timing Data or any data-related view.
   This is as if the UI was trying to categorize everything and prevent from trying to expose any real frame, with JS URL + line of execution/allocation.

Here is a full record, with increased buffer size:
https://perfht.ml/2UyJWJ8

I'll need to think of the strategy for how to ensure that XPCOM_MEM_BLOAT_LOG doesn't get in the way.

This may be worth looking at addressing bug 1421972, I imagine it would help disabling this.

Comment 8

[Florian Quèze [:florian]]

(In reply to Alexandre Poirot [:ochameau] from comment #7)

2. The profile looks broken. I haven't tried to investigate if this was specific to mochitest or when turning nativeallocations.

This is because of the selected profiler features (MOZ_PROFILER_STARTUP_FEATURES=nativeallocations). You need js in this list to see JS frames, and you need stackwalk in the list to see native frames.
Running this with MOZ_PROFILER_STARTUP_FEATURES=nativeallocations,js,stackwalk should give you profiles closer to what you expect.

Comment 9

[Alexandre Poirot [:ochameau]]

Thanks a lot, this is very correct.
I also had to seriously bump de buffer. I had to go up to MOZ_PROFILER_STARTUP_ENTRIES=70000000 to record everything!

Here is the command line I had to use at the end:
MOZ_PROFILER_STARTUP_ENTRIES=70000000 MOZ_PROFILER_STARTUP_FEATURES=nativeallocations,js,stackwalk MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_SHUTDOWN=mochitestprofile.json MOZCONFIG=mozconfig-firefox-artifact ./mach mochitest --headless devtools/client/debugger/test/mochitest/browser_dbg-asm.js

This is sooo useful to be able to see allocations on reproducable test cases, which mochitest provile!
Not having to manually click everywhere to reproduce a STR is very handy!
There is just bug 1421972, which force manual steps in order to see the profile.

Comment 10

[Greg Tatum [:gregtatum]]

Attachment: Bug 1612309 - Turn off XPCOM_MEM_BLOAT_LOG in mochitests when using nativeallocations; r?sparky,gerald

The profiler feature "nativeallocations" is disabled when the bloat log is turned on
because they both use the same memory hook feature, and are not compatible. This is
confusing for users trying to enable the feature.

Comment 11

[Greg Tatum [:gregtatum]]

Attachment: Bug 1612309 - Add an NS_WARNING for when nativeallocations are disabled by the bloat log; r?gerald

This makes it easier to debug when native allocations are turned on.

Depends on D70074

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0df1276f99cc
Turn off XPCOM_MEM_BLOAT_LOG in mochitests when using nativeallocations; r=sparky
https://hg.mozilla.org/integration/autoland/rev/ce1e5df902e2
Add an NS_WARNING for when nativeallocations are disabled by the bloat log; r=gerald

Comment 13

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/0df1276f99cc
https://hg.mozilla.org/mozilla-central/rev/ce1e5df902e2