bugzilla.mozilla.org has resumed normal operation. Attachments prior to 2014 will be unavailable for a few days. This is tracked in Bug 1475801.
Please report any other irregularities here.

Status

()

Core
JavaScript Engine
P3
normal
REOPENED
a year ago
9 months ago

People

(Reporter: MarkYen, Unassigned)

Tracking

(Blocks: 1 bug, {perf})

56 Branch
x86_64
Windows 10
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [qf:p3][QRC][QRC_Analyzed] )

Attachments

(1 attachment)

(Reporter)

Description

a year ago
STR:
1. Open Gmail in logged in state
2. Mouse click the first email in th inbox
3. Click on the “reply” button on the top right corner of the email

Short Gecko Profile(cover only Input Lantency action):
https://perfht.ml/2twhCX7
on Ref Device

Reports: https://goo.gl/V7un6P
Notes: https://docs.google.com/spreadsheets/d/1RgiyTm41Af-mC0lVkqiDT1sp9yKNkZ5cBoj7bApZWtY/edit?ts=596c1cbc#gid=256706414

Updated

a year ago
Blocks: 1366881
Whiteboard: [QRC][QRC_Analyzed]

Updated

a year ago
Whiteboard: [QRC][QRC_Analyzed] → [QRC][QRC_NeedAnalysis]

Comment 1

a year ago
Jed, could you help to have first analysis? Thanks.
Assignee: nobody → jld
Flags: needinfo?(jld)
Someone who knows a little bit about our js engine might be better. Jed works on sandboxing / security.
Flags: needinfo?(bchien)
I took a look at the profile, but I don't see any obvious hot spots.  Someone who knows the JS engine better might be able to see if there's a general JIT tuning problem going on here, or something like that.
Assignee: jld → nobody
Flags: needinfo?(jld)

Updated

a year ago
Component: JavaScript Engine → General
Flags: needinfo?(bchien)
I'm profiling this on Windows using xperf.

I didn't have an exact timing for this case, but it feels obviously slower. I just use the CPU usage diagram as a rough estimation of the time spent in opening the reply UI. The selected time span is from the native mouse up time to when the CPU usage drops to 0 for the main thread of the render/content process.

The difference is obvious on my workstation. Chrome vs Nightly is 670 ms vs 1600 ms. Chrome spent 634 ms in user space, and Nightly spent 1262 ms in user space. We have too much idle time.

If I filter the CPU samples using "GC", Chrome only has 33 samples (~33 ms) in user space. In contrast, I use "js::gc" as the filter, and we have 162 samples. We spent too much time in GC when opening the reply UI.

I'll update the bug when I have more findings from the profiles.
Assignee: nobody → cyu
Created attachment 8893775 [details]
Main thread idle for 100 ms

The attached screenshot is a 200 ms time span after I clicked the user name to open the chat tab. It can be seen that the main thread of the content process is not busy processing. In this span we spent 100 ms idling. The smaller peaks in the 2nd half of this span are mostly mouse move events. This span contains several script loads and ends with a completion of off-thread JS script loading. Then the main thread is busy running the JS script.

We need to investigate further where this delay come from. If it's because the server just hasn't sent us the scripts, we may not be able to do anything for it. If it's delayed for some other reason, we should improve that.
I made a head-to-head comparison between Nightly (57.0a1 2017-08-08) and Google Chrome Stable (60.0.3112.90) using xperf.
This use case is pretty computation-intensive. The main thread of the content/render process is 100% busy, and most of the time is spent in JS (including native code called from JS).

As an approximation of Hasal's measurement, my measurement starts at the time when the OS receives the MouseUp event, and ends at when mozilla::dom::Element::focus() is called for Nightly and blink::Document::SetFocusedElement() is called foe Google Chrome.

The test steps are:
1. Open the browser, open "mail.google.com". Because of the saved password, the browser signs on automatically and goes to the inbox.
2. Click the latest mail.
3. Click the reply button.
4. Go back to inbox.
5. Repeat from step 2 until we have performed this use case 5 times.

Here are my test results:
Nightly: 360 ms, 274 ms, 201 ms, 239 ms, 242 ms
Google Chrome: 160 ms, 78 ms, 78 ms, 70 ms, 71 ms

It looks like our JS engine produces more optimized code after the first 2 runs. Even so, we still have a higher variation. We still fall behind Google Chrome by a large margin.

We need someone with JS expertise to take a deeper look at this case.
Assignee: cyu → nobody

Updated

11 months ago
See Also: → bug 1381384

Comment 7

11 months ago
Naveed, could you find help in javascript team? Thanks.

Also attache historical numbers from perfherder:

Win7: https://treeherder.mozilla.org/perf.html#/graphs?series=%5B%22mozilla-central%22,%229f895f9b80b67f1760f8558afb153f749deccc64%22,1,9%5D&series=%5B%22mozilla-central%22,%22c0129b9875ad01281562db94d1ec5faadda0c9a0%22,1,9%5D

Win10: https://treeherder.mozilla.org/perf.html#/graphs?series=%5B%22mozilla-central%22,%22b5bb1e97342c43d067e35c3b4eabbc1e9645acaf%22,1,9%5D&series=%5B%22mozilla-central%22,%2232fc0e6ee22a421071853e629b88461fde526687%22,1,9%5D
Component: General → JavaScript Engine
Flags: needinfo?(nihsanullah)
Summary: gmail_ail_reply_mail for QRC_NeedAnalysis → gmail_ail_reply_mail
Whiteboard: [QRC][QRC_NeedAnalysis] → [qf][QRC][QRC_Analyzed]
Flags: needinfo?(nihsanullah)
Whiteboard: [qf][QRC][QRC_Analyzed] → [qf:p1][QRC][QRC_Analyzed]

Comment 9

11 months ago
(In reply to maggus.staab from comment #8)
> Duplicate of https://bugzilla.mozilla.org/show_bug.cgi?id=1367666 ?

Yes, the same issue reported from the different sources. Let's use here as the main discussion thread.
Status: NEW → RESOLVED
Last Resolved: 11 months ago
Resolution: --- → FIXED

Updated

11 months ago
Duplicate of this bug: 1367666

Updated

11 months ago
See Also: → bug 1367666

Comment 11

10 months ago
(In reply to Bobby Chien [:bchien] from comment #9)
> (In reply to maggus.staab from comment #8)
> > Duplicate of https://bugzilla.mozilla.org/show_bug.cgi?id=1367666 ?
> 
> Yes, the same issue reported from the different sources. Let's use here as
> the main discussion thread.

Is this supposed to be resolved? You mention using this as a discussion thread.

Comment 12

10 months ago
(In reply to blissdev from comment #11)
> (In reply to Bobby Chien [:bchien] from comment #9)
> > (In reply to maggus.staab from comment #8)
> > > Duplicate of https://bugzilla.mozilla.org/show_bug.cgi?id=1367666 ?
> > 
> > Yes, the same issue reported from the different sources. Let's use here as
> > the main discussion thread.
> 
> Is this supposed to be resolved? You mention using this as a discussion
> thread.

My mistake. Thanks.

Updated

10 months ago
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
I reprofiled this test case. Some time-consuming operations in the profile in comment #6 is now much faster:
nsGenericHTMLElement::SetContentEditable() reduced from 10 ms to 1.9 ms
Stylo is much faster. Filtering the time range using "servo::" and it only accumulates to 12 ms in the user space.
There is one 7.39 ms wait, where the main thread is waiting for other threads to complete the restyle (the stack shows rayon_core::latch::LockLatch::wait(), readied by another thread of the same process and the ready stack contains rayon_core::job::{{impl}}::execute.

This test case is now 298 ms, which is about 60ms shaved off compared to comment #6.
Priority: -- → P3

Comment 14

10 months ago
This bug will not be addressed in 57. Changing from qf:p1 to qf:p3 for post 57 work.
Whiteboard: [qf:p1][QRC][QRC_Analyzed] → [qf:p3][QRC][QRC_Analyzed]
You need to log in before you can comment on or make changes to this bug.