782731 - about:memory takes several minutes to load

Status: RESOLVED INCOMPLETE

(Toolkit :: about:memory, defect)

Description

[Steve Fink [:sfink] [:s:]]

Attachment: about:memory dump

After my browser has been running for a few hours, going to about:memory takes several minutes. I'm not sure what the actual time is, but I have to click Continue on 3-6 slow script dialogs before it finally comes up.

My browser is generally responsive. My CC times are 50-150ms. GC times are mostly in the 200-250ms range but occasionally take a little over a second. I have no addons enabled except for billm's GC Collector addon (I disabled all other addons to try to help him diagnose my browser's poor GC behavior.) I have many tabs open -- probably around 250. (Sorry; my tab counting addon is disabled with the rest.)

This happens reliably every time I open the browser.

If I were to insert timing log entries to try to track down where the time is going, where would I put them? (First, how can I distinguish the memory reporters from the about:memory page processing?)

Comment 1

[Andrew McCreight [:mccr8]]

You could try the profiler. https://developer.mozilla.org/en/Performance/Profiling_with_the_Built-in_Profiler

Comment 2

[Steve Fink [:sfink] [:s:]]

I should also mention that I have 8GB of RAM, and the hard drive starts chattering while about:memory is processing. Within the same browser session as the attached about:memory dump, I have 2GB free.

Comment 3

[Steve Fink [:sfink] [:s:]]

(In reply to Andrew McCreight [:mccr8] from comment #1)
> You could try the profiler.
> https://developer.mozilla.org/en/Performance/Profiling_with_the_Built-
> in_Profiler

Good point. Though I'll need to get off of the profiling branch (which is now the non-profiling branch) first. And it'll screw with the data I'm giving billm, because the profiler seems to trigger weird behavior for me.

Comment 4

[Nicholas Nethercote [inactive]]

I suspect that the most costly part of generating about:memory is the JS memory reporter, which touches every single live cell on the GC heap.  You could confirm this by commenting out the invocation of that reporter in dom/base/nsWindowMemoryReporter.cpp:

  xpc::JSMemoryMultiReporter::CollectReports(&windowPaths, aCb, aClosure);

Beyond that... your memory consumption is high but not so high that I'd expect it to take several minutes.  Given that the hard disk is going, it sounds like paging is occurring.  Your "page-faults-hard" count is quite high at 11,426 (on my 16GB machine it's currently 163, though I only have ~20 tabs open).  If you load about:memory twice in a row you'll be able to see the difference between the two.

Comment 5

[Nicholas Nethercote [inactive]]

Steve, can you do the follow-up from comment 4?  We won't make any progress without that.

Comment 6

[Steve Fink [:sfink] [:s:]]

Attachment: about:memory dump with timings for > 10ms

Sorry, I know I have a habit of throwing these unsolveable things out there and then abandoning them.

But here's an about:memory dump where I also had it print how long each simple reporter took, as well as timings for the multi-reporters broken down by their individual reporters, but only showing the ones that took at least 10ms.

One thing that immediately stands out is 

"reporter explicit/atom-tables: 17480ms"

but on the other hand, that one came out early, well before the half-dozen slow script dialogs that I had to dismiss.

Reloading about:memory *usually* is so fast it doesn't require any slow scripts, though I've had times where it was nearly as bad as the previous one. Since I suspect most of this time is due to swapping in stale memory to add things up, that probably just means it didn't fit in memory at all or I had something else active that needed to page in a bunch of stuff too.

I'll whip up a script to sort the messy multi-reporter output by elapsed time....

Comment 7

[Steve Fink [:sfink] [:s:]]

output of perl -le 'while(<>) { push @L, [ $1, $2 ] if /^"(multi-reporter.*): (\d+)ms\"$/ }; for (sort { $b->[1] <=> $a->[1] } @L) { print "$_->[1]ms $_->[0]" }' /tmp/mem.timings.txt | head -10

45037ms multi-reporter(window-objects) explicit/window-objects/top(https:\\\\bugzilla.mozilla.org\\show_bug.cgi?id=794494, id=467)/active/window(https:\\\\bugzilla.mozilla.org\\show_bug.cgi?id=794494)/dom/other
22526ms multi-reporter(window-objects) explicit/window-objects/top(http:\\\\www.whatwg.org\\specs\\web-apps\\current-work\\#dom-document-lastmodified, id=21)/active/window(http:\\\\www.whatwg.org\\specs\\web-apps\\current-work\\#dom-document-lastmodified)/dom/other
10505ms multi-reporter(window-objects) explicit/window-objects/top(https:\\\\mail.google.com\\mail\\u\\1\\?ui=2&shva=1#inbox, id=29)/active/window(https:\\\\plus.google.com\\u\\1\\_\\notifications\\frame?sourceid=23&hl=en&origin=https%3A%2F%2Fmail.google.com&uc=1&jsh=m%3B%2F_%2Fabc-static%2F_%2Fjs%2Fgapi%2F__features__%2Frt%3Dj%2Fver%3DKLeoPG_X_T8.en.%2Fsv%3D1%2Fam%3D!6NLDMLeKYpaBETGdoQ%2Fd%3D1#pid=23&id=gbsf&parent=https%3A%2F%2Fmail.google.com&rpctoken=271420089&_methods=onError%2ConInfo%2ChideNotificationWidget%2CpostSharedMessage%2CsetNotificationWidgetHeight%2CswitchTo%2CnavigateTo%2CgetNotificationText%2CsetNotificationText%2CsetNotificationAnimation%2ChandlePosted%2C_ready%2C_close%2C_open%2C_resizeMe%2C_renderstart)/dom/other
6710ms multi-reporter(window-objects) explicit/window-objects/top(https:\\\\bugzilla.mozilla.org\\show_bug.cgi?id=772563, id=61)/active/window(https:\\\\bugzilla.mozilla.org\\show_bug.cgi?id=772563)/dom/other
4379ms multi-reporter(window-objects) explicit/window-objects/top(http:\\\\www.diynot.com\\forums\\viewtopic.php?t=168580, id=379)/active/window(http:\\\\www.diynot.com\\forums\\viewtopic.php?t=168580)/dom/other
4172ms multi-reporter(window-objects) explicit/window-objects/top(http:\\\\code.google.com\\p\\strace-plus\\, id=447)/active/window(http:\\\\code.google.com\\p\\strace-plus\\)/dom/other
2894ms multi-reporter(window-objects) explicit/window-objects/top(http:\\\\people.mozilla.org\\~jorendorff\\es6-draft.html#sec-15.5.4, id=331)/active/window(http:\\\\people.mozilla.org\\~jorendorff\\es6-draft.html#sec-15.5.4)/dom/other
2678ms multi-reporter(window-objects) explicit/window-objects/top(http:\\\\mashable.com\\2012\\09\\19\\xkcd-click-and-drag-comic\\, id=453)/active/window(http:\\\\www.facebook.com\\plugins\\recommendations_bar.php?api_key=122071082108&channel=http%3A%2F%2Fstatic.ak.facebook.com%2Fconnect%2Fxd_arbiter.php%3Fversion%3D11%23cb%3Df266178ee9c75f4%26origin%3Dhttp%253A%252F%252Fmashable.com%252Ff398f5d47ff958c%26domain%3Dmashable.com%26relation%3Dparent.parent&href=http%3A%2F%2Fmashable.com%2F2012%2F09%2F19%2Fxkcd-click-and-drag-comic%2F&locale=en_US&max_age=1&num_recommendations=2&read_time=10&ref=slider&sdk=joey&side=right&site=http%3A%2F%2Fmashable.com&trigger=onvisible)/dom/other
2391ms multi-reporter(window-objects) explicit/window-objects/top(https:\\\\bugzilla.mozilla.org\\show_bug.cgi?id=593096, id=25)/active/window(https:\\\\bugzilla.mozilla.org\\show_bug.cgi?id=593096)/dom/other
2343ms multi-reporter(window-objects) explicit/window-objects/top(http:\\\\usa.yamaha.com\\products\\musical-instruments\\keyboards\\digitalkeyboards\\portable_keyboards\\psr-275\\?mode=model, id=407)/active/window(http:\\\\usa.yamaha.com\\products\\musical-instruments\\keyboards\\digitalkeyboards\\portable_keyboards\\psr-275\\?mode=model)/dom/other

Comment 8

[Steve Fink [:sfink] [:s:]]

45 seconds for a bugzilla window seems unfortunate, even with swapping.  Here's the fully expanded memory tree for that one:

│  │  ├──────6.06 MB (00.20%) -- top(https://bugzilla.mozilla.org/show_bug.cgi?id=794494, id=467)/active
│  │  │      ├──5.65 MB (00.19%) -- window(https://bugzilla.mozilla.org/show_bug.cgi?id=794494)
│  │  │      │  ├──3.00 MB (00.10%) -- js/compartment(https://bugzilla.mozilla.org/show_bug.cgi?id=794494)
│  │  │      │  │  ├──1.75 MB (00.06%) -- gc-heap
│  │  │      │  │  │  ├──0.64 MB (00.02%) -- objects
│  │  │      │  │  │  │  ├──0.35 MB (00.01%) ── non-function
│  │  │      │  │  │  │  └──0.29 MB (00.01%) ── function
│  │  │      │  │  │  ├──0.41 MB (00.01%) ── unused-gc-things
│  │  │      │  │  │  ├──0.38 MB (00.01%) -- shapes
│  │  │      │  │  │  │  ├──0.16 MB (00.01%) ── dict
│  │  │      │  │  │  │  ├──0.16 MB (00.01%) ── tree
│  │  │      │  │  │  │  └──0.05 MB (00.00%) ── base
│  │  │      │  │  │  ├──0.23 MB (00.01%) ── scripts
│  │  │      │  │  │  ├──0.07 MB (00.00%) ── type-objects
│  │  │      │  │  │  ├──0.03 MB (00.00%) ── arena-admin
│  │  │      │  │  │  └──0.01 MB (00.00%) ── sundries
│  │  │      │  │  ├──0.71 MB (00.02%) ── script-data
│  │  │      │  │  ├──0.28 MB (00.01%) -- shapes-extra
│  │  │      │  │  │  ├──0.14 MB (00.00%) ── tree-tables
│  │  │      │  │  │  ├──0.08 MB (00.00%) ── dict-tables
│  │  │      │  │  │  ├──0.05 MB (00.00%) ── compartment-tables
│  │  │      │  │  │  └──0.02 MB (00.00%) ── tree-shape-kids
│  │  │      │  │  ├──0.14 MB (00.00%) -- type-inference
│  │  │      │  │  │  ├──0.10 MB (00.00%) ── object-main
│  │  │      │  │  │  └──0.03 MB (00.00%) ── tables
│  │  │      │  │  ├──0.08 MB (00.00%) ── objects/slots
│  │  │      │  │  ├──0.02 MB (00.00%) ── analysis-temporary
│  │  │      │  │  └──0.02 MB (00.00%) ── other-sundries
│  │  │      │  ├──1.16 MB (00.04%) -- layout
│  │  │      │  │  ├──0.37 MB (00.01%) -- frames
│  │  │      │  │  │  ├──0.13 MB (00.00%) ── nsTextFrame
│  │  │      │  │  │  ├──0.09 MB (00.00%) ── nsBlockFrame
│  │  │      │  │  │  ├──0.07 MB (00.00%) ── sundries
│  │  │      │  │  │  ├──0.05 MB (00.00%) ── nsInlineFrame
│  │  │      │  │  │  ├──0.01 MB (00.00%) ── nsContinuingTextFrame
│  │  │      │  │  │  └──0.01 MB (00.00%) ── nsTableCellFrame
│  │  │      │  │  ├──0.28 MB (00.01%) ── pres-shell
│  │  │      │  │  ├──0.20 MB (00.01%) ── style-sets
│  │  │      │  │  ├──0.16 MB (00.01%) ── style-contexts
│  │  │      │  │  ├──0.07 MB (00.00%) ── line-boxes
│  │  │      │  │  ├──0.05 MB (00.00%) ── rule-nodes
│  │  │      │  │  └──0.02 MB (00.00%) ── pres-contexts
│  │  │      │  ├──1.13 MB (00.04%) -- dom
│  │  │      │  │  ├──0.59 MB (00.02%) ── element-nodes
│  │  │      │  │  ├──0.43 MB (00.01%) ── text-nodes
│  │  │      │  │  ├──0.11 MB (00.00%) ── other [2]
│  │  │      │  │  └──0.00 MB (00.00%) ── comment-nodes
│  │  │      │  ├──0.36 MB (00.01%) ── style-sheets
│  │  │      │  └──0.00 MB (00.00%) ── property-tables
│  │  │      └──0.41 MB (00.01%) ++ window(about:blank)

(note that I have 2 tabs open on that URL, one unloaded. Or at least, I assume that's what the about:blank entry is for. The 45 seconds was for the loaded one. The unloaded one was 65ms, and happened later.)

Comment 9

[Nicholas Nethercote [inactive]]

Thanks for investigating further.  That's interesting data, but I'm not really sure what to do with it... :/

Comment 10

[Nicholas Nethercote [inactive]]

I'm going to close this because it doesn't look like it will go anywhere. Please reopen if you disagree.

Comment 11

[Steve Fink [:sfink] [:s:]]

I haven't seen this in a long time now.