1271544 - "nsRefreshDriver::Tick" spent more time when typing

Status: RESOLVED INCOMPLETE

(Core :: General, defect)

Description

[Shako Ho]

ref profile:
https://goo.gl/tpriAy

Analyze the running time when typing
From Gecko Profiling data, the Range [60591, 178539]:
 11794  100% Startup::XRE_Main
  3515 29.8% ├─ nsViewManager::DispatchEvent
  3492 29.6% │  └─ EventDispatcher::Dispatch
  3386 28.7% │     └─ js::RunScript
  3226 27.4% ├─ nsRefreshDriver::Tick
  1810 15.3% │  ├─ PreShell::Paint
   938  8.0% │  ├─ PreShell::Flush (Flush_Style)
             │  └─ so on
  2334 19.8% ├─ Timer::Fire
             │  └─ ...so on
             └─ ...so on

Comment 1

[Naveed Ihsanullah [:naveed]]

Needs root cause analysis

Comment 2

[Jet Villegas (inactive)]

We're flushing Layout & painting after the tick to render the character that was typed. That takes some time to do vs. nothing to render.

Comment 3

[Daniel Holbert [:dholbert]]

Can you still reproduce? Do you have a testcase or website in particular that's affected? (Or does this happen in general for typing in any site?)

[ni=reporter, & also jet in case he reproduced this while investigating in comment 2 -- not sure]

Comment 4

[Daniel Holbert [:dholbert]]

(Comment 2 sounds like the reported behavior is expected, too -- is there anything particularly known to be bad/unexpected here?)

Comment 5

[Daniel Holbert [:dholbert]]

Marking [qf-] since this seems like expected behavior, per comment 2 & comment 4.

(Please renominate if I'm misunderstanding & there's some significant & unexpected perf hit here.)

Comment 6

[Shako Ho]

(In reply to Daniel Holbert [:dholbert] (reduced availability - travel & post-PTO backlog) from comment #3)
> Can you still reproduce? Do you have a testcase or website in particular
> that's affected? (Or does this happen in general for typing in any site?)
> 
> [ni=reporter, & also jet in case he reproduced this while investigating in
> comment 2 -- not sure]

Hi Daniel,

 This test case tests against the Google Doc, we crate a blank page and start to type characters, insert image and create tables.

  The STR as below:

  0. Open the browser, paste a blank google document link in the urlbar.
  1. After the page is loaded, keep typing format10 until 1 page is fully written.
  2. Change the last few line to Bold.
  3. Insert an image and go to next page
  4. Create 1 page of content with keyword(format10) in it & Make the last line bulleted list
  5. reate 20*20 table and go to next page
  6. Repeat step 1 to 5 3 times
  7. Create 1 page of content with keyword in it & Make the last line bold

Comment 7

[Jet Villegas (inactive)]

(In reply to Daniel Holbert [:dholbert] from comment #3)
> Can you still reproduce? Do you have a testcase or website in particular
> that's affected? (Or does this happen in general for typing in any site?)
> 
> [ni=reporter, & also jet in case he reproduced this while investigating in
> comment 2 -- not sure]

The bug as filed was to investigate why we spend more time in ::Tick when typing text in a Google doc. The time spent seems consistent with laying out and painting text:

  3226 27.4% ├─ nsRefreshDriver::Tick
  1810 15.3% │  ├─ PreShell::Paint
   938  8.0% │  ├─ PreShell::Flush (Flush_Style)

Comment 8

[Daniel Holbert [:dholbert]]

Thanks. If I'm understanding correctly, it sounds like things are working as-intended then.

 --> Resolving as INVALID, since the problem described is not a bug.

Comment 9

[(no longer active)]

I don't understand how this is working as intended...  We should very well be capable of painting the dynamic changes worth of typing a character in a page within a frame budget.  If we can't, that is a serious problem.

I suspect what we are seeing here though is bug 1343538 (overpainting on google docs).  Shako, can you please turn on paint flashing and try your test case again and see what portions of the screen are being repainted?  If things work as intended, you should see a small part of the page change its color as you type (for example around the character being typed, or the text in the same paragraph or some such.)  If vast parts of the page keep changing their colors, then we are overpainting the page.

(To turn on paint flashing, you can press Shift+F2, and enter the "paintflashing on" command.)

Comment 10

[Daniel Holbert [:dholbert]]

(In reply to :Ehsan Akhgari (needinfo please, extremely long backlog) from comment #9)
> I don't understand how this is working as intended...  We should very well
> be capable of painting the dynamic changes worth of typing a character in a
> page within a frame budget.

Do we have a demonstration of that *not* happening here? (It's not clear to me that we do.)

The reported numbers are for a 118-second timeperiod, I think (comment 0 says it's from "the Range [60591, 178539]").  And IIUC, the breakdown in comment 0 shows that we're spending 1.81 seconds on painting, during that 118 second long period.

So that averages out to 15ms of painting per second, which is (barely) under the 16ms 60fps frame budget (again, on average).  Having said that, if we look at the nsRefreshDriver time (3226ms i.e. 3.226 seconds), then clearly we're breaking the 60fps budget by a little. (17ms of nsRefreshDriver tick per second)  Obviously it'd be better if the average were less than 15ms; I don't have a good feel for how crazy-high that measurement is, but superficially it doesn't seem too extreme for a use-case when a user is typing continuously on a complex webapp.

In any case: I'll bet you're right that this could be related to bug 1343538.