Closed Bug 1074809 Opened 5 years ago Closed 5 years ago

Tumblr blog pages causing Fx to hang for several seconds

Categories

(Core :: Graphics: Text, defect)

x86
All
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla35
Tracking Status
firefox33 --- unaffected
firefox34 + fixed
firefox35 + fixed

People

(Reporter: fvsch, Assigned: jfkthame)

References

Details

(Keywords: regression)

Attachments

(4 files)

This might be just me but on Firefox 33, 34, 35 (Nightly), and 2 different profiles (one busy, the other one almost blank), all *.tumblr.com pages cause Firefox to hang for one to a few seconds.

When loading e.g. http://bohemiancoding.tumblr.com/post/98721054305/sketch-3-1

1. Page interaction is blocked.
2. Page interaction in other tabs is blocked.
3. Firefox UI is blocked (can show a beachball if it hangs for more than 2-3 seconds).

I can see this on all tumblr blogs (with URLS in something.tumblr.com or with custom domains) on first page loads. A refresh a few seconds later is not affected.
Tested in Firefox 33, 34 et 35. In Nightly, Electrolysis doesn’t seem to help.

On the same machine:
- Chrome 37 is not affected.
- Safari 7 is not affected.

(I’m on an averagely powered machine: macbook air 2011, 4GB ram, CPU not that fast but often fast enough.)

Now for the problem’s source itself: Tumblr adds a lot of front-end code to Tumblr blogs, even if the blog theme itself is minimal. It calls many resources from several domains, including a 211 KB stylesheet and a 1060 KB script.

Still, this load does not cripple other browsers in the same way it cripples Firefox, so maybe there’s something specific to Firefox going on, that should be investigated by Mozilla folks.
I do not see a delay on my main system on windows but I can see a 1-2s beachball on my late 2009 mac mini.
The time is to short to do a good regression range search on my OSX system that i access via vnc :-(

Florent: 
Could you find the first bad and the last good build with our mozregression tool ?
- http://mozilla.github.io/mozregression/
Flags: needinfo?(florent)
I'm able to reproduce it on Win 7.

Regression range:
good=2014-08-25
bad=2014-08-26
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=daa84204a11a&tochange=dc352a7bf234

Maybe: Steve Workman — Bug 1054572
Status: UNCONFIRMED → NEW
Component: Untriaged → Networking: Cache
Ever confirmed: true
Keywords: regression
Product: Firefox → Core
[Tracking Requested - why for this release]:
Regression window(m-i)
Good:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fe85fa066bf2
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:34.0) Gecko/20100101 Firefox/34.0 ID:20140825064648
Bad:
https://hg.mozilla.org/integration/mozilla-inbound/rev/822c7f854920
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:34.0) Gecko/20100101 Firefox/34.0 ID:20140825065747
Pushlog:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=fe85fa066bf2&tochange=822c7f854920

Suspect: Bug 1057488
Blocks: 1057488
Component: Networking: Cache → Graphics: Text
OS: Mac OS X → All
The following 2 error shown in browser console


downloadable font: metrics: bad sb: 0 < 124 (font-family: "Blank" style:normal weight:normal stretch:normal src index:0)
source: data:font/opentype;base64,T1RUTwAKAIAAAwAgQ0ZGIM6ZbkwAAEPoAAAZM0RTSUcAAAABAABtJAAAAAhPUy8yAR6vMwAAARAAAABgY21hcDqI98oAACjoAAAa4GhlYWQAVAYrAAAArAAAADZoaGVhCCID7wAAAOQAAAAkaG10eAPoAHwAAF0cAAAQBm1heHAIAVAAAAABCAAAAAZuYW1lEb5dKwAAAXAAACd4cG9zdP+4ADIAAEPIAAAAIAABAAAAAQj1QlgfWV8PPPUAAwPoAAAAAM6qXK8AAAAAzqpcrwB8/4gDbANwAAAAAwACAAAAAAAAAAEAAANw/4gAyAPoAHwAfANsAAEAAAAAAAAAAAAAAAAAAAACAABQAAgBAAAABAAAAZAABQAAAooCWAAAAEsCigJYAAABXgAyANwAAAAAAAAAAAAAAAD3/67/+9///w/gAD8AAAAAQURCRQHAAAD//wNw/4gAyANwAHhgLwH/AAAAAAAAAAAAAAAgAAAAAAARANIAAQAAAAAAAQALAAAAAQAAAAAAAgAHAAsAAQAAAAAAAwAbABIAAQAAAAAABAALAAAAAQAAAAAABQA5AC0AAQAAAAAABgAKAGYAAwABBAkAAABuAHAAAwABBAkAAQAWAN4AAwABBAkAAgAOAPQAAwABBAkAAwA2AQIAAwABBAkABAAmATgAAwABBAkABQByAV4AAwABBAkABgAUAdAAAwABBAkACAA0AeQAAwABBAkACwA0AhgAAwABBAkADSQSAkwAAwABBAkADgBIJl5BZG9iZSBCbGFua1JlZ3VsYXIxLjAzNTtBREJFO0Fkb2JlQmxhbms7QURPQkVWZXJzaW9uIDEuM


