Closed Bug 1015317 Opened 11 years ago Closed 3 years ago

Gecko Profiler add-on causes Nightly to gradually consume a ton of memory when enabled

Categories

(Core :: Gecko Profiler, defect)

x86
macOS
defect
Not set
normal

Tracking

()

RESOLVED FIXED

People

(Reporter: mconley, Unassigned)

References

(Blocks 1 open bug)

Details

(Whiteboard: [MemShrink:P2])

Attachments

(3 files)

Not sure when this showed up - BenWa assures me that he hasn't touched the add-on recently, so this might have been caused by a change in the SDK or otherwise Platform. Basically, I was at my machine when OS X claimed that I was running out of memory. I opened up the Activity Monitor and saw that Nightly was consuming 10.8GB! I shutdown Nightly and restarted, and my memory usage started to escalate again - it seemed to go up by 5-10MB at a time, which was pretty shocking. I then started disabling add-ons to try to find the culprit, and the Gecko Profiler seems to be at least involved if not fully culpable for the memory consumption. Disabling it stops the leak in its tracks, and re-enabling it causes it to climb again.
At least using about:addons-memory (https://addons.mozilla.org/en-US/firefox/addon/about-addons-memory/), it doesn't look like the Gecko Profiler itself is consuming lots of memory. I wonder if perhaps the act of collecting a profile is causing the platform to consume large chunks of memory?
Summary: Gecko Profiler add-on leaks a ton of memory when enabled → Gecko Profiler add-on causes Nightly to gradually consume a ton of memory when enabled
I've also noticed that stopping the profiler (and not just disabling it) also causes the leaking to stop.
Ok, last bit of useful information - this does not seem to, at this time, affect Aurora 31.0a2 (2014-05-21). It _does_ affect Nightly 32.0a1 (2014-05-23). I'm going to see if I can get a regression range, and then I'll leave this alone.
If I'm not 100% mistaken, I _believe_ this is a very new leak that may have been introduced last night: https://hg.mozilla.org/mozilla-central/pushloghtml?startdate=2014-05-22&enddate=2014-05-23 I'll try to bisect a little further in there to see what I get.
I'm going to guess it's bug 908503 which affected how stderr is used.
Hrm... my bisecting is pointing at this merge changeset: https://hg.mozilla.org/integration/fx-team/pushloghtml?changeset=e06ed340ebcd
This is pretty strange. My bisecting is pointing the blame squarely at bug 759252. I can still reproduce the leak on Nightly, and when I back out this patch, it seems to go away. Very, very strange. I'm busy most of today, but I'll try to post some STR tomorrow for some other people to confirm this, since this is pretty strange.
Blocks: 759252
STR (for OS X at least): 1) In a new Firefox profile, install the Gecko Profiler add-on (save https://github.com/bgirard/Gecko-Profiler-Addon/blob/master/geckoprofiler.xpi?raw=true and then drag from the download panel into web content to do it quickly) 2) Shut down the browser, and open the OS X Activity Monitor (Utilities > Activity Monitor) 3) Restart the browser with the same profile. 4) Wait approximately 10 seconds. 5) Watch the entry in the Activity Monitor for Firefox (or Nightly, in my case) start to gradually increase in memory usage.
I'll note that I haven't run Fx long enough in this state to determine _how long_ the memory consumption goes on for. It might peter out after a while, or it might continue indefinitely until your OS hates you.
Here's a video of me demonstrating the issue: http://www.screencast.com/t/ew8IbfvRk
I can reproduce this in today's nightly; as long as I have the profiler extension installed and profiling not stopped, memory use (in heap-unclassified, according to about:memory) grows quickly. If I stop profiling, or disable the Gecko Profiler extension, growth stops but the heap-unclassified memory is not released. I've attached an Activity Monitor sample taken as the memory use was growing.
If you backout the patch for bug 759252 (https://hg.mozilla.org/mozilla-central/rev/a9329165ace3), do you also see the issue go away?
Flags: needinfo?(irving)
Yes, as far as I can tell, backing out bug 759252 makes the problem go away.
Flags: needinfo?(irving)
This is *really* weird... Jared, what should we do here? David, could this be an underlying leak in the platfrom? Has anyone ran this under DMD yet?
Flags: needinfo?(jaws)
Flags: needinfo?(dbaron)
Whiteboard: [MemShrink]
about:addons-memory can be useful, but it can also miss lots of stuff, so you can't make strong conclusions from its data. A DMD run is needed here; it will point us directly at the cause of the problem. https://wiki.mozilla.org/Performance/MemShrink/DMD are the instructions, which I rewrote just last week so they're easier to follow -- all the instructions for building and running on Mac are in one section, https://wiki.mozilla.org/Performance/MemShrink/DMD#Desktop_Firefox_.28Mac.29
Attached file DMD Report (compressed) (deleted) —
I used DMD to generate this report following the instructions from [1]. Hopefully this is useful. [1]: https://wiki.mozilla.org/Performance/MemShrink/DMD
This looks suspect: Unreported: 6,290 blocks in stack trace record 1 of 2,171 77,291,520 bytes (56,610,000 requested / 20,681,520 slop) 46.51% of the heap (46.51% cumulative); 61.78% of unreported (61.78% cumulative) Allocated at replace_malloc (DMD.cpp:1245, in libdmd.dylib) 0xa7f1 malloc_zone_malloc (in libsystem_c.dylib) + 71 0x85487183 malloc (in libsystem_c.dylib) + 41 0x85487bd7 moz_xmalloc (mozalloc.cpp:52, in libmozalloc.dylib) 0xec3be ThreadProfile::ThreadProfile(char const*, int, PseudoStack*, int, PlatformData*, bool, void*) (ProfileEntry.cpp:167, in XUL) 0x393fb76 SyncProfile::SyncProfile(char const*, int, PseudoStack*, int, bool) (SyncProfile.cpp:14, in XUL) 0x39410bf (anonymous namespace)::NewSyncProfile() (TableTicker.cpp:693, in XUL) 0x3942ff6 TableTicker::GetBacktrace() (TableTicker.cpp:699, in XUL) 0x3942f23 mozilla_sampler_get_backtrace() (ProfilerBacktrace.cpp:14, in XUL) 0x3947893 nsRefreshDriver::AddStyleFlushObserver(nsIPresShell*) (nsRefreshDriver.h:160, in XUL) 0x342f5dd mozilla::RestyleManager::PostRestyleEventCommon(mozilla::dom::Element*, nsRestyleHint, nsChangeHint, bool) (RestyleManager.cpp:1530, in XUL) 0x3423331 nsAnimationManager::FlushAnimations(mozilla::css::CommonAnimationManager::FlushFlags) (nsAnimationManager.h:105, in XUL) 0x32f0b0e nsRefreshDriver::Tick(long long, mozilla::TimeStamp) (nsRefreshDriver.cpp:1092, in XUL) 0x34070c8 mozilla::RefreshDriverTimer::Tick() (nsTArray.h:884, in XUL) 0x3409878 nsTimerImpl::Fire() (nsTimerImpl.cpp:570, in XUL) 0x169fac9 nsTimerEvent::Run() (nsTimerImpl.cpp:639, in XUL) 0x169fdc0 nsThread::ProcessNextEvent(bool, bool*) (nsThread.cpp:714, in XUL) 0x169b44c NS_ProcessPendingEvents(nsIThread*, unsigned int) (nsThreadUtils.cpp:210, in XUL) 0x1606dbd nsBaseAppShell::NativeEventCallback() (nsBaseAppShell.cpp:99, in XUL) 0x2797617 nsAppShell::ProcessGeckoEvents(void*) (nsAppShell.mm:285, in XUL) 0x27510cf __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ (in CoreFoundation) + 17 0x86a7db31 __CFRunLoopDoSources0 (in CoreFoundation) + 245 0x86a7d455 __CFRunLoopRun (in CoreFoundation) + 789 0x86aa07f5 CFRunLoopRunSpecific (in CoreFoundation) + 290 0x86aa00e2
Lots of stuff with this in the stack: ThreadProfile::ThreadProfile(char const*, int, PseudoStack*, int, PlatformData*, bool, void*) (ProfileEntry.cpp:167, in XUL) 0x393fb76 SyncProfile::SyncProfile(char const*, int, PseudoStack*, int, bool) (SyncProfile.cpp:14, in XUL) 0x39410bf (anonymous namespace)::NewSyncProfile() (TableTicker.cpp:693, in XUL) 0x3942ff6 TableTicker::GetBacktrace() (TableTicker.cpp:699, in XUL) 0x3942f23 mozilla_sampler_get_backtrace() (ProfilerBacktrace.cpp:14, in XUL) 0x3947893 nsRefreshDriver::AddStyleFlushObserver(nsIPresShell*) (nsRefreshDriver.h:160, in XUL) 0x342f5dd mozilla::RestyleManager::PostRestyleEventCommon(mozilla::dom::Element*, nsRestyleHint, nsChangeHint, bool) (RestyleManager.cpp:1530, in XUL) 0x3423331
Look like the style flushes are getting out of hand and the profiler is trying to track them all. I'll double check tomorrow to make sure these objects aren't leaking. Otherwise we might need to limit them.
Flags: needinfo?(jaws)
Flags: needinfo?(dbaron)
Thanks, mconley!
Just a heads up that bug 1016942 is probably going to land soon which might cause the memory consumption to go away - but will not fix the underlying issue.
Right, this bug will still reproduce with something that flushes a lot.
No longer blocks: 759252
(In reply to Mike Conley (:mconley) from comment #21) > Just a heads up that bug 1016942 is probably going to land soon which might > cause the memory consumption to go away - but will not fix the underlying > issue. Still reproducible with latest Nightly (Build ID: 20140602030202) on Mac OS X 10.9.2 and Ubuntu 14.04 LTS 32bit - the memory usage is rising after Gecko Profiler add-on is installed.
Whiteboard: [MemShrink] → [MemShrink:P2]
Blocks: 1329219

There is no more profiler add-on, so I'll call this bug fixed. The stacks in previous comments look unfamiliar to me (started working on the profiler in 2019), so I doubt these would appear anymore.

If you do see large memory use (more than the buffer size limit) when the profiler is running, please reopen or file new bugs.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: