75001 - Too many calls to PR_Now in HTMLContentSink::IsTimeToNotify

Status: RESOLVED WORKSFORME

(Core :: DOM: HTML Parser, defect)

Description

[Daniel Bratell]

When looking at quantify outputs, one thing I noticed with the jdk index page at 
http://www.javasoft.com/j2se/1.3/docs/api/index-files/index-7.html is the cost 
of HTMLContentSink::IsTimeToNotify. Just that function (which should not be 
visible at all) has 2.5% of the total time.

The reason for this is that it's called 64000 times, causing 64000 calls to 
PR_Now which is a function that costs a little. Another slow page, the colour 
table stresscase gets 60000 calls to IsTimeToNotify, but that only results in 
412 calls to PR_Now making it much cheaper. It should be the same for the JDK 
index.

Calling PR_Now 64000 times is like calling it once every ms, which is a little 
ridiculous.

Comment 1

[Daniel Bratell]

More info: HTMLContentSink::IsTimeToNotify is called from DidAddContent which is 
called from FlushText (33000 times) and CloseContainer (31000 times). I would 
reckon that maybe it's not necessary to call it if the diff since last time is 
very small, like a closed <a> or a short added text.

Alternatively, maybe we should make PR_Now faster. All it does now is to call 
ftime. Maybe that's not necessary.

Comment 2

[Daniel Bratell]

If we need to do so many checks for the time we should (on Windows) use
timeGetTime instead of ftime. timeGetTime is 3-4 times as fast and gives the
necessary information since we only want to now how long time has passed since
last notify.

I just checked NSPR and it seems as if the function PRIntervalTime() is using
timeGetTime sometimes. It could be worth a test to switch to that.

Comment 3

[Daniel Bratell]

No, PRIntervalTime is no good choice. It uses QueryPerrfomanceCounter normally
and only timeGetTime as a fallback. Why QueryPerfomanceCounter is bad can be
seen from this table:

Function                       Time in us
==========================================
timeGetTime                        209
ftime                              809
QueryPerfomanceCounter            4205

So, either we need a new function in NSPR or reduce the number of calls if we
want to make this better.

Comment 4

[Pierre Saslawsky]

HTMLContentSink::IsTimeToNotify => reassigned to Parser/harishd (but maybe it 
should go to Nisheeth)

Comment 5

[Daniel Bratell]

(Just a reminder to self: Another possible time function on win32 is 
GetSystemTimeAsFileTime which returns time in 100 ns chunks. It is the function 
used by ftime)

Comment 6

[harishd]

Nisheeth, could you please take a look at this. Thanx.

Comment 7

[Heikki Toivonen (remove -bugzilla when emailing directly)]

Daniel, I am reassigning this to you. You seem to be able to figure out what is
the best fix. If you need help in actual fix or checkin, let me know.

Comment 8

[Markus Hübner]

Any news on that one?

Comment 9

[Daniel Bratell]

The problem is still there. HTMLContentSink::IsTimeToNotify calls PR_Now 63576 
times on the test page for a total of 3% of the layout time.

According to the NSPR docs, the right thing to do would be to use PR_IntervalNow 
but that function is even slower (bug 124695). Another idea would be to use some 
timer that sets some signal flag when fired and just look at that flag. That 
would probably be better than polling the clock.

Hmm. HTMLContentSink::DidProcessAToken has also started (mis)using time calls 
(bug 124697) for a total of 5% of the page load time.

Comment 10

[Jerry]

Daniel, in your comment #2, you said timeGetTime is much faster than ftime.
why not modify ntmisc.c, change PR_Time's implementation from ftime to 
timeGetTime(), does it make sense?


http://lxr.mozilla.org/mozilla/source/nsprpub/pr/src/md/windows/ntmisc.c#85

Comment 11

[Daniel Bratell]

I don't have access to all the necessary docs right now, but as I recall it 
timeGetTime has the necessary precision for the parser, but the parser uses 
PR_Now which, by the NSPR documentation, should have a minimum precision that 
timeGetTime can't get.

I think we would need another NSPR function |PR_Approximately_Now| that would 
be enough for this and other uses where we don't need millisecond precision.

Comment 12

[Jerry]

when I check the source code,I think I get it.

int nsresult SinkContext::CloseContainer() function, 
it will call FlushTextAndRelease() ,
FlushTextAndRelease() will call FlushText(),
FlushText() will do something like create content object, then call 
SinkContext::DidAddContent().

after FlushTextAndRelease(), CloseContainer() will call DidAddContent() again.
that is why mozilla will call PR_Now() so many times.

So I think we should remove one DidAddContent().

Comment 13

[Jerry]

Attachment: patch (remove addition DidAddContent)

Comment 14

[Jerry]

add jkeiser to cc list
Hope he can take an look.

Comment 15

[John Keiser (jkeiser)]

DidAddContent() needs to be called for more than one piece of content in the
case you're talking about.  Once for the text node and once for the container
that's being closed.

As for fixing the problem, it seems to me that IsTimeToNotify() logic is just
simulating a timer (badly).  Why not just make it one?

Comment 16

[Jerry]

jkeiser is right,DidAddContent is called twice in CloseContainer(), 
one is for text content, another is for container.
so mark my patch as obsolete.

Comment 17

[John Keiser (jkeiser)]

Some more info: the only reason IsTimeToNotify is called is to flush.  The flush
can safely be placed on a timer.  Just look at the only place it is called, you
can see all it does is FlushTags().

Comment 18

[Daniel Bratell]

John, do you want this bug? Looks like you've already started on it. Feel free
to grab it in that case.

Comment 19

[Markus Hübner]

Any further findings in the meantime?

Comment 20

[Boris Zbarsky [:bzbarsky]]

A timer may not work because to fire a timer you have to go out to the event
loop.. which means you need to interrupt parsing.

Then again, you need to do that to paint too.  So perhaps there will be no
perceptible change....

Comment 21

[Henri Sivonen (:hsivonen)]

We could fix this by migrating the XML side to use nsHtml5TreeOpExecutor, too.

Comment 22

[Josh Matthews [:jdm]]

I wonder if TimeStamp::NowLoRes might be an acceptable compromise?

Comment 23

[BugBot [:suhaib / :marco]]

The bug assignee didn't login in Bugzilla in the last 7 months, so the assignee is being reset.

Comment 24

[Mayank Bansal]

The URL Loads fast enough.