972856 - Timestamp of last happened CC has changed from milliseconds to microseconds in GC API

Status: VERIFIED FIXED

(Core :: XPCOM, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1]]

As we have seen in MemChaser the duration since the last CC happened, has been changed from milliseconds to microseconds. My investigation has been shown that bug 948554 has been caused this.

As Andrew said, this is not expected. As of now Firefox 29 and 30 are affected.

Comment 1

[Andrew McCreight [:mccr8]]

I don't think it needs to be tracked.  Yours is one of the only addons that actually looks at this data, and you have a work around in place if I can't get it fixed in time. :)

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+1]]

I think what is to blame here is the following line:
http://hg.mozilla.org/mozilla-central/diff/3453305f7101/dom/base/nsJSEnvironment.cpp#l1.167

   1.167 -  PRTime endCCTime = PR_Now();
   1.168 +  TimeStamp endCCTime = TimeStamp::Now();

The change to TimeStamp causes us to print microseconds instead of milliseconds. Should we call endCCTime.ToMilliseconds() when formatting it forJSON instead of using endCCTime directly?

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+1]]

With that I mean here:
http://mxr.mozilla.org/mozilla-central/source/dom/base/nsJSEnvironment.cpp#2286

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Actually this is the timestamp property and not the duration one in the CC JSON string.

Comment 5

[Andrew McCreight [:mccr8]]

Attachment: Use PR_Now() for CC timestamp in JSON log.

Great analysis, thanks!  You saved me a lot of time.  If you could test this to make sure it is okay, I'd appreciate it.

There's no .ToMilliseconds() for TimeStamp, and anyways, we should be using the same method for generating the time stamp for the GC and CC, so there's a consistent timeline, and I don't feel like changing the GC approach, so I am just going to change it to use the old approach.

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8376356 [details] [diff] [review]
Use PR_Now() for CC timestamp in JSON log.

Variable names are now backwards.
endCCTime is for TimeStamp and endCCTimeStamp for PR_Now()

Comment 7

[Andrew McCreight [:mccr8]]

Attachment: Use PR_Now() for CC timestamp in JSON log.

I switched the names.  You are right, it was weird before.

https://tbpl.mozilla.org/?tree=Try&rev=af50cdecffa3

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+1]]

That fixes it. Thank you Andrew!

Comment 9

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ae95fa9d4450

Should we have a test for this?

Comment 10

[Andrew McCreight [:mccr8]]

probably

Comment 11

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/ae95fa9d4450

Comment 12

[Andrew McCreight [:mccr8]]

Comment on attachment 8376896 [details] [diff] [review]
Use PR_Now() for CC timestamp in JSON log.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 948554
User impact if declined: breaks some addons
Testing completed (on m-c, etc.): m-c
Risk to taking this patch (and alternatives if risky): very low, and it shouldn't affect anybody who isn't running one of these addons
String or IDL/UUID changes made by this patch: none

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Works fine with Mozilla/5.0 (X11; Linux x86_64; rv:30.0) Gecko/20100101 Firefox/30.0 ID:20140219030203 CSet: bf0e76f2a7d4. Marking as verified fixed.

Comment 14

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/a47082eaf863

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Works fine also with Mozilla/5.0 (X11; Linux x86_64; rv:29.0) Gecko/20100101 Firefox/29.0 ID:20140221004001 CSet: 62aa405444cd