978583 - Expanding tree of history is too slow in Library and Sidebar

Status: RESOLVED WORKSFORME

(Core :: General, defect)

Description

[Alice0775 White]

Attachment: sample places.sqlite

Steps To Reproduce:
1. Make sure a lot of history (attachment if necessary)
2. Open Library(ctrl+shift+h) or Sidebar(ctrl+h)
3. Click "Today", "November 2013", "October 2013", "Older than 6 months" in left tree by order

Actual Results:
It takes a lot of time than before(Firefox28beta)

Regression window(m-i):
Good:
http://hg.mozilla.org/integration/mozilla-inbound/rev/dffbfd00ac4e
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0 ID:20140131185210
Bad:
http://hg.mozilla.org/integration/mozilla-inbound/rev/6199eb8d2f3e
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0 ID:20140131191643
Pushlog:
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=dffbfd00ac4e&tochange=6199eb8d2f3e

Regressed by Bug 902587

Comment 1

[Alice0775 White]

Aurora29.0a2 is not affected.
Maybe, '--enable-profiling' triggers the problem.

Comment 2

[Alice0775 White]

(In reply to Alice0775 White from comment #1)
> Maybe, '--enable-profiling' triggers the problem.

Pls ignore the above sentence.

Comment 3

[Alice0775 White]

On local build
Last Good: 61a591c422b7
First Bad: de11fdd37b20
Triggered by
	de11fdd37b20	Aaron Klotz — Bug 902587 - Part 3: IO Interpose Reporter for Telemetry; r=froydnj

Comment 4

[:Gavin Sharp [email: [e-mail]]]

Is the I/O telemetry stuff making I/O slower?

Comment 5

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

well, if it's intercepting write calls to system libs and doing something on each call, and we do thousands of calls I suppose the overhead may become interesting. If Observe is the main method invoked every time (https://bugzilla.mozilla.org/page.cgi?id=splinter.html&bug=902587&attachment=8369009) it seems to be doing a lot of strings manipulation... Maybe as a beginning that should be enabled only in Nightly, but still...

Comment 6

[(No longer employed by Mozilla) Aaron Klotz]

Curious; Main thread I/O *is* only enabled in Nightly.

Comment 7

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

Well, that reduces a lot impact and priority of the issue. Still, the overhead here should be investigated and reduced.

Comment 8

[:Gavin Sharp [email: [e-mail]]]

That's consistent with comment 1, right? So not so curious :)

Do we have plans to enable it for non-Nightly?

Comment 9

[(No longer employed by Mozilla) Aaron Klotz]

(In reply to :Gavin Sharp (email [e-mail]) from comment #8)
> That's consistent with comment 1, right? So not so curious :)

But inconsistent with comment 2 ;)

> 
> Do we have plans to enable it for non-Nightly?

Bug 966496, once bugs like this one get ironed out.

Comment 10

[Boris Zbarsky [:bzbarsky]]

> But inconsistent with comment 2 ;)

Er, how so?

Comment 11

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

I think he meant comment 7, I suggested it to be enabled only in Nightly, I didn't have a clue it was already, sorry.

Comment 12

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

ehr comment 5...

Comment 13

[(No longer employed by Mozilla) Aaron Klotz]

Sorry, I was thinking about the "--enable-profiling" part, not the "Aurora29.0a2 is not affected" part. *Sigh* Mondays. Never mind that :-)

Anyway, there are some efficiencies to be had with the string stuff in there. Bug 972577 will also improve things when the profiler is turned on.

Comment 14

[Jonas Finnemann Jensen (:jonasfj)]

aklotz, is likely more up-to-date than me, but I recall two concerns that could cause this:
 A) While reporting an I/O observation all other I/O operations are blocked from being reported
    due to a global lock on the list of observers:
    http://dxr.mozilla.org/mozilla-central/source/tools/profiler/IOInterposer.cpp#169

 B) All main-thread I/O reports for telemetry calls Observation::Filename() which looks up the
    filename from the file handle.

Mitigation:
 A) Could be mitigated by a shared read-only lock as suggested in bug 913653, I note for the record
    that the tests carried out in bug 913653 assumes a different method for resolving filenames from
    file handles. See bug 902587#c50 for details on the alternatives I tested.
    Current implementation uses `CreateFileMapping` which I never tested.

 B) Could be mitigated by a file handle to filename cache in PoisonIOInterposerWin.cpp.
    You would have to clear the cache when file handles are closed by interposing NtClose.
    And as suggested above, alternative methods for resolving filenames from file handles
    could be tested, but even a small cache would probably go far. If I recall correctly I
    had lots of hits with a cache size of 50.

Comment 15

[(No longer employed by Mozilla) Aaron Klotz]

(A) This is probably the bigger issue with respect to storage I/O. I am planning to completely eliminate the need to take that lock during IOInterposer observer callouts.

(B) I have previously measured the cost of the handle to filename mapping and it is not significant enough to be the cause of user-observable delays. I'm not saying that a cache wouldn't help at all, but I think that there is much lower hanging fruit.

Comment 16

[:Gavin Sharp [email: [e-mail]]]

This is a Nightly-only issue until bug 966496 is fixed, so no need to track.

Comment 17

[:Gijs (he/him)]

Alice, are you still seeing this being slow? ISTM based on some of the other comments that some of the perf issues around the IO observer code have been fixed since then, but it's hard for me to tell...

Comment 18

[Alice0775 White]

no longer reproduce on nightly80