downloadable font: metrics: bad lsb: 0 < 124 (font-family: "Blank" style:normal weight:normal stretch:normal src index:0)
source: data:font/opentype;base64,T1RUTwAKAIAAAwAgQ0ZGIM6ZbkwAAEPoAAAZM0RTSUcAAAABAABtJAAAAAhPUy8yAR6vMwAAARAAAABgY21hcDqI98oAACjoAAAa4GhlYWQAVAYrAAAArAAAADZoaGVhCCID7wAAAOQAAAAkaG10eAPoAHwAAF0cAAAQBm1heHAIAVAAAAABCAAAAAZuYW1lEb5dKwAAAXAAACd4cG9zdP+4ADIAAEPIAAAAIAABAAAAAQj1QlgfWV8PPPUAAwPoAAAAAM6qXK8AAAAAzqpcrwB8/4gDbANwAAAAAwACAAAAAAAAAAEAAANw/4gAyAPoAHwAfANsAAEAAAAAAAAAAAAAAAAAAAACAABQAAgBAAAABAAAAZAABQAAAooCWAAAAEsCigJYAAABXgAyANwAAAAAAAAAAAAAAAD3/67/+9///w/gAD8AAAAAQURCRQHAAAD//wNw/4gAyANwAHhgLwH/AAAAAAAAAAAAAAAgAAAAAAARANIAAQAAAAAAAQALAAAAAQAAAAAAAgAHAAsAAQAAAAAAAwAbABIAAQAAAAAABAALAAAAAQAAAAAABQA5AC0AAQAAAAAABgAKAGYAAwABBAkAAABuAHAAAwABBAkAAQAWAN4AAwABBAkAAgAOAPQAAwABBAkAAwA2AQIAAwABBAkABAAmATgAAwABBAkABQByAV4AAwABBAkABgAUAdAAAwABBAkACAA0AeQAAwABBAkACwA0AhgAAwABBAkADSQSAkwAAwABBAkADgBIJl5BZG9iZSBCbGFua1JlZ3VsYXIxLjAzNTtBREJFO0Fkb2JlQmxhbms7QURPQkVWZXJzaW9uIDEu
Bug 1057488 seems unlikely to me. (Those browser console warnings should be benign; OTS is fixing up a minor inconsistency in the font data, but that shouldn't cause significant delay.)

I'm guessing bug 1048579 is much more likely to have affected the network loading behavior. From attachment 8497461 [details] it looks like we might be blocking on the two (eventually-failing) loads from sb.scorecardresearch.com; could this be a result of the content-sniffing behavior change in bug 1048579?
In local build
Last Good: 96312bdb2fb4
First Bad: 2bf8a805206e

Triggered by
	2bf8a805206e	Frédéric Wang — Bug 1057488 - Part 4: Update OTS to 5c25bdac8f02080f49fa416ea997ed77e3be0d30. r=jfkthame
Huh, that's unexpected. OK, we'd better look more closely at exactly what changed in OTS there...
So the Good/Bad build profiles have no useful symbols.

But the Nightly profile is very interesting  It shows 32% of the overall spent under reflow, and almost all of that (30.3%) under gfxUserFontEntry::SanitizeOpenTypeData.  The vast majority of _that_ (29.4%) is under nsUserFontSet::LogMessage, and a large chunk of that is under nsCSSFontFaceRule::GetCssText (the rest us getting URI specs, converting UTF-8 to UTF-16, etc).  The GetCssText is mostly under nsStyleUtil::AppendSerializedFontSrc, CSS-escaping the huge string.

But worse yet, the time spent above is all contiguous, and in particular we spend 3 seconds of wall-clock time under that SanitizeOpenTypeData call(!).

One reason for that is that we're actually logging the second error mentioned in comment 5 multiple times.  The exact number of times is different every time I reload the page.  I've seen it logged 224 times, 254 times, 96 times (and the first error was not logged at all that time!), 245 times, 231 times.

Even taking 10-15ms to log the error seems pretty excessive, but if we then do it several hundred times we get the observed multi-second hang.
Flags: needinfo?(florent)
Oh, and the worst part is that the GetCssText call is only done to provide the "source line" to the script error.  But as far as I can tell our web console doesn't ever show the source line (why not?), so it's pretty much ending up as wasted work...
FWIW, the base64 fontdata in question is a ~600 byte "blank" font.  Looks like it's stripped down from Adobe Blank, perhaps by bruteforce deleting bytes while it works...  It's seriously damaged AFAIS.  I can't get a dump of it from TTX easily.
I might be wrong.  Still trying to find where in the page the blank font is coming from.
(In reply to Boris Zbarsky [:bz] from comment #11)
> Oh, and the worst part is that the GetCssText call is only done to provide
> the "source line" to the script error.  But as far as I can tell our web
> console doesn't ever show the source line (why not?), so it's pretty much
> ending up as wasted work...

That's sad. I thought I'd seen the source line in messages in the past; perhaps this changed?

So it turns out the hang *is* related to those warning messages, despite what I said in comment 6. It's not the OTS error detection and fixup that's the problem; it's our message-logging code.

The reason it regressed in 2bf8a805206e, I think, is that in earlier versions, such "warning" messages (as opposed to errors that cause the font to be rejected) were not being logged via our message callback.
Ok I've got the full font now.  It's a 2049-glyph version of Adobe Blank.  All glyphs except for the first one are just blank.  So, whatever per-glyph warning we hit we should hit for 2048 glyphs.  If I run ot-sanitize on the font indeed I get 2048 of the "bad lsb: 0 < 124" warning.  The warning looks wrong to me however.  I believe it's a bug in OTS...

A few things that need to be done:

  - Fix OTS warning,

  - Add warning throttling either in OTS or Firefox.  Perhaps we can add a max-warnings setting to OTContext, after which OTS should give up on the font?  Or just give up reporting?

  - Make warning code on Firefox side faster.
OTS issue reported (with culprit) here: https://github.com/khaledhosny/ots/issues/36
> perhaps this changed?

Not sure; talking to the devtools folks about it.

That said, I think the right thing to do there is to pass rule->GetLineNumber() as the line number instead of 0.  And the correct stylesheet URI.  Then you get a link in the web console, and assuming devtools ever gets unbroken such that following that link actually _works_, things would be nice....

Any idea why the number of warnings varies so widely here?
I filed bug 1075617 on getting the right line/column/url here.
Assignee: nobody → jfkthame
Status: NEW → ASSIGNED
Note that this patch depends on the OTS update in bug 1074223.
Depends on: 1074223
(In reply to Jonathan Kew (:jfkthame) from comment #14)

> So it turns out the hang *is* related to those warning messages, despite
> what I said in comment 6. It's not the OTS error detection and fixup that's
> the problem; it's our message-logging code.
> 
> The reason it regressed in 2bf8a805206e, I think, is that in earlier
> versions, such "warning" messages (as opposed to errors that cause the font
> to be rejected) were not being logged via our message callback.

Why is this the cause of a beachball? Are we calling this repeatedly? One call to GetCssText per font for such a small font does not seem like it could cause this. Is there some cycle here that somehow is causing to code to call LogMessage repeatedly for the same font?
> Why is this the cause of a beachball? Are we calling this repeatedly?

Yes.  See comment 10, next to last paragraph.  Still not clear to me why the number of calls varies.
(In reply to Boris Zbarsky [:bz] from comment #22)
> > Why is this the cause of a beachball? Are we calling this repeatedly?
> 
> Yes.  See comment 10, next to last paragraph.  Still not clear to me why the
> number of calls varies.

My (untested) guess is that the devtools console may be dropping messages when they arrive too rapidly, or something like that. For that font, OTS should have been logging a constant number of warnings (one per glyph, total 2048; see comment 15), but apparently some of them are getting lost.

It might be worth investigating that to see what's really happening, but it's somewhat separate from the fact that logging this level of OTS warning is probably not all that helpful (and was consciously omitted when we first started logging OTS errors; only a recent change within OTS made them start getting reported here). OTS uses "warning" for minor discrepancies that it automatically fixes up (aside from the fact that this particular case was a bogus warning, but that's a separate issue, fixed upstream). For web dev purposes, only messages that relate to an actual failure are really of interest.
Comment on attachment 8501940 [details] [diff] [review]
Only log OTS failure messages that cause the font to be discarded, not minor warnings.


*sigh* r+ 

I'd like to see a simple, single warning per font when OTS sees something it doesn't like. But given that this is a slowdown now, let's get this fixed and try and improve it later.

(In reply to Behdad Esfahbod from comment #15)
> Ok I've got the full font now.  It's a 2049-glyph version of Adobe Blank. 
> All glyphs except for the first one are just blank.  So, whatever per-glyph
> warning we hit we should hit for 2048 glyphs.  If I run ot-sanitize on the
> font indeed I get 2048 of the "bad lsb: 0 < 124" warning.  The warning looks
> wrong to me however.  I believe it's a bug in OTS...

Per problem warnings are *way* too fine-grained to be useful. 

(In reply to Jonathan Kew (:jfkthame) from comment #23)

> OTS uses "warning" for minor discrepancies that it automatically
> fixes up (aside from the fact that this particular case was a
> bogus warning, but that's a separate issue, fixed upstream). For
> web dev purposes, only messages that relate to an actual failure
> are really of interest.

I actually disagree here, I think it's useful for webdevs to understand that OTS was issuing warnings about a font. But I think there only needs to be a *single* warning per font, hopefully one that lists the tables that needed fixing. Firefox could implement a handler for this within gfxOTSContext but OTS would need to be changed to pick up the table info, since all the code within the Message() method sees is a format string and a list of parameters.
Attachment #8501940 - Flags: review?(jdaggett) → review+
(In reply to John Daggett (:jtd) from comment #24)
> Comment on attachment 8501940 [details] [diff] [review]
> Only log OTS failure messages that cause the font to be discarded, not minor
> warnings.
> 
> 
> *sigh* r+ 
> 
> I'd like to see a simple, single warning per font when OTS sees something it
> doesn't like. But given that this is a slowdown now, let's get this fixed
> and try and improve it later.
> 
> (In reply to Behdad Esfahbod from comment #15)
> > Ok I've got the full font now.  It's a 2049-glyph version of Adobe Blank. 
> > All glyphs except for the first one are just blank.  So, whatever per-glyph
> > warning we hit we should hit for 2048 glyphs.  If I run ot-sanitize on the
> > font indeed I get 2048 of the "bad lsb: 0 < 124" warning.  The warning looks
> > wrong to me however.  I believe it's a bug in OTS...
> 
> Per problem warnings are *way* too fine-grained to be useful. 
> 
> (In reply to Jonathan Kew (:jfkthame) from comment #23)
> 
> > OTS uses "warning" for minor discrepancies that it automatically
> > fixes up (aside from the fact that this particular case was a
> > bogus warning, but that's a separate issue, fixed upstream). For
> > web dev purposes, only messages that relate to an actual failure
> > are really of interest.
> 
> I actually disagree here, I think it's useful for webdevs to understand that
> OTS was issuing warnings about a font. But I think there only needs to be a
> *single* warning per font, hopefully one that lists the tables that needed
> fixing. Firefox could implement a handler for this within gfxOTSContext but
> OTS would need to be changed to pick up the table info, since all the code
> within the Message() method sees is a format string and a list of parameters.

Designers don't care about warnings as long as the font works.
Font designers don't care about warnings as long as the font works.
(In reply to Behdad Esfahbod from comment #25)

> Designers don't care about warnings as long as the font works.
> Font designers don't care about warnings as long as the font works.

Um, that's a pretty broad, blanket assertion. Since there's a lot of font tweaking that goes on with webfonts, it's very common for web designers to end up with a copy of a font that's not quite right. The warning is a clue that if things with that font aren't working quite right they should double check the source of that font. It's also a clue that OTS is spending time cleaning up a font and web designers *do* care about time wasted due to error handling.
This bug notwithstanding, warnings don't make anything slower.  They are warnings afterall, they don't block the use of the font.  And webfont preparations don't really affect the parts of fonts that cause warnings.

I'm not going to continue this discussion though, all has been said.
OK, here's a followup that implements a simple filtering behavior: for warning messages, only the first instance of any given (unique) message will be logged to the console. This should eliminate most likely forms of console spamming where every glyph in a font generates the same warning, for example. It'd still be possible to spam the console by carefully constructing a font where every glyph generates a *different* warning, but that's getting pretty far-fetched ... and is no worse, IMO, than all sorts of other (easier) ways to bring the browser to a crawl using deliberately-crafted content such as infinitely-growing JS strings.
Attachment #8503072 - Flags: review?(jdaggett)
Attachment #8503072 - Flags: review?(jdaggett) → review+
Pushed (patch 2):
https://hg.mozilla.org/integration/mozilla-inbound/rev/0402daa909e4
Target Milestone: --- → mozilla35
Comment on attachment 8503072 [details] [diff] [review]
patch 2 - For OTS warning (rather than failure) messages, only log the first occurrence of any given message per font.

Approval Request Comment
[Feature/regressing bug #]:
The OTS update in bug 1057488 led to an unplanned change in warning-logging behavior that can result in spamming the developer console with messages.

[User impact if declined]:
The (additional) OTS update in bug 1074223, also nominated for uplift, will fix the specific problem case in this report, because it removes the (bogus) warning that was being generated. However, the more general problem remains, that a font which generates a very large number of warnings can temporarily hang the browser. This patch addresses that broader issue.

[Describe test coverage new/current, TBPL]:
Existing webfont tests exercise this code.

[Risks and why]:
Minimal, just adds a filter to ensure we don't spam the console with numerous instances of a warning.

[String/UUID change made/needed]:
none
Attachment #8503072 - Flags: approval-mozilla-aurora?
https://hg.mozilla.org/mozilla-central/rev/0402daa909e4
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Comment on attachment 8503072 [details] [diff] [review]
patch 2 - For OTS warning (rather than failure) messages, only log the first occurrence of any given message per font.

Moving pending approval request from aurora to beta, as merge has happened in the meantime.
Attachment #8503072 - Flags: approval-mozilla-aurora? → approval-mozilla-beta?
Comment on attachment 8503072 [details] [diff] [review]
patch 2 - For OTS warning (rather than failure) messages, only log the first occurrence of any given message per font.

Beta+
Attachment #8503072 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Needs rebasing for beta uplift.
Flags: needinfo?(jfkthame)
Attachment #8506813 - Attachment description: For OTS warning (rather than failure) messages, only log the first occurrence of any given message per font. → [mozilla-beta patch] For OTS warning (rather than failure) messages, only log the first occurrence of any given message per font.
Flags: needinfo?(jfkthame)
Attachment #8506813 - Flags: checkin?
Attachment #8506813 - Flags: checkin? → checkin+
You need to log in before you can comment on or make changes to this bug.