235022 - Pathologically slow rendering of extremely wide text file

Status: RESOLVED WORKSFORME

(Core :: Layout: Text and Fonts, defect)

Description

[Robert Krawitz]

User-Agent:       
Build Identifier: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.6) Gecko/20040207 Firefox/0.8

The URL above (which refers to a text file of a single line of about 11 MB)
takes pathologically long to display.  This happens with both Mozilla 1.6 and
Firefox 0.8.  It took about 17 minutes of CPU time on a 1 GHz processor to load.
 The file in question is plain ASCII text; it's a data file for a special
purpose renderer (which incidentally is quite fun to watch, but that's
irrelevant here).

It doesn't matter if it's downloaded or loaded from a local file.

Reproducible: Always
Steps to Reproduce:
1. Load the above URL, either as specified or from a local file, either
compressed or not (i. e. downloading the file, gunzip'ing it, and then loading
the file into the browser with a file: URL).
Actual Results:  
The browser appeared to start loading the file normally, including displaying
the start of the file.  I could initially scroll over one page to the right with
the mouse, but after that the browser did not respond at all until the page
completed processing.  The throbber (on Mozilla 1.6) advanced very slowly and
continued to advance while the file was being processed.

The browser did not consume an excessive amount of memory in the process.  At
the completion of processing, it had an address space of 61900 KB, compared to
35804K at start (with no startup page).  Upon starting to load the page, the
address space immediately went up to 51 MB, and then slowly increased its memory
consumption as time progressed.  Most of the additional memory consumption
happened in the first few minutes; the rate of memory growth slowed down over
time.  My system has ample memory (512 MB), and top indicates that it's using
about 95% of the CPU.  strace isn't reporting excessive activity:

brk(0x9705000)                          = 0x9705000
gettimeofday({1077291169, 845463}, NULL) = 0
gettimeofday({1077291169, 848795}, NULL) = 0
gettimeofday({1077291169, 851944}, NULL) = 0
kill(2361, SIGRTMIN)                    = 0
gettimeofday({1077291169, 857925}, NULL) = 0
kill(2362, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
brk(0x9708000)                          = 0x9708000
kill(2362, SIGRTMIN)                    = 0
kill(2362, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
kill(2371, SIGRTMIN)                    = 0
gettimeofday({1077291169, 965478}, NULL) = 0
gettimeofday({1077291169, 968685}, NULL) = 0
gettimeofday({1077291169, 971893}, NULL) = 0
gettimeofday({1077291169, 975042}, NULL) = 0
brk(0x970a000)                          = 0x970a000
gettimeofday({1077291169, 981098}, NULL) = 0
gettimeofday({1077291169, 984207}, NULL) = 0
brk(0x970c000)                          = 0x970c000
gettimeofday({1077291169, 990723}, NULL) = 0
gettimeofday({1077291169, 993856}, NULL) = 0
brk(0x970e000)                          = 0x970e000
gettimeofday({1077291169, 999988}, NULL) = 0
gettimeofday({1077291170, 3116}, NULL)  = 0
brk(0x9710000)                          = 0x9710000
gettimeofday({1077291170, 9598}, NULL)  = 0
gettimeofday({1077291170, 12742}, NULL) = 0
brk(0x9712000)                          = 0x9712000
gettimeofday({1077291170, 19061}, NULL) = 0
gettimeofday({1077291170, 22168}, NULL) = 0
brk(0x9714000)                          = 0x9714000
gettimeofday({1077291170, 28325}, NULL) = 0
gettimeofday({1077291170, 31732}, NULL) = 0
brk(0x9716000)                          = 0x9716000
gettimeofday({1077291170, 38021}, NULL) = 0
gettimeofday({1077291170, 40740}, NULL) = 0
gettimeofday({1077291170, 43846}, NULL) = 0
kill(2361, SIGRTMIN)                    = 0
gettimeofday({1077291170, 50095}, NULL) = 0
gettimeofday({1077291170, 53387}, NULL) = 0
gettimeofday({1077291170, 56556}, NULL) = 0
kill(2361, SIGRTMIN)                    = 0
write(6, "\372", 1)                     = 1
write(3, "5\30\4\0\275\4@\2@\0\0\0\"\0\"\0Fe\5\0\275\4@\2M\1@\2\0"..., 452) = 452
read(3, "\1\0016\233\0\0\0\0\16\0\240\2\0\0\0\0\0\0\0\0\0\0\0\0"..., 32) = 32
write(3, "F\30\5\0\275\4@\2v\0@\2\377\377\377\377\"\0\"\0>\4\7\0"..., 516) = 516
read(3, "\1\1P\233\0\0\0\0\16\0\240\2\0\0\0\0\0\0\0\0\0\0\0\0x+"..., 32) = 32
write(3, ";\0\5\0\t\0@\2\0\0\0\0\2\0\2\0\v\0\v\0;\0\5\0\7\0@\2\0"..., 376) = 376
read(3, "\1\1d\233\0\0\0\0\16\0\240\2\0\0\0\0\0\0\0\0\0\0\0\0x+"..., 32) = 32
write(3, ";\0\5\0\t\0@\2\0\0\0\0\224\3\2\0\v\0\v\0;\0\5\0\7\0@\2"..., 360) = 360
read(3, "\1\1x\233\0\0\0\0\16\0\240\2\0\0\0\0\0\0\0\0\0\0\0\0x+"..., 32) = 32
write(3, ";\0\5\0\10\0@\2\0\0\0\0\r\0\2\0\7\0\v\0008\0\4\0\10\0@"..., 380) = 380
read(3, "\1\1\214\233\0\0\0\0\16\0\240\2\0\0\0\0\0\0\0\0\0\0\0\0"..., 32) = 32
brk(0x971b000)                          = 0x971b000
write(3, ">\0\7\0\276\4@\2\371\3@\2\10\4@\2\0\0\0\0\0\0\266\2\242"..., 88) = 88
write(3, "\376\000062a 853 853 -1 -1 1 1 1 1 Z25"..., 2048) = 2048
write(3, "\376\000220 76 12 220 76 12 220 80 12 "..., 2048) = 2048
gettimeofday({1077291170, 113256}, NULL) = 0
write(3, " \0BnnBrrBqBhlBiBieBnnBrrBqqBlBih"..., 72) = 72
ioctl(3, FIONREAD, [0])                 = 0

(the last write() appears to be writing data from the file).  There are a few
other mozilla threads, but none of them accumulate as much as 1 second of CPU time.

I repeated this with a completely fresh browser, with the same results except
that it took 9:25 of CPU time rather than about 17 minutes.  The two differences
were that in the first session I first tried to load a bogus URL, and then typed
in the file:/// url directly, and attempted to scroll the file while it was
being processed.  The second time I used the Open File box (C-o) to open the
file, and did not attempt to do anything to the browser while processing was
taking place.  The end memory consumption was the same.

Expected Results:  
Render the page in a reasonable amount of time.

No obvious reason to believe this is configuration related, but I will be happy
to supply prefs.js upon request.

Comment 1

[Ian Graham]

There is no file at the referened URL:
http://http://wso.williams.edu/~bchaffin/patersons_worms/worm_draw/hash061-2.3e18-draw.gz

Comment 2

[Marco Perez [:mpk]]

Stripped duplicate leading "http://" from test URL so it should work correctly.
Experienced the same symptoms on Firefox (Build from 20040219), so setting OS to
"all".

Comment 3

[Marco Perez [:mpk]]

Forgot to mention that it's Firefox on Win2K, thus the OS change to "all". Sorry
for the spam.

Comment 4

[Robert Krawitz]

BTW, this file is not on my server so please don't hit it too hard.  I tried to
attach it but bugzilla doesn't allow such a big attachment.

Comment 5

[Max Alekseyev]

*** This bug has been marked as a duplicate of 72885 ***

Comment 6

[Boris Zbarsky [:bzbarsky]]

Max, please do not EVER mark a bug like this duplicate without actually checking
whether it is (via a profile).  If you can't do a profile, mark the bug qawanted
and cc some people who can.  This bug is nothing like bug 72885, and it would
have gotten totally lost if I hadn't happened to glance at the bugs filed two
days ago....

Comment 7

[Boris Zbarsky [:bzbarsky]]

So, here's what a profile shows:

1)  Of 20137 total hits, 19948 are under nsTextFrame::MeasureText (all called
    from nsTextFrame::Reflow)
2)  These are divided as follows:

   19948 nsTextFrame::MeasureText
     11005 nsTextFrame::ComputeTotalWordDimensions
      8539 nsRenderingContextGTK::GetTextDimensions
       395 nsTextTransformer::GetNextWord

As Robert points out in bug 72885 comment 15 and bug 72885 comment, we have
O(N^2) growth here.

To be precise, the way we append text is using nsIDOMCharacterData::AppendData
which _always_notifies_.  So every time we append a chunk of text, if we're not
creating a new textnode we actually notify and reflow the whole document.  This
could be part of what causes problems in bug, of course.  In any case, since
reflow of a long string of text means measuring it, which is O(N) in string
length, we end up with O(N^2) layout time overall.

So there are a few things we should look into doing here:

1)  Use an API that does _not_ notify when we append text in the content sink,
    and batch those notifications like we would any others.
2)  Have nsTextFrame cache the measured text width and just use it if some flag
    is set.  The flag would be cleared by getting a new style context, by
    getting a new next-in-flow, maybe (linebreaking changed), by getting the
    "textnode data changed" notification.  Any other cases?  Would this be
    feasible?

Comment 8

[Boris Zbarsky [:bzbarsky]]

Attachment: Full profile

Comment 9

[Boris Zbarsky [:bzbarsky]]

Actually, nsTextFrame already has a check like what I describe...  Also, even if
I force the content sink to not notify and the measureText boolean to true in
the textframe, things are _still_ slow, though orders of magnitude faster.  In
that case, nsRenderingContextGTK::GetTextDimensions is gone but the other two
callees of MeasureText are still alive and kicking.... Why are they being
called, exactly?  It looks like we're trying to line-break this text (!!!! it's
not breakable to start with!), which shouldn't have to be repeated if nothing
changed since last reflow, imo...

So we seem to have three issues:

1)  We need to notify less
2)  We should make sure we don't measure any more than we need to
3)  Even when not measuring, we still have O(N^2) behavior because MeasureText
    still putters about with word fragments.

jst, sicking, should I spin off #1 into a separate DOM bug?  The other two
issues should be dealt with together....

Comment 10

[Jonas Sicking (:sicking) No longer reading bugmail consistently]

Yeah, please do spin off another bug for notifying less. I ran into this
notification not long ago and thought it looked unneccesary but didn't think
much of it since i figured it wouldn't happen very often. Didn't think of 11MB
textdocuments though :)

Comment 11

[Boris Zbarsky [:bzbarsky]]

Bug 235255 filed.

Comment 12

[Max Alekseyev]

Sorry for unappropriate dupping. 
But I've got confused. Why did this bug get so much special attention while
whole bunch of similar/related bugs like bug 52005, bug 72885, bug 155440, bug
210946, bug 212358 etc. was abandoned?

Comment 13

[Boris Zbarsky [:bzbarsky]]

I don't read mailnews bugs.  Of the browser bugs you mention, I've profiled most
of them and didn't see anything obviously going wrong past "this is a really big
page with lots of stuff in it".  With the testcase here there _is_ something
obviously wrong if you look at the profile.  That's the difference.  If I see
something fixable, I can try to fix it.  If I don't, then I can't.

Comment 14

[Boris Zbarsky [:bzbarsky]]

ccing roc in case he has ideas on the text-measurement issues here....

Comment 15

[Boris Zbarsky [:bzbarsky]]

Hmm...  So the testcase seems to be gone.  Is it still available somewhere?

Comment 16

[Robert Krawitz]

I spotted that last comment (a year later!) while searching my open bugs.

I've placed a (bzip2'd copy) in ftp://66.92.65.9/pub/hash061-2.3e18-draw.bz2.  Please download it, since it's on a 1500/600 DSL pipe.

Comment 17

[Wayne Mery (:wsmwk)]

bz, did you get ftp://66.92.65.9/pub/hash061-2.3e18-draw.bz2 ?
it's too big to attach to the bug

Comment 18

[Boris Zbarsky [:bzbarsky]]

Hmm.  I seem to have missed comment 16.  Looking.

Comment 19

[Boris Zbarsky [:bzbarsky]]

OK, I put a copy of that file at http://web.mit.edu/bzbarsky/www/testcases/bugs/235022/hash061-2.3e18-draw.bz2

Now to profile it.

Comment 20

[Boris Zbarsky [:bzbarsky]]

OK.  So as expected, 52% textrun construction, 23% BreakAndMeasureText, a bunch of kernel time in memory traffic (vm_fault and such).

Comment 21

[Wayne Mery (:wsmwk)]

>  http://web.mit.edu/bzbarsky/www/testcases/bugs/235022/hash061-2.3e18-draw.bz2

current nightly build with e10s enabled, windows 7, quad core, < 5 seconds

Does anyone still see a problem?

Comment 22

[Wayne Mery (:wsmwk)]

Andre can you reproduce testcase in comment 19?  If not, please close WFM as confirmation of my comment 21

Comment 23

[Gregory Pappas [:gregp]]

Attachment: testcase.zip

Comment 24

[Gregory Pappas [:gregp]]

(I attached the testcase directly to the bug just in case mit.edu goes down in the future)

Do you think it's safe to close this now?

Comment 25

[Jonathan Kew [:jfkthame]]

I think so; performance in a current version seems reasonable for the scale of the testcase here. It'd be best to have new bugs for any specific cases that still perform particularly badly.