Closed Bug 987408 Opened 11 years ago Closed 11 years ago

Slow reflows at app startup with very simple content, largely due to CheckForFeaturesInvolvingSpace() during textrun creation

Categories

(Core :: Graphics: Text, defect, P2)

Product:
Core
Component:
Graphics: Text
Platform:
All
Gonk (Firefox OS)
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla31
Project Flags:
blocking-b2g 1.4+
Tracking Flags:
Tracking Status
firefox29 --- unaffected
firefox30 --- fixed
firefox31 --- fixed
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed

People

(Reporter: fabrice, Assigned: jtd)

References

Details

(Keywords: perf, Whiteboard: [c=progress p= s=2014.04.25 u=1.4])

Attachments

(5 files)

gecko logging patch v1: demonstrating time spent in CheckForFeaturesInvolvingSpace()
5.83 KB, patch
Details | Diff | Splinter Review
gaia helloworld app v1 (unzip in gaia/apps)
3.03 KB, application/zip
Details
logging results v1
3.94 KB, text/plain
Details
backtrace of CheckForFeaturesInvolvingSpace call
10.73 KB, text/plain
Details
patch, use the correct prefname
1.00 KB, patch
m_kato
: review+
Details | Diff | Splinter Review
When launching an app with the simplest content, we still experience a pretty long reflow (62ms in this case), that account for about 10% of the launch time. I/Gecko ( 6293): PresShell::DoReflow() 11.80ms interruptible app://system.gaiamobile.org/index.html I/Gecko ( 6293): PresShell::DoReflow() 0.21ms interruptible app://system.gaiamobile.org/index.html I/Gecko ( 6293): PresShell::DoReflow() 9.20ms uninterruptible app://system.gaiamobile.org/index.html I/Gecko ( 6446): PresShell::DoReflow() 0.00ms interruptible about:blank I/Gecko ( 6446): PresShell::DoReflow() 62.35ms uninterruptible app://helloworld.gaiamobile.org/index.html I/Gecko ( 6446): PresShell::DoReflow() 0.22ms uninterruptible app://helloworld.gaiamobile.org/index.html I/Gecko ( 6446): PresShell::DoReflow() 0.29ms uninterruptible app://helloworld.gaiamobile.org/index.html I/Gecko ( 6446): PresShell::DoReflow() 0.49ms interruptible app://helloworld.gaiamobile.org/index.html I/Gecko ( 6446): PresShell::DoReflow() 0.21ms interruptible app://helloworld.gaiamobile.org/index.html I/Gecko ( 6446): PresShell::DoReflow() 0.39ms interruptible app://helloworld.gaiamobile.org/index.html I/Gecko ( 6446): PresShell::DoReflow() 0.20ms interruptible app://helloworld.gaiamobile.org/index.html I/Gecko ( 6293): PresShell::DoReflow() 4.46ms interruptible app://system.gaiamobile.org/index.html helloworld/index.html is: <!DOCTYPE html> <html> <head> <meta name="viewport" content="width=device-width, user-scalable=no, initial-scale=1"> <meta charset="utf-8" /> <title>Videos</title> </head> <body> helloworld </body> </html>
I think there are two things we ought to look into here: (1) what's being this slow, and why? The numbers seem bad just on their own. (2) Are there things we can do to suppress reflow during the loading process of apps? We've tuned XUL documents to avoid doing a bunch of incremental stuff while they're loading (though I've forgotten where the code is, even.) There's also some amount of analogy to paint suppression for Web pages we're in the process of navigating to (PresShell::mPaintingSuppressed and related code). I'm wondering if Daniel would be able to look into both of these issues?
Flags: needinfo?(dholbert)
Sure -- I'll take a look tomorrow morning.
Preliminary results indicate that most of this time is in a single ReflowText() call. Here's the first I see of helloworld, when I add logging to ReflowText (to the patch I got from fabrice, which already has logging in DoReflow): { nsTextFrame::ReflowText() 73.43ms URL: app://helloworld.gaiamobile.org/index.html nsTextFrame::ReflowText() 0.06ms URL: app://helloworld.gaiamobile.org/index.html PresShell::DoReflow() 98.94ms uninterruptible app://helloworld.gaiamobile.org/index.html } This is using an RAII logging class (created in the patch that I got from Fabrice); the logging is displayed when the function returns, so these ReflowText() calls are happening inside of PresShell::DoReflow().
Flags: needinfo?(dholbert)
Component: Layout → Layout: Text
Version: unspecified → Trunk
Do you know if the time was actually spent in reflow, or if we ended up doing something slow and font-related?
I'm betting on the latter (something font-related), but I'm measuring to be sure; will report back soon.
We're spending most of the time in this EnsureTextRun call: > 7811 gfxSkipCharsIterator iter = > 7812 EnsureTextRun(nsTextFrame::eInflated, ctx, > 7813 lineContainer, aLineLayout.GetLine(), &flowEndInTextRun); http://mxr.mozilla.org/mozilla-central/source/layout/generic/nsTextFrame.cpp#7811
How up-to-date is your Gecko - in particular, does it have the patches from bug 921858 (landed a few days ago)? Can you get a profile of this?
(In reply to Jonathan Kew (:jfkthame) from comment #7) > How up-to-date is your Gecko - in particular, does it have the patches from > bug 921858 (landed a few days ago)? Up-to-date as of yesterday. And yes, 'git log' shows patches from that bug in the history. > Can you get a profile of this? I tried [1], but it didn't have enough granularity to be useful, as far as I can tell. Feel free to play around, though. (This contains the app startup (the spiky bits) plus a bit of steady-state buffer on either side.) [1] http://people.mozilla.org/~bgirard/cleopatra/#report=a37e098f97589d18f6fd53a030f6a22854500980
(In reply to Daniel Holbert [:dholbert] from comment #8) > [1] > http://people.mozilla.org/~bgirard/cleopatra/ > #report=a37e098f97589d18f6fd53a030f6a22854500980 If I filter on Reflow, it looks like most of the time in reflow was spent in harfbuzz code. It doesn't have good callstacks, though.
Hmm. Yeah, that doesn't really seem to show much - and the possibly-interesting spots I can find have stacks that look awfully incomplete, like lots of frames are skipped over. One thing I wonder is whether the "whitelist" from bug 921858 that is supposed to make us bypass the OpenType table analysis for Fira is not actually working as intended; that would result in a significant performance hit the first time each font face is used. Can you run this with NSPR_LOG_MODULES=fontinit:5 enabled and collect whatever that reports? That ought to show us if there's an expensive font analysis happening, I believe.
Drilling down a few more layers, all of the time is being spent in this call to aFontGroup->MakeTextRun(), in nsTextFrame.cpp's own "MakeTextRun" method: http://mxr.mozilla.org/mozilla-central/source/layout/generic/nsTextFrame.cpp?rev=79a62689ba10#569 (In reply to Jonathan Kew (:jfkthame) from comment #10) > Can you run this with NSPR_LOG_MODULES=fontinit:5 enabled and collect > whatever that reports? That ought to show us if there's an expensive font > analysis happening, I believe. I'll see; making a debug build to try this. (So far, I've been using an opt build with --disable-debug, which means no prlog IIUC)
(In reply to Daniel Holbert [:dholbert] from comment #11) > I'll see; making a debug build to try this. (So far, I've been using an opt > build with --disable-debug, which means no prlog IIUC) Given https://hg.mozilla.org/mozilla-central/file/c69c55582faa/gfx/thebes/gfxPlatform.cpp#l6 , maybe not, although it might also depend on whether FORCE_PR_LOG is in the files that have the logging statements (ugh).
Summary: Slow reflows at app startup with very simple content → Slow reflows at app startup with very simple content, due to text run creation
I ended up making a debug build, and was able to trigger PR logging, but it only seemed to affect the root process, or something. I followed the instructions at [1], using NSPR_LOG_MODULES=fontinit:5,textrun:5 and I saw logged textruns for the lock screen (numpad strings, "no sim", "emergency calls only") plus some strings from crash reporting, but no textruns would get logged when I launched normal apps. In any case, rather than grappling with prlogging some more, I'm going to try some more targeted function-timing to see what inside of MakeTextRun is slow. [1] https://developer.mozilla.org/en-US/Firefox_OS/Developing_Firefox_OS/Customizing_the_b2g.sh_script
(In reply to Daniel Holbert [:dholbert] from comment #11) > (In reply to Jonathan Kew (:jfkthame) from comment #10) > > Can you run this with NSPR_LOG_MODULES=fontinit:5 enabled and collect > > whatever that reports? That ought to show us if there's an expensive font > > analysis happening, I believe. > > I'll see; making a debug build to try this. (So far, I've been using an opt > build with --disable-debug, which means no prlog IIUC) No, the fontinit:5 logging is force enabled so you can do this with non-debug builds.
OK, so with some more targeted application of a stopwatch RAII class, it looks like we're spending ~70% of our time in a single call to CheckForFeaturesInvolvingSpace(). Here's the patch with the timing/logging code that I'm using.
(And here's the helloword app that fabrice sent me to test with.)
Attached file logging results v1 —
I'm attaching the results of opening the "helloworld" app with the attached logging patch. Here's most interesting chunk: { > 03-25 19:05:48.650 I/Gecko ( 409): Entering PresShell::DoReflow() uninterruptible app://helloworld.gaiamobile.org/index.html > 03-25 19:05:48.650 I/Gecko ( 409): Entering gfxFontGroup::MakeTextRun() > 03-25 19:05:48.660 I/Gecko ( 409): Entering gfxFont::SpaceMayParticipateInShaping() > 03-25 19:05:48.660 I/Gecko ( 409): Entering gfxFont::CheckForFeaturesInvolvingSpace() > 03-25 19:05:48.670 I/Gecko ( 409): In CheckForFeaturesInvolvingSpace() do-while loop 1.86ms > 03-25 19:05:48.670 I/Gecko ( 409): In CheckForFeaturesInvolvingSpace() for loop 2.62ms > 03-25 19:05:48.670 I/Gecko ( 409): In CheckForFeaturesInvolvingSpace() for loop 8.97ms > 03-25 19:05:48.680 I/Gecko ( 409): In CheckForFeaturesInvolvingSpace() for loop 13.82ms > 03-25 19:05:48.690 I/Gecko ( 409): In CheckForFeaturesInvolvingSpace() for loop 27.47ms > 03-25 19:05:48.690 I/Gecko ( 409): After CheckForFeaturesInvolvingSpace() do-while loop 30.27ms > 03-25 19:05:48.720 I/Gecko ( 409): Exiting gfxFont::CheckForFeaturesInvolvingSpace() 58.01ms > 03-25 19:05:48.720 I/Gecko ( 409): Exiting gfxFont::SpaceMayParticipateInShaping() 60.00ms > 03-25 19:05:48.730 I/Gecko ( 409): Exiting gfxFontGroup::MakeTextRun() 70.56ms > 03-25 19:05:48.740 I/Gecko ( 409): Exiting PresShell::DoReflow() 85.91ms uninterruptible app://helloworld.gaiamobile.org/index.html } So, of our 85.91ms initial reflow, we spend 58.01ms in CheckForFeaturesInvolvingSpace. And about half of that 58ms is spent in our 4 iterations through this "for" loop... http://mxr.mozilla.org/mozilla-central/source/gfx/thebes/gfxFont.cpp?rev=652e389a3592&mark=2261-2281#2261 ...and the remaining half is spent after the for loop is done. (Also, interestingly, each iteration through the for loop is a good deal more expensive than the previous. I don't really know what's going on in the loop, but there might be some sort of doubling behavior that's tripping us up... Or maybe this is expected/normal.)
(Here's the backtrace of the CheckForFeaturesInvolvingSpace() invocation that's implicated here.)
It would be interesting to know why https://hg.mozilla.org/mozilla-central/rev/652e389a3592 isn't making us skip this work. Then again, I think at this point it's probably best for jdaggett or jfkthame to pick this up.
Agreed -- looks like we should expect that cset to save us from doing this. Tagging needinfo=jdaggett to see if he can poke at this further, since he's the author of that cset. (Also: as a sanity-check to be absolutely sure I have that patch in my build (and git log isn't fooling me somehow), I verified that my B2G/gecko/gfx/thebes/gfxFT2FontList.cpp file does indeed have the "family->SetSkipSpaceFeatureCheck" line added in 652e389a3592)
Flags: needinfo?(jdaggett)
See Also: → 921858
Summary: Slow reflows at app startup with very simple content, due to text run creation → Slow reflows at app startup with very simple content, largely due to CheckForFeaturesInvolvingSpace() during textrun creation
The more interesting question is why we'd be failing the mSkipSpaceLookupCheckFamilies.Contains(name), assuming we're hitting it at all -- what's |name| there?
I haven't managed to attach a debugger early enough to be sure. (I believe that code is run towards the beginning of the process, IIUC). However, I think I might've identified the problem -- the fonts that get skipped are controlled by the "font.whitelist.skip_space_lookup_check" pref, which is not actually set to anything, as shown by this MXR search: http://mxr.mozilla.org/mozilla-central/search?string=skip_space_lookup_check mozilla-central changeset 652e389a3592 did add a value for a *different* pref -- "font.whitelist.skip_default_features_space_check" (NOTE: "skip_default", not "skip_space") -- but it doesn't set a value for the skip_space version.
(In reply to Daniel Holbert [:dholbert] from comment #22) > I haven't managed to attach a debugger early enough to be sure. (I believe > that code is run towards the beginning of the process, IIUC). > > However, I think I might've identified the problem -- the fonts that get > skipped are controlled by the "font.whitelist.skip_space_lookup_check" pref, > which is not actually set to anything, as shown by this MXR search: > http://mxr.mozilla.org/mozilla-central/search?string=skip_space_lookup_check > > mozilla-central changeset 652e389a3592 did add a value for a *different* > pref -- "font.whitelist.skip_default_features_space_check" (NOTE: > "skip_default", not "skip_space") -- but it doesn't set a value for the > skip_space version. Aw crap, this is my fault. Those two should match obviously. The logging indicates we're spending time analyzing a font. Looking at the prefs I'm guessing this is probably Droid Serif. The fix for bug 921858 added additional logic to check substitution features (the four iterations within CheckForFeaturesInvolvingSpace). The fix also added a bypass for FFOS -- if a font does not have default features that involve space lookups (most fonts) it can be added to a list of font families in a pref to avoid the overhead of the check (unless some form of font feature is enabled).
Flags: needinfo?(jdaggett)
Blocks: 921858
Component: Layout: Text → Graphics: Text
Looks like the pref name just changed in response to a review comment, bug 921858 comment 71, but that change didn't make it back into the code. Aha! Brief testing shows that, after the pref name is made to match, SpaceMayParticipateInShaping() now returns in 0.00ms. That function accounted for most of the time spent in my attached "logging results", which means we end up being much faster. (6.50ms *total* for the first DoReflow now, according to the test I just did -- though there's a small chance that I might've accidentally left in another change that's influencing things here, so it would be worth sanity-checking my results. :) I'll do that tomorrow if no one else has yet.)
Attachment #8396947 - Flags: review?(dholbert)
Attachment #8396947 - Flags: review?(dholbert) → review?(m_kato)
Attachment #8396947 - Flags: review?(m_kato) → review+
Pushed pref name fix to inbound. https://hg.mozilla.org/integration/mozilla-inbound/rev/8fd9d782c948 Marking as leave-open until we can confirm that this alone is the problem.
Keywords: leave-open
Is there any chance to backport that to a gecko28 branch for b2g 1.3t?
On my phone, measuring the initial PresShell::DoReflow() call (with no other logging), with an disable-debug enable-opt b2g build: - Without the pref rename, the initial PresShell::DoReflow() takes ~80ms. - With the pref rename, the initial PresShell::DoReflow() takes ~25ms.
for comment 27 (which presumably means backporting at least some of bug 921858)
Flags: needinfo?(jdaggett)
(In reply to Fabrice Desré [:fabrice] from comment #27) > Is there any chance to backport that to a gecko28 branch for b2g 1.3t? As dbaron mentions, you're really requesting a backporting of bug 921858 so I would request that there. Fabrice, one question I have is whether you see a speedup pre-921858 vs. after the correct prefname fix?
Flags: needinfo?(jdaggett)
(In reply to John Daggett (:jtd) from comment #30) > (In reply to Fabrice Desré [:fabrice] from comment #27) > > Is there any chance to backport that to a gecko28 branch for b2g 1.3t? > > As dbaron mentions, you're really requesting a backporting of bug 921858 so > I would request that there. ok. > Fabrice, one question I have is whether you see a speedup pre-921858 vs. > after the correct prefname fix? 1.3t doesn't have 921858, and I'll check with a master build tomorrow.
Fabrice, could you confirm that this patch fixes the regression that you were seeing? If it does, we should resolve this bug as fixed.
I think this is significant enough that we should uplift to mozilla-aurora for 1.4. I think the patch here just missed the merge by a week or so.
blocking-b2g: --- → 1.4?
Daniel, are we still waiting for more verification on this or can we mark fixed?
Flags: needinfo?(dholbert)
See comment 33; we're waiting on confirmation from fabrice, who reported this.
Flags: needinfo?(dholbert)
Ah, sorry. I thought that was just a question about uplifting to v1.3t. Thanks!
1.4+ - blocks a blocker
blocking-b2g: 1.4? → 1.4+
(In reply to Preeti Raghunath(:Preeti) from comment #38) > 1.4+ - blocks a blocker Preeti, bkelly, this was a regression caused by poor editing in the patch for bug 921858. So I think you really need to evaluate whether that fix is needed or not on bug 921858. Any backport of that would naturally include this fix. *Please* mark that status on that bug, not this one...
John, I thought bug 921858 was in v1.4 already. I see now, though, that I was incorrect.
No longer blocks: 986681
Drop the flag as requested by John. I think we should investigate a bit more before trying to uplift bug 921858. I only requested the uplift here so quickly because I thought it was just a low-risk pref change.
blocking-b2g: 1.4+ → ---
(In reply to John Daggett (:jtd) from comment #33) > Fabrice, could you confirm that this patch fixes the regression that you > were seeing? If it does, we should resolve this bug as fixed. Sorry for the long delay. And yes, that fixed the issue I was seeing.
Status: NEW → RESOLVED
Closed: 11 years ago
Flags: needinfo?(fabrice)
Resolution: --- → FIXED
Keywords: perf
Priority: -- → P2
Whiteboard: [c=progress p= s=2014.04.25 u=]
Assignee: nobody → jdaggett
status-b2g-v2.0: --- → fixed
status-firefox31: --- → fixed
Keywords: leave-open
Target Milestone: --- → mozilla31
This needs to be uplifted as well. Unfortunately the patch uplifted in bug 921858 comment 91 to mozilla-aurora did not include this fix.
blocking-b2g: --- → 1.4?
Preeti, can we get this 1.4+'d again so we can get the pref fixed for bug 921858. Sorry for my mix up here.
Flags: needinfo?(praghunath)
blocking-b2g: 1.4? → 1.4+
Whiteboard: [c=progress p= s=2014.04.25 u=] → [c=progress p= s=2014.04.25 u=1.4]
Flags: needinfo?(praghunath)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: