1381382 - facebook_ail_click_open_chat_tab

Status: RESOLVED WORKSFORME

(Core :: General, defect)

Description

[MarkYen]

STR:
0. Login with White Hat account.
1. Click on a name in the chat panel on the right side.
2. Wait for the chat window to open.

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

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

Comment 1

[Bobby Chien]

New profiling for open-chat-tab on facebook

Comment 2

[Ting-Yu Chou [:ting] (away)]

The profile has untranslated symbols in xul.pdb, is this a local build or a Nightly?

Comment 3

[MarkYen]

(In reply to Ting-Yu Chou [:ting] from comment #2)
> The profile has untranslated symbols in xul.pdb, is this a local build or a
> Nightly?

Latest Nightly build

Comment 4

[MarkYen]

(In reply to Ting-Yu Chou [:ting] from comment #2)
> The profile has untranslated symbols in xul.pdb, is this a local build or a
> Nightly?

Version: 56.0a1
Build ID: 20170716030208

Update Short Gecko Profile:
https://perfht.ml/2tw2GrU

Comment 5

[Cervantes Yu [:cyu] [:cervantes]]

One thing that is worth deeper investigation is that after the content process receives the mouse click event, the main thread has ~20ms idle.

Comment 6

[Cervantes Yu [:cyu] [:cervantes]]

Though not counted in the measurement of bug 1366960, there are several blocking operations when the user clicks to open a chat tab. One is tracked in bug 1382150. There are also several GetCookie sync IPC operations, one taking about 50ms, which should be fixed by bug 1331680.

Comment 7

[Cervantes Yu [:cyu] [:cervantes]]

This test case also spent some in CSS. Turning on stylo helps to shave off 20~30 ms on my workstation (e.g. 65ms vs 28ms).

Comment 8

[Bobby Chien]

Tingyu, could you help to continue the investigation? Thanks.

Comment 9

[Ting-Yu Lin [:TYLin] (PST, UTC-7)]

By reading the profile in comment 4 and my own local profile, I don't have other observation to add other than those mention by Cervantes.

Comment 10

[Bobby Chien]

tracking under Quantum Flow

Comment 11

[Ting-Yu Chou [:ting] (away)]

(In reply to myen from comment #4)
> Update Short Gecko Profile:
> https://perfht.ml/2tw2GrU

In this profile, there are 234 samples from 1.717ms where mouseup to 2.117ms (+400ms which is the average latency that Hasal reports)

234ms 100.0% (root)
  185ms  79.1% js::RunScript
    123ms  52.6% EventListenerManager::HandleEventInternal load
     19ms   8.1% EventListneerManager::HandleEventInternal click
     16ms   6.8% nsJSUtils::ExecutionContext
     12ms   5.1% js::RunScript
      8ms   3.4% EventListenerManager::HandleEventInternal message
      7ms   3.0% nsTimerImpl::Fire -> js::RunScript ha
   21ms   9.0% nsRefreshDriver::Tick (13ms in style, 6ms in paint)
   13ms   5.6% WaitForMessage

Comment 12

[Cervantes Yu [:cyu] [:cervantes]]

I have local xperf profiles of Firefox nightly (57.0a1 2017-08-07) and Google Chrome stable (60.0.3112.90) for head-to-head comparison. I tried to mimic metric Hasal currently uses. I only measure the CPU usage of the main threads of the content/renderer processes. Time span of my measurement begins at the mouse click and ends at when the content/renderer process creates a GL context for the HTML canvas, when the browser shows the outer frame of the chat box and starts to render the inner content of the chat box. This is used as an approximation to Hasal's metric.

Main thread's CPU usage can be roughly divided into 2 parts: samples with full stack containing ntdll!RtlUserThreadStart, indicating we are not running some JS code. It could be paint, layout, HTTP, layout, style, etc. The other part contains samples containing partial stack with the (?!?) bottommost frame, indicating we are running some JS code. Google Chrome also has full stacks containing "V8ScriptRunner". These samples are also counted as running JS.

The following comparisons are taken from 2 Nightly profiles and 2 Google Chrome profiles.

The whole time spans are 286 and 283 ms for Nightly and 397 and 366 ms.
In my profiles, Nightly spends 275 and 277 ms in user space, and Google Chrome spends 153 and 214 ms.
Nightly spends 216 and 217 ms in JS. Google Chrome spends 127 and 189 ms in JS.
Nightly spends 43 and 48 ms in jitted JS. Google Chrome spends 29 and 44 ms in jitted JS.
Nightly spends 58 and 48 ms in non-JS code. Google Chrome spends 26 and 25 ms in non-JS code.

In my profiles, we are slightly better than Google Chrome in this measurement because our main thread is pretty busy, taking full utilization of the CPU. In contrast, Google Chrome spends quite some time idling. In my previous profiles, sometime our main thread can spend some time idling too (like waiting for off-thread script compilation). I am not sure if this experiment is consistently reproducible, or I just had better luck in Nightly. We need more data to tell.

Note that we still spend more time in user space, either in JS or non-JS part. It shows that we still have pretty much room for improvement. The tests are conducted with browser shutdown/restart. Maybe our JS engine doesn't have chance to optimize the JS code further.

Comment 13

[Bobby Chien]

worksforme per the bug 1366960, comment 17. 

Attached perfherder link: https://treeherder.mozilla.org/perf.html#/graphs?timerange=2592000&series=mozilla-central,1509565,1,9&series=mozilla-central,1509567,1,9