1305238 - garbage collection slows page load of bugzilla.mozilla.org

Status: RESOLVED WORKSFORME

(Core :: JavaScript: GC, defect, P3)

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Attachment: screenshot bmo performance analysis

Firefox 49.0 64 bit on Windows 8.1 (not new in 49.0)

In my default profile with hundreds of tabs, loading a bugzilla page, e.g. https://bugzilla.mozilla.org/ takes ~30 seconds even if most of it gets loaded from cache. Performance analysis shows that small GC is running almost all the time. I don't see the issue with other sites (at least it isn't noticeable). There are still 6 GB RAM available.

bmo contains a 400KB minified JavaScript file, does that trigger that? https://bugzilla.mozilla.org/data/assets/bccac07675cf5ec5378a5dc580e746cd.js?1474380019

FTR, while testing this, I was able once to load the page in <2 seconds.

Comment 1

[Ben Kelly [:bkelly, not reviewing]]

If you can reproduce this an SPS profile using these instructions would probably be helpful:

https://developer.mozilla.org/en-US/docs/Mozilla/Performance/Profiling_with_the_Built-in_Profiler

Comment 2

[Andrew McCreight [:mccr8]]

If you set javascript.options.mem.log to true in about:config, then you'll get information about GC times in the browser console. The information isn't quite complete, but it will be a start.

Comment 3

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Attachment: gc log

Warning: Numbers are formatted by an OS in German, so "," means en-US "."

The browser console shows almost constantly messages like this:
GC Slice 21 - Pause: 10,059ms of 10ms budget (@ 1622,357ms); Reason: REFRESH_FRAME; Reset: no; Cycles: 1 Times: Mark: 6,904ms, Minor GCs to Evict Nursery: 2,819ms, Other: 1,103ms, Mark Roots: 1,716ms, Other: 1,508ms, Mark Rooters: 0,208ms

GC stops when bmo gets loaded and shows messages like this after they page loaded:
GC(T+4016.5)[default] Summary - Non-Incremental: 14392,326ms (requested); Zones: 2903 of 4346; Compartments: 9307 of 10750; HeapSize: 1874,418 MiB; HeapChange (abs): +0 (0); 

11:11:54.890 GC Slice 524 - Pause: 104,369ms of 10ms budget (@ 24100,337ms); Reason: REFRESH_FRAME; Reset: no; Cycles: 1 Times: Sweep: 97,292ms, Other: 0,107ms, Mark During Sweeping: 57,660ms, Other: 1,032ms, Mark Weak: 28,718ms, Mark Gray and Weak: 27,907ms, Finalize Start Callbacks: 10,808ms, Per-Slice Weak Callback: 10,801ms, Sweep Compartments: 28,688ms, Sweep Miscellaneous: 28,633ms, Minor GCs to Evict Nursery: 5,357ms, Other: 2,851ms, Mark Roots: 2,506ms, Other: 1,996ms, Mark Rooters: 0,510ms

Comment 4

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

(In reply to Ben Kelly [:bkelly] from comment #1)
> If you can reproduce this an SPS profile using these instructions would
> probably be helpful:
> 
> https://developer.mozilla.org/en-US/docs/Mozilla/Performance/
> Profiling_with_the_Built-in_Profiler
Steps to reproduce (on my machine) without leaking personal data:
1. Create new profile for Firefox release (50.1.0 64-bit on Windows 8.1 64-bit; Nightly unloads the inactive tabs (or doesn't even load them and I don't know the preference to switch that behavior).
2. Install the Gecko profiler add-on from the link above.
3. Just loading the bugzilla tabs from my default profile (~110 tabs) is insufficient to reproduce the long load times. So I load 1000 bugzilla tabs in chunks with the following script which I run in scratchpad with chrome privileges (set devtools.chrome.enabled to true to have that option):

var bugnumberStart = 800000;
var tabsToOpen = 500;
for (let bugnumber = bugnumberStart; bugnumber < bugnumberStart + tabsToOpen; bugnumber++)
{
  gBrowser.addTab("https://bugzilla.mozilla.org/show_bug.cgi?id=" + bugnumber)
}

It's best to start with big chunks and loader small ones later, but be aware that sometimes when I loaded the last 200-300 tabs, private bytes skyrocketed from 5.x GB to 17+ GB.

4. After everything has loaded, open a new tab and load https://bugzilla.mozilla.org/

Actual result:
Loading might still be fast, e.g. https://cleopatra.io/#report=b99aacffcb499f97e7fb0c4dff4518677cbc5938
But most often it takes 10 or more seconds, e.g.
https://cleopatra.io/#report=316ec96bd8c2976631bf84466b01915e75a691b6
https://cleopatra.io/#report=3bc0ef7eefdc742b7a905de4fdf2583e903bbe6b
https://cleopatra.io/#report=43a8e70ca8ec2384c1f729af9f186ecda8fcbac5

A stack capture during such a 'Loading' phase:
xul.dll!js::gc::ArenaCellIterImpl::next+0x2e
xul.dll!SweepArenaList<js::Shape>+0x51
xul.dll!js::gc::GCRuntime::sweepPhase+0x2e4
xul.dll!js::gc::GCRuntime::incrementalCollectSlice+0x14a
xul.dll!js::gc::GCRuntime::gcCycle+0x193
xul.dll!js::gc::GCRuntime::collect+0x97
xul.dll!js::gc::GCRuntime::gcSlice+0x42
xul.dll!nsJSContext::GarbageCollectNow+0x97
xul.dll!nsTimerImpl::Fire+0x3db
xul.dll!nsTimerEvent::Run+0xf5
xul.dll!nsThread::ProcessNextEvent+0x33e
xul.dll!NS_ProcessNextEvent+0x22
xul.dll!mozilla::ipc::MessagePump::Run+0x105
xul.dll!mozilla::ipc::MessagePumpForChildProcess::Run+0x70
xul.dll!MessageLoop::RunHandler+0x1b
xul.dll!MessageLoop::Run+0x3e
xul.dll!nsBaseAppShell::Run+0x3c
xul.dll!nsAppShell::Run+0x2c
xul.dll!XRE_RunAppShell+0x2e
xul.dll!mozilla::ipc::MessagePumpForChildProcess::Run+0x29
xul.dll!MessageLoop::RunHandler+0x1b
xul.dll!MessageLoop::Run+0x3e
xul.dll!XRE_InitChildProcess+0x63c
firefox.exe!content_process_main+0x8e
firefox.exe!wmain+0x463c
firefox.exe!__scrt_common_main_seh+0x124
KERNEL32.DLL!BaseThreadInitThunk+0x22
ntdll.dll!RtlUserThreadStart+0x34

Comment 5

[hatasoft]

i've noticed this with other sites, google.com in particular
it happens when i don't restart firefox for several days
here is my config http://pastebin.com/VV7bnWhJ
i'll attach memory report and performance profile captured when loading https://www.google.by/search?q=hello&ie=utf-8&oe=utf-8&client=firefox-b-ab&gfe_rd=cr&ei=UntmWPibBorDNPrXhtAN

Comment 6

[hatasoft]

Attachment: memory-report.json.gz

Comment 7

[hatasoft]

Attachment: performance profile.zip

performance profile when loading a google search page

Comment 8

[Nickolay_Ponomarev]

I can reproduce some pauses using the steps from comment 4. There's an older but similar bug 1229654.

I filed bug 1332880 for a similar problem I'm having.

Comment 9

[Julien Cristau [:jcristau]]

Too late for firefox 52, mass-wontfix.

Comment 10

[Wayne Mery (:wsmwk)]

aryx, do you still encounter this? I routinely have 200-500 tabs, at least half of which are BMO, and I don't see this problem.