782117 - Close Firefox is very slow while enabling telemetry

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[blinky]

Close Firefox is very slow after enabling telemetry.

This happens since the version 17.0a1 (2012-07-21)
http://hg.mozilla.org/mozilla-central/rev/446b788ab99d

Must wait a few seconds before running Firefox again
See http://s449.photobucket.com/albums/qq217/movh/?action=view&current=0b9d88db.mp4


This does not happen in version 17.0a1 (2012-07-20)
http://hg.mozilla.org/mozilla-central/rev/3a05d298599e

Close Firefox very fast
See http://s449.photobucket.com/albums/qq217/movh/?action=view&current=68c4c036.mp4

Comment 1

[Josh Matthews [:jdm]]

http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=3a05d298599e&tochange=446b788ab99d

There's only on bug in that list that explicitly mentions telemetry: bug 776081

Comment 2

[Alice0775 White]

I can reproduce.

And warning box pops up sometimes as follows:
A script on this page may be busy, or it may have stopped responding. You can stop the script now, or you can continue to see if the script will complete.
Script: resource:///components/TelemetryPing.js:814

Regression window(m-i)
Good:
http://hg.mozilla.org/integration/mozilla-inbound/rev/0a00993c6ebe
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/17.0 Firefox/17.0 ID:20120719124653
Bad:
http://hg.mozilla.org/integration/mozilla-inbound/rev/e0a1d64fc929
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/17.0 Firefox/17.0 ID:20120719145854
Pushlog:
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=0a00993c6ebe&tochange=e0a1d64fc929

Comment 3

[Josh Matthews [:jdm]]

Bug 775719 looks like a smoking gun.

Comment 4

[Alice0775 White]

Warning box pops up in latest Nightly
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/17.0 Firefox/17.0 ID:20120812030538

A script on this page may be busy, or it may have stopped responding. You can stop the script now, or you can continue to see if the script will complete.
Script: resource:///components/TelemetryPing.js:815

Comment 5

[Alice0775 White]

The problem is gone if I delete files in saved-telemetry-pings folder in profile.

However, 
The number of the files in the saved-telemetry-pings folder increases whenever I restart Firefox.
So, the shutdown speed becomes slow when I repeat restart Firefox dozens of times(20-50 times at least).

Comment 6

[Alice0775 White]

I noticed that all files in the saved-telemetry-pings folder are rewritten at the shutdown.

Comment 7

[Nathan Froyd [:froydnj]]

(In reply to Alice0775 White from comment #6)
> I noticed that all files in the saved-telemetry-pings folder are rewritten
> at the shutdown.

This should not be difficult to fix.  I will write a patch for this today.

Comment 8

[Nathan Froyd [:froydnj]]

Attachment: patch

This patch only saves pings to disk when necessary.

I'm not super happy with the patch.  I think it'd be a lot nicer, if a lot more work, to load the pings in from disk incrementally.  I think that's more appropriate to do as a followup, rather than for fixing this bug.

I'd appreciate it if folks having the issue and the capability to build Firefox themselves would test this patch to see if it does what I claim it does.

Comment 9

[(dormant account)]

Comment on attachment 651357 [details] [diff] [review]
patch

The problem is safe-output-stream fsync()ing. Use a normal fileoutput stream, checksum is there to guard against io corruption.

Comment 10

[Nathan Froyd [:froydnj]]

Attachment: part 1 - don't use safe-file-output-stream

It's not clear to me that this is really needed; we've been using safe-file-output-stream for quite a while without problems.  I think the real issue is rewriting the pings over and over.  But you asked for it, so...

Comment 11

[Nathan Froyd [:froydnj]]

Attachment: part 2 - don't overwrite previously-saved pings

Virtually the same patch as before, only now use O_EXCL or equivalent when opening the file to do the "does it exist?" detection, rather than relying on the checksum in the ping packet.  Note that this doesn't save any syscalls, as discussed on IRC yesterday, but it is somewhat more robust.

Comment 12

[(dormant account)]

Comment on attachment 652140 [details] [diff] [review]
part 2 - don't overwrite previously-saved pings

Flip your logic, use a positive overwrite.

Comment 13

[Nathan Froyd [:froydnj]]

Patch pushed with overwrite flipped.

https://hg.mozilla.org/integration/mozilla-inbound/rev/1ffe10e14d7c
https://hg.mozilla.org/integration/mozilla-inbound/rev/a3ded704cf28

Comment 14

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/1ffe10e14d7c
https://hg.mozilla.org/mozilla-central/rev/a3ded704cf28

Comment 15

[Virgil Dicu [:virgil] [QA]]

Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/17.0 Firefox/17.0 beta 1 a

Verifiend on Ubuntu 12.10, Mac OsX 10.7, WIndows 8 Firefox 17 beta 1.

After enabling telemetry Firefox is starting normally and after closing it it's not necessary to wait a few seconds before running it again.