1269695 - (gdoc_pageend) [perf][google suite][google docs] 40.77%(7678 ms) slower than Chrome when opening 200+ pages mix content and to the page end

Status: RESOLVED INCOMPLETE

(Core :: JavaScript Engine, defect, P2)

Description

[Shako Ho]

# Test Case
STR
1. Launch the browser with blank page
2. input the google doc url with 100 page content ( 33 image, 33 table, others are txt)
3. Press ctrl+end ( to the last page)
4. close the browser

# Hardware
OS: Ubuntu 14.04 LTS 64-bit
CPU: i7-3770 3.4GMhz
Memory: 16GB Ram
Hard Drive: 1TB SATA HDD
Graphics: GK107 [GeForce GT 640]/ GF108 [GeForce GT 440/630]

# Browsers
Firefox version: 45.0.2
Chrome version: 50.0.2661.75

# Result
Browser | Run time (median value) 
Firefox | 26511.1111111111 ms
Chrome  | 18833.3333333333 ms

Comment 1

[Cynthia Tang [:cynthiatang]]

# Profiling Data:
https://cleopatra.io/#report=044257096cad876ba097681f99dd9d1a986703ed

# Performance Timing:
http://goo.gl/bUitTs
{ 
  "navigationStart": 1462772125577, 
  "unloadEventStart": 0, 
  "unloadEventEnd": 0, 
  "redirectStart": 0, 
  "redirectEnd": 0, 
  "fetchStart": 1462772125581, 
  "domainLookupStart": 1462772125581, 
  "domainLookupEnd": 1462772125581, 
  "connectStart": 1462772125581, 
  "connectEnd": 1462772125581, 
  "requestStart": 1462772125583, 
  "responseStart": 1462772126104, 
  "responseEnd": 1462772126104, 
  "domLoading": 1462772126109, 
  "domInteractive": 1462772128162, 
  "domContentLoadedEventStart": 1462772129359, 
  "domContentLoadedEventEnd": 1462772129360, 
  "domComplete": 1462772138007, 
  ”loadEventStart": 1462772138007, 
  "loadEventEnd": 1462772138020
 }

# Adding perf mark (#3) into following test script:
    sys.path.append(sys.argv[2])
    import browser
    import common
    import gdoc
    
    com = common.General()
    ff = browser.Firefox()
    gd = gdoc.gDoc()
    
    ff.clickBar()
    ff.enterLink(sys.argv[3]) 
    sleep(5)
    gd.wait_for_loaded()
    
    ff.profilerMark_3()
    type(Key.END, Key.CTRL)
    ff.profilerMark_3()

    sleep(2)
    gd.deFoucsContentWindow()

Comment 2

[Cynthia Tang [:cynthiatang]]

Attachment: test_firefox_gdoc_pageend_1462772080.har

Comment 3

[Cynthia Tang [:cynthiatang]]

# Try to identify the time when clicking Page End (Bug 1271225)

Profiler: https://goo.gl/tScpLh 

From Gecko Profiling data, the Range [66426, 74097]:
 7639  100% Startup::XRE_Main
 5632 73.7% ├─ nsViewManager::Dispatch
 5630 73.7% │  ├─ EventDispatcher::Dispatch
 5623 73.6% │  │  ├─ js::RunScript
            │  │  └─ ...so on
            │  └─ ...so on
            │ 
 1230 16.1% ├─ js::RunScript
 1230 16.1% │  ├─ js::RunScript
  603  7.9% │  │  ├─ JS::HeapObjectPostBarrier(JSObject**,JSObject*,JSObject*)                        
            │  │  └─ ...so on
            │  └─ ...so on
            └─ ...so on

Comment 4

[Cynthia Tang [:cynthiatang]]

From Gecko Profiling data, the Range [45135, 57152]:
 11851  100.0%  Startup::XRE_Main
  4377   36.9%  ├─ Timer::Fire
  3961   33.4%  │  ├─ js::RunScript 
   367    3.1%  │  ├─ nsJSContex::GarbageCollectNow
                │  └─ ...so on
                │
  2446   20.6%  ├─ nsInputStreamPump::OnInputStreamReady
  2210   18.6%  │  ├─ nsInputStreamPump::OnStateStop 
   149    1.3%  │  ├─ nsInputStreamPump::OnStateStart
    44    0.5%  │  └─ nsInputStreamPump::OnStateTransfer
                │
  1641   13.8%  ├─ nsHtml5TreeOpExecutor::RunFlushLoop
  1439   12.1%  │  ├─ nsJSUtils::EvaluateString
   167    1.4%  │  ├─ EventDispatcher::Dispatch
                │  └─ ...so on
                │
  1522   12.8%  ├─ nsRefreshDriver::Tick 
   912    7.7%  │  ├─ PressShell::Paint
   371    3.1%  │  ├─ PressShell::Flush (Flush_Style)
                │  └─ ...so on
                └─ ...so on

Note
 1. Filed Bug 1272186 for tracking "js::RunScript"
 2. Filed Bug 1272187 for tracking "nsInputStreamPump::OnStateStop"
 3. Filed Bug 1272188 for tracking "nsJSUtils::EvaluateString"
 4. Filed Bug 1272190 for tracking "nsRefreshDriver::Tick"

Comment 5

[Cynthia Tang [:cynthiatang]]

Bug 1272186 has been marked as a duplicate of bug 1271914
Bug 1272187 has been marked as a duplicate of bug 1267971 
Bug 1272188 has been marked as a duplicate of bug 1270351 
Bug 1272190 has been marked as a duplicate of bug 1270427

Comment 6

[Andrew Overholt [:overholt]]

(In reply to Shako Ho from comment #0)
> 2. input the google doc url with 100 page content ( 33 image, 33 table,
> others are txt)

Can you provide the test document's URL?

Comment 7

[Andrew Overholt [:overholt]]

Olli, seems like we're spending lots of time dispatching events but maybe that's expected?

Comment 8

[Olli Pettay [:smaug][[e-mail]]]

I don't see anything hinting event dispatch takes lots of time.
Seems like this is mostly, or at least largely, JS.
Event dispatch is just on top of the stack since events tend to trigger JS code to run.

Comment 9

[Shako Ho]

Hi Andrew,
Sorry, the test script url as below:
https://github.com/Mozilla-TWQA/Hasal/blob/master/tests/test_chrome_load_file.py
https://github.com/Mozilla-TWQA/Hasal/blob/master/tests/test_firefox_load_file.py

Comment 10

[Cynthia Tang [:cynthiatang]]

Hi Andrew,
The test document's URL is https://docs.google.com/document/d/1EPSmGqm2r4Qq42B4t1VOYacjTlL0JVuC8JSlUvoIhss/edit

Thank you.

(In reply to Andrew Overholt [:overholt] from comment #6)
> (In reply to Shako Ho from comment #0)
> > 2. input the google doc url with 100 page content ( 33 image, 33 table,
> > others are txt)
> 
> Can you provide the test document's URL?

Comment 11

[Olli Pettay [:smaug][[e-mail]]]

I wonder, is the cleopatra profile created using Nightly or some release version?
IIRC Gecko profiler gives better information when used with Nightly, though one needs to remember to set javascript.options.asyncstack to false (see bug 1280819).

Comment 12

[Andrew Overholt [:overholt]]

ni?(Shako) for comment 11

Comment 13

[Shako Ho]

Reply to comment 11
Hi Olli,
This testing result is based on Ubuntu default installed Firefox which version is 45.0.2. 
Sorry, one question about "IIRC Gecko profiler", Is "IIRC Gecko profiler" equal to "Gecko profiler"?
If yes, we have another test for the Nightly, you can reference the bug 1285181 , we generate another profiler data with Gecko Profiler and Nightly build.
If not, could you provide more information about "IIRC Gecko profiler", I didn't get much information about if after google it.

Thanks,
Shako

Comment 14

[Kan-Ru Chen [:kanru] (UTC+9)]

(In reply to Shako Ho from comment #13)
> This testing result is based on Ubuntu default installed Firefox which
> version is 45.0.2. 
> Sorry, one question about "IIRC Gecko profiler", Is "IIRC Gecko profiler"
> equal to "Gecko profiler"?
> If yes, we have another test for the Nightly, you can reference the bug
> 1285181 , we generate another profiler data with Gecko Profiler and Nightly
> build.

I think Olli meant that Gecko Profiler gives better information when used with Nightly.

Regarding testing against stable release, we should be testing the build produced by ourself, ie. downloaded from our server.

Comment 15

[Olli Pettay [:smaug][[e-mail]]]

Yes, we should be testing our own builds and also non-ESR, but more recent, since there has been many performance improvements since FF45.
So, at least FF47, but Nightly is probably better (possibly tested with and without e10s enabled)

I don't know how accurate the availability of native stack is in https://developer.mozilla.org/en-US/docs/Mozilla/Performance/Profiling_with_the_Built-in_Profiler#Native_stack_vs._Pseudo_stack
but it hints that Nighty builds would give better information.

Comment 16

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

Just from my wallclock timings, I am still seeing a huge difference between my local opt build (with hw accel off, gc poisoning off, non-e10s) of 51 -- about 11sec to jump to the end, vs around 6sec in Chrome 52.0.2743.116 (64-bit) on Fedora 24.

My profile is https://cleopatra.io/#report=8061075abe111ece0019758ca3aff909e0a7d5bf which, although it does show a lot of time in RunScript, seems to be saying to my naive eye that we're spending a lot of that time in layout.

I struggled a bit to get a recording from the builtin Firefox devtools (it overflows the buffer, sometimes results in a Stop Script alert, and has mysterious pauses), but just from the raw number of "Layout" marker entries, it seems to agree.

On the other hand, I'm doubting myself because the Chrome devtools show the majority of time in script. On the gripping hand, the heaviest function is:

function Gfb(a, b, c, d, e) {
    b != a.H && (a.H = b,
    b = KE(LE.Ka(), b, d),
    a.F.style.cssText = b);
    a.F.innerHTML = c;
    e.firstChild != a.C && (Gp(e),
    e.appendChild(a.C));
    return e.getBoundingClientRect().width
}

which looks pretty layout-y to me. Maybe? bz, any opinion here?

Comment 17

[Boris Zbarsky [:bzbarsky]]

> My profile is https://cleopatra.io/#report=8061075abe111ece0019758ca3aff909e0a7d5bf 

So RunScript near toplevel is being listed as 64% of the time here.  Under there, we have at least 6% GC (nursery and otherwise), at least 24% layout flushing from script, and the rest of the time (so call it 34%) is various JS engine bits.  I wish I could just blame all the JS-execution bits on their ancestors so I could get a better idea of what SpiderMonkey stuff is being called and how much of the time is jitcode.

There's also 12% ticking the refresh driver, breaking down as: 2% nursery GC, 2% non-nursery GC, 3% painting, 1% layout, 3% some sort of event dispatch that does script execution.

10% of the profile is claimed to be polling.

5% is timers firing and doing GC.

And as usual some long-tail stuff.  So in general 25% (or maybe a bit more if I missed some more calls to it) is layout, 15% GC of various sorts, 37% various JS execution (maybe there's more gc in there; dunno), 3% painting, 10% polling.  That adds up to 90%.

> which looks pretty layout-y to me.

And DOM-y, if those parts of the function are reached (the innerHTML set).  Note that in the profile linked from comment 16 I see no obvious GetBoundingClientRect calls.  I do see SetInnerHTML, but not many profiler hits in there....  Same for SetCssText.

Comment 18

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

Since GC came up, I looked at the total hits for major GC (js::GCRuntime::collect): 101. For minor GC (js::Nursery::collect): 99. Given that a major GC starts out by doing a minor GC, that means that almost all of the GC time was in nursery collections. GC time comes to 2% of the total.

That seemed a little odd to me. But I looked at the Chrome run in their devtools, and they're showing the same thing: 4.9% of the time in minor GC, 0.4% of the time in major GC.

At any rate, at 2% it doesn't seem like GC is a big component here.

I wish I had a better way to answer the question "why is Firefox taking longer on this than Chrome?"

Comment 19

[Boris Zbarsky [:bzbarsky]]

> At any rate, at 2% it doesn't seem like GC is a big component here.

The profile linked in comment 16 has at least to 10% GC, based on my numbers in comment 18  Just under Timer:::Fire (called from Startup::XRE_Main according to the profile) we have a GarbageCollectNow call that has 233 samples.  172 of them are under GCRuntime::collect and 61 are under Nursery::collect.  That's out of a total of 4661.

If I filter on GCRuntime::collect I see 535 samples total in that profile.  For Nursery::collect I see 366 samples.  Oh, and the callstacks to Nursery::collect in that profile do NOT seem to go through GCRuntime::collect.  For example, nsJSContext::GarbageCollectNow is shown as calling both functions separately, not one from the other.

Comment 20

[Andrew McCreight [:mccr8]]

We call nsJSContext::PokeGC() in nsGlobalWindow::SetNewDocument(). This queues up a GC for 5 seconds later. On these really tough Google docs cases, loading can take more than 5 seconds, and you hit a GC during the load. We also call PokeGC() in nsDocumentViewer::LoadComplete(), so maybe this one should be removed?

Comment 21

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

(In reply to Boris Zbarsky [:bz] from comment #19)
> > At any rate, at 2% it doesn't seem like GC is a big component here.
> 
> The profile linked in comment 16 has at least to 10% GC, based on my numbers
> in comment 18  Just under Timer:::Fire (called from Startup::XRE_Main
> according to the profile) we have a GarbageCollectNow call that has 233
> samples.  172 of them are under GCRuntime::collect and 61 are under
> Nursery::collect.  That's out of a total of 4661.
> 
> If I filter on GCRuntime::collect I see 535 samples total in that profile. 
> For Nursery::collect I see 366 samples.  Oh, and the callstacks to
> Nursery::collect in that profile do NOT seem to go through
> GCRuntime::collect.  For example, nsJSContext::GarbageCollectNow is shown as
> calling both functions separately, not one from the other.

Ugh. Sorry, I failed at using cleopatra. I think what happened is that I expanded the tree to the js::GCRuntime::collect underneath nsRefreshDriver::Tick, and clicked on the right arrow, thinking that meant to look at all samples whose stacks contain that function. :( It looks like it does something more useful, which is to look at that function only within the selected context, but without any indication in the UI of what context you are in. Sorry, you are correct, that's a lot of GC. Yay! Something to look into.

And also, you are right. Although GCRuntime::collect always invokes a minor GC at the beginning (via gcCycle -> evictNursery), either we never took a sample there or it's all inlined away.

(535+366)/4661 says nearly 20% of the samples were in GC. (And just in case, filtering on ::collect finds 901 samples, so there aren't any duplicates with both functions on the stack.)

Comment 22

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

(In reply to Andrew McCreight [:mccr8] from comment #20)
> We call nsJSContext::PokeGC() in nsGlobalWindow::SetNewDocument(). This
> queues up a GC for 5 seconds later. On these really tough Google docs cases,
> loading can take more than 5 seconds, and you hit a GC during the load. We
> also call PokeGC() in nsDocumentViewer::LoadComplete(), so maybe this one
> should be removed?

Makes sense to me. Though I guess there's the case where we pile up enough garbage during a long load that we *want* to GC some of it away? (Or does JS run before LoadComplete? Maybe this is for CC stuff?) I don't know how much garbage the loading can create.

That wouldn't apply to the profile in comment 16, though. I loaded the page first, then started the profiler just before pressing Ctrl-end. The profile in comment 1 *does* contain the whole load. (The test script adds markers to identify just the Ctrl-end portion.) That profile is for 92sec, 52sec of it waiting in poll(). GC accounts for 8% of the non-poll time there.

Comment 23

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

I was hoping that bug 1237058 would improve this case, but on my machine, it does not appear to have changed much.

   - Firefox: 8.7 9.2 13.6 7.9 11.5
   - Chrome: 5.2 4.6 5.6

Comment 24

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

Sorry for the kind of blind forward, but jonco, can you make sense of just the GC portion of this?

This particular test is pretty easy to reproduce on my laptop at least -- I load the page <https://docs.google.com/document/d/1db4kafFrlLmjW-ZHioLzZcHUiJnSQFS-sNl8xRYfE5c/edit>, then reload and start timing once it's loaded, then press Ctrl-end, and stop timing when it shows the final page's image. (If you immediately go to the end of the document rather than do an initial reload, you'll often get extremely fast results (especially in Chrome, but somewhat in Firefox as well), but I suspect that's because it's doing more of some sort of "prep" work during that initial load. Or something.)

My currently Nightly's timings are in comment 23.

I have looked at the GC logs for this, which is how I noticed that we were pretty frequently overrunning the budget on the mark -> sweep transition, but you've fixed that already and that's a latency thing, not a throughput thing like this bug is about.

Comment 25

[Jon Coppeard (:jonco)]

I can reproduce this and get similar timings (~12 seconds on firefox vs ~8 on chrome).

I tried removing the SET_NEW_DOCUMENT GC poke but that had no discernible effect either on total time or overall GC behaviour.

I did notice some long GC slices, which all seem to be for different reasons.  I'll continue to investigate.

Comment 26

[Jon Coppeard (:jonco)]

I'm seeing occasional GC slices of > 1 second caused by time spent in CancelOffThreadIonCompile.  It seems that occasionally we wait a very long time for a cancelled helper thread to signal that it is finished here:

http://searchfox.org/mozilla-central/source/js/src/vm/HelperThreads.cpp#168

Comment 27

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

I just did another non-e10s run on the 2016-10-07 nightly. Bug 1304081 landed in the 2016-09-22 nightly, so it should be included. My profile is https://cleopatra.io/#report=9669142ecbd1e43451935dbc7b8bc57ede011f99 and the summary is:

  script: 44%
  GC: 29%
  layout: 9%
  wait: 8%
  frameconstruction: 2%

So we're still seeing lots of script and GC (assuming the symbolication is correct), and the majority of that scripting is *not* just triggering layout.

Comment 28

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

sstangl: If you'd like to look at one of the google docs perf examples, this bug is a pretty good example of the sort of thing we're looking at. It has lots of time spent in scripting and GC.

To reproduce, you can visit https://docs.google.com/document/d/1EPSmGqm2r4Qq42B4t1VOYacjTlL0JVuC8JSlUvoIhss/edit

Cleopatra profile is at https://cleopatra.io/#report=9669142ecbd1e43451935dbc7b8bc57ede011f99

Reduced Tracelogger files are uploaded to http://people.mozilla.org/~sfink/data/bug-1269695-200page-end.tar.xz but note that this contains an initial load, a reload, and then the go-to-last-page processing. I haven't come up with a good way to mark regions of interest for TL yet.

jonco was looking at the GC stuff, and has fixed some things, but we're still doing a ton of GC here. (And all of this is against a background of not knowing how much of this is unavoidable, and is a function of what the page is doing.)

Comment 29

[Jenn Chaulk (:jchaulk)]

plat-rel tracked at the meta level

Comment 30

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

(No reason to treat this bug specially.)

Comment 31

[Nicolas B. Pierron [:nbp] {away}]

Nobody looked into these bugs for a while, moving to P2 and waiting for [qf] re-evaluation before moving back to P1.

Comment 32

[Daniel Holbert [:dholbert]]

[qf-] because opening 200+ tabs is not a typical use case.  Other blockers of bug 1260981 may be more relevant for qf.

Comment 33

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

(In reply to Daniel Holbert [:dholbert] (PTO 7/26 - 7/30) from comment #32)
> [qf-] because opening 200+ tabs is not a typical use case.  Other blockers
> of bug 1260981 may be more relevant for qf.

Is this comment for the correct bug? I'm not arguing that this shouldn't be closed, but this bug is about a 200+ page Google Doc, not multiple tabs.

Comment 34

[Daniel Holbert [:dholbert]]

(In reply to Steve Fink [:sfink] [:s:] from comment #33)

Is this comment for the correct bug? I'm not arguing that this shouldn't be
closed, but this bug is about a 200+ page Google Doc, not multiple tabs.

Only just seeing this question now, sorry. Yeah, it looks like we misunderstood what "200 pages" meant in the bug title here when doing QF triage on this.

In any case, I dropped by this bug to ask if anyone knows at this point what the the Google Docs URL in question is here? We don't seem to have captured it in this bug report. Comment 0 just says "the google doc url with 100 page content ( 33 image, 33 table, others are txt)" -- this implies we had some standard test doc, but I'm not sure what it was.

(I got a bot-triggered needinfo on associated bug 1329601 which was for a slow reflow with this bug's STR, I think; and I'm wondering if we still have the doc handy anywhere.)

Comment 35

[Daniel Holbert [:dholbert]]

(In reply to Daniel Holbert [:dholbert] from comment #34)

In any case, I dropped by this bug to ask if anyone knows at this point what the the Google Docs URL in question is here?

I do see a link in comment 28 which might be the answer to my question, but that google doc seems to have been deleted since then ("Sorry, the file you have requested does not exist."

As I noted in bug 1329601: if we don't have the original URL, I think we can assume that Google Docs' performance is quite different nowadays vs. when this was filed, due in part to their rewrite to move to Canvas as discussed in https://workspaceupdates.googleblog.com/2021/05/Google-Docs-Canvas-Based-Rendering-Update.html

sfink: I'll defer to you since this bug is classified under JS, but I'd suggest that we might want to close this bug as INCOMPLETE (like I did for bug 1329601), given that (I think) we don't have the original testcase, and given the likelihood that Google Docs' perf issues have changed as part of various rewrites on our end as well as Google's. We can track any modern-day Google Docs perf bugs in new bug reports, as we discover them.

Comment 36

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

I fully agree with your reasoning here.