1251238 - track service worker install time

Status: RESOLVED FIXED

(Core :: DOM: Service Workers, defect)

Description

[Ben Kelly [:bkelly, not reviewing]]

To help with debugging it would be nice to track the time when a service worker was installed.  At first this could just be exposed through about:serviceworkers and devtools.

I also wrote a spec issue about possibly exposing to content:

https://github.com/slightlyoff/ServiceWorker/issues/842

Comment 1

[Jan Keromnes [:janx]]

Interesting idea, thanks Ben for the suggestion!

Comment 2

[Ben Kelly [:bkelly, not reviewing]]

It's also probably a bug that we don't persist the times with the registration.  Our 24 hour checks are probably wrong after a browser restart.  Not a major problem because I think we update more frequently than necessary, but would be nice to fix.

Comment 3

[Tom Tung [:tt, :ttung]]

I'd like to working on this.

Comment 4

[Tom Tung [:tt, :ttung]]

Attachment: [WIP] track SW's installed time and activated time

In this patch, I've tracked SW's installed time and activated time and saved them on ServiceWorkerInfo. The reason is that we only have one ServiceWorkInfo among different SW instances (same scope but different global objects) and it's used to be stored information about SW.

To do this, :hopang and I recorded them while "ServiceWorkerInfo::UpdateState()" [1] and "ServiceWorkerInfo::SetActivateStateUncheckedWithoutEvent()" [2] are called. And, if our thought is correct, the devtools' server is able to get these informations by registering a nsIServiceWorkerRegistrationListener [3].

However, we found a problem while trying to add several checks on existing test [4]. When we get the waiting SW from a Registration, but its state is installing rather than installed. Moreover, it happens on active SW as well. As a result, we failed to get installed time. Is it correct regarding our implementation?  

[1] http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerInfo.cpp#150
[2] http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerInfo.h#145
[3] http://searchfox.org/mozilla-central/source/dom/interfaces/base/nsIServiceWorkerManager.idl#80
[4] http://searchfox.org/mozilla-central/source/dom/workers/test/serviceworkers/test_serviceworkerregistrationinfo.xul

Comment 5

[Tom Tung [:tt, :ttung]]

Attachment: Part 1: Update service worker's state before notifying the chrome listeners to enure they get correct state information.

Patch for modifying SWRInfo to ensure a SWR changes anything (including its SW) before notifying the chrome listener.

Comment 6

[Tom Tung [:tt, :ttung]]

Attachment: Part 3: Add timestamp to track service worker's install time, active time and life time.

Patch for adding timestamp to track an SW's install/active/life time and store them on SWInfo.

Comment 7

[Tom Tung [:tt, :ttung]]

Attachment: Part 7: Add a test to make sure timestamp track time as expected.

Patch for adding a test to verifying implementation.

Comment 8

[Tom Tung [:tt, :ttung]]

Comment on attachment 8850437 [details] [diff] [review]
Part 3: Add timestamp to track service worker's install time, active time and life time.

Shift the Part number because I want to add a patch between current Part 1 & 2.

Comment 9

[Tom Tung [:tt, :ttung]]

Attachment: Part 2: Modify test because we notify chrome listener each time when service worker's state is updated.

Add a new patch for fixing the issue that I trying to notify the chrome listener each time when SW's state updated. The original code notified the chrome listener only when SWRInfo changes, but I made it notify when SWInfo changes as well. Thus, I updated the test.

Comment 10

[Tom Tung [:tt, :ttung]]

Comment on attachment 8850438 [details] [diff] [review]
Part 7: Add a test to make sure timestamp track time as expected.

Shift the test again since I forgot to store timestamps on the disk.

Comment 11

[Tom Tung [:tt, :ttung]]

Attachment: Part 3: Make TimeStamp's ctor be public and create a getter to get the TimeStampValue, since we need to store it as string and reconstruct it later.

Comment 12

[Tom Tung [:tt, :ttung]]

Attachment: Part 4: Add timeStamp to track when a service worker is installed/activated/redundant and when a service worker's registration is updated.

Comment 13

[Tom Tung [:tt, :ttung]]

Attachment: Part 5: Store tracking timeStamp into serviceWroekrReistrar.

Comment 14

[Tom Tung [:tt, :ttung]]

Attachment: Part 6: Test to verify there is no problem on storing timestamps.

Comment 15

[Tom Tung [:tt, :ttung]]

Attachment: Part 3: Add timestamps to track when a service worker is installed/activated/redundant and when a service worker's registration is updated.

Comment 16

[Tom Tung [:tt, :ttung]]

Attachment: Part 4: Store installed time for a service worker and last updated time for a service worker's registration into serviceWorkerRegistrar.

Comment 17

[Tom Tung [:tt, :ttung]]

Attachment: Part 5: Modify Gtest to verify storing installed time and last updated time works in SWRegistrar.

Comment 18

[Tom Tung [:tt, :ttung]]

Attachment: Part 6: Add a test to make sure that timestamps track time as expected and modify the test since we notify the chrome listener when updating

Comment 19

[Tom Tung [:tt, :ttung]]

Attachment: Part 4: Store installed time for a service worker and last updated time for a service worker's registration into serviceWorkerRegistrar.

Comment 20

[Tom Tung [:tt, :ttung]]

Hi Ben,

I implement to this bug for tracking SW's installed time and SWR's last update time. Besides that, I also track SW's activated time and redundant time to provide more information on devtools and make users realize when a service worker starts to deal with events and when a service worker dead. 

Moreover, I made SWR notify the chrome listener each time when time markers are recorded (when the SW state changes and when the SWR updates). 

BTW, I only stored installed time and last updated time into registrar, since service worker will be active/redundant again and thus we don't need to store them into registrar.

Would you mind helping me reviewing it when you have time? Thanks!

Comment 21

[Tom Tung [:tt, :ttung]]

I'll file the follow-up bugs for the devtools sides to show these time on about:debugging#worker later

Comment 22

[Ben Kelly [:bkelly, not reviewing]]

Comment on attachment 8853205 [details] [diff] [review]
Part 3: Add timestamps to track when a service worker is installed/activated/redundant and when a service worker's registration is updated.

Review of attachment 8853205 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/interfaces/base/nsIServiceWorkerManager.idl
@@ +48,5 @@
>    readonly attribute bool handlesFetchEvents;
>  
> +  readonly attribute PRTime installedTime;
> +  readonly attribute PRTime activatedTime;
> +  readonly attribute PRTime redundantTime;

Maybe add a comment that these will return 0 if SW has not reached that state yet.

::: dom/workers/ServiceWorkerInfo.cpp
@@ +200,5 @@
> +      (PRTime) ((TimeStamp::Now() - mCreationTimeStamp).ToSeconds() * 1e6);
> +  } else if (aState == ServiceWorkerState::Redundant) {
> +    mRedundantTime =
> +      mCreationTime +
> +      (PRTime) ((TimeStamp::Now() - mCreationTimeStamp).ToSeconds() * 1e6);

Please just use ToMicroseconds() instead of us multiplying by 1e6.

Also, can you take these measurements in the Transition*To*() methods?  That would avoid the need for the if-else statements here.  Might be a little easier to read.

nit: Please use static_cast<PRTime>() instead of c-style casting.

::: dom/workers/ServiceWorkerRegistrationInfo.h
@@ +27,5 @@
>  
> +  // Timestamp to track SWR's last update time
> +  PRTime mCreationTime;
> +  TimeStamp mCreationTimeStamp;
> +  PRTime mLastUpdateTime;

Can you do a follow-on patch to remove mLastUpdateCheckTime?  It seems like its duplicate data now with these fields.

Comment 23

[Ben Kelly [:bkelly, not reviewing]]

Comment on attachment 8853211 [details] [diff] [review]
Part 4: Store installed time for a service worker and last updated time for a service worker's registration into serviceWorkerRegistrar.

Review of attachment 8853211 [details] [diff] [review]:
-----------------------------------------------------------------

r=me, but please do a follow-on patch within this bug to save/restore the activating time.

::: dom/workers/ServiceWorkerRegistrarTypes.ipdlh
@@ +21,5 @@
>  
>    uint32_t loadFlags;
> +
> +  int64_t currentWorkerInstalledTime;
> +  int64_t lastUpdateTime;

I think we should probably also store the activated time here so that it doesn't constantly change in devtools when the browser is restarted.

When the registration is loaded you can pass the activated time to ServiceWorkerRegistrationInfo::SetActive() as an extra parameter.  Or you can just override it like you do for the installing time now.

::: dom/workers/ServiceWorkerRegistrationInfo.cpp
@@ +631,5 @@
> +void
> +ServiceWorkerRegistrationInfo::SetLastUpdateTime(const int64_t aTime)
> +{
> +  if (aTime == 0) {
> +      return;

nit: 2 space indent

Comment 24

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Ben Kelly [not reviewing due to deadline][:bkelly] from comment #22)
> Can you do a follow-on patch to remove mLastUpdateCheckTime?  It seems like
> its duplicate data now with these fields.

Oh, the other reason to do this is so our "update after 24 hours" logic actually tracks time across browser reboot.

Comment 25

[Tom Tung [:tt, :ttung]]

Attachment: P3-interdiff: Update installed/ativated time after calling UpdateState() in SWRegistrationInfo.

Addressed comment 22 except merging mLastUpdateCheckTime.

In this patch, I did things as following:
- Update installed/activated/redundant time on Transit*To*() and other function which calling UpdateState().
- Use ToMicroseconds() instead of us multiplying by 1e6.
- Use static_cast<PRTime> rather c-style casting
- Add few comments

Comment 26

[Tom Tung [:tt, :ttung]]

Attachment: P3-interdiff-2: Remove calling SetActivateStateUncheckedWithoutEvent() after calling SetActive(), since we've called it on SetActive().

The purpose of this patch is to remove calling SetActivateStateUncheckedWithoutEvent() after calling SetActive(), since we've called it on SetActive().

I found we called SetActivateStateUncheckedWithoutEvent()[1] twice when we load registration. We called it in SetActive() [2] and then we called in LoadRegistration after SetActive()[3]. 

Should I file an another bug to remove it or do it in this bug?

[1] http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerInfo.h#146
[2] http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerRegistrationInfo.cpp#560
[3] http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerRegistrationInfo.cpp#560

Comment 27

[Tom Tung [:tt, :ttung]]

Attachment: P4-interdiff: Store activated time into SWRegistrar.

To addressed comment 23, I stored activated time into registrar in this patch.

Comment 28

[Tom Tung [:tt, :ttung]]

Attachment: P4-interdiff-2: patch for merging mLastUpdateCheckTime and mLastUpdateTime.

Patch for merging mLastUpdateCheckTime and mLastUpdateTime as comment 22.

However, I found a problem in this implementation. I'm not sure that should I file the follow-up bugs for it or do it in this bug. :( 

Right now, I use a PRTime(mCreationTime) to store system time for converting calendar time and use a TimeStamp(mCreationTimeStamp) to track interval time between last update time and the current time. However, since it's not easy to store TimeStamp as a string (its value is complicated in XP_WIN), I only store PRTime into SWRegistrar, which are much easily to convert into string format. 

The problem is that if someone reset the system time between we store registration and load registration, it will make the mLastUpdateTime become incorrect. 

The solution in this patch is to make SWR update by returning true as mLastUpdateTime is greater than the current time.

I believe that we should store TimeStamp(mCreationTimeStamp) as well in the final version to avoid resetting system problem, but I'm not sure about whether is the right way to do that or not and should I do it in this bug or file a follow-up bug to do that later.

-- 
Information for PRTime/PRIntervalTime/TimeStamp

If we want to track times in gecko, as far as I know, we have three ways to achieve that. 
First, we can track time via PRTime[1], and it's absolute time[2]. It provides functions for converting to calendar time. But, it depends on system time to get the current time, which means it can be reset. 
Second, we can track time via PRIntervalTime[3]. It is used to track interval time, but it rolls over every 50 days. 
Third, we can track time via TimeStamp[4], and it rolls over up to 280,000 years. However, it didn't provide a method to convert to string format and its value in XP_WIN are different.

[1] http://searchfox.org/mozilla-central/source/nsprpub/pr/include/prtime.h
[2] https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSPR/Reference/PRTime
[3] http://searchfox.org/mozilla-central/source/nsprpub/pr/include/prinrval.h
[4] http://searchfox.org/mozilla-central/source/mozglue/misc/TimeStamp.h

Comment 29

[Tom Tung [:tt, :ttung]]

Attachment: interdiff-P5: Modify gtest, since storing activated time into registrar.

The corresponding changes on gtest, since we store activated time into registrar

Comment 30

[Tom Tung [:tt, :ttung]]

Hi Ben,

Sorry for disturbance, I addressed your comment(comment 22 & comment 23) in attachment 8855213 [details] [diff] [review] / attachment 8855217 [details] [diff] [review] / attachment 8855218 [details] [diff] [review] attachment 8855230 [details] [diff] [review]. Could you help me to review them when you have time? Thanks!

Note: I have two questions when I implemented patches and I listed them in comment 26 and comment 28.

Comment 31

[Tom Tung [:tt, :ttung]]

Attachment: [Final] Bug 1251238 - Part 1: Update service worker's state before notifying the chrome listeners to enure they get correct state information. r=bkelly

Update commit message

Comment 32

[Tom Tung [:tt, :ttung]]

Attachment: [Final] Bug 1251238 - Part 2: Modify test because we notify chrome listener each time when service worker's state is updated. r=bkelly

Comment 33

[Tom Tung [:tt, :ttung]]

Attachment: [Final] Bug 1251238 - Part 3: Add timestamps to track when a service worker is installed/activated/redundant and when a service worker's registration is updated. r=bkelly

Comment 34

[Tom Tung [:tt, :ttung]]

Attachment: [Final] Bug 1251238 - Part 4: Remove calling SetActivateStateUncheckedWithoutEvent() after calling SetActive(), since we've called it on SetActive(). r=bkelly

Comment 35

[Tom Tung [:tt, :ttung]]

Attachment: [Final] Bug 1251238 - Part 5: Store installed/activated time for a service worker and last updated time for a service worker's registration into serviceWorkerRegistrar. r=bkelly

Comment 36

[Tom Tung [:tt, :ttung]]

Attachment: [Final] Bug 1251238 - Part 6: Merge mLastUpdateCheckTime and mLastUpdateTime. r=bkelly

Comment 37

[Tom Tung [:tt, :ttung]]

Attachment: [Final] Bug 1251238 - Part 7: Modify Gtest to verify storing installed/activated time and last updated time works in SWRegistrar. r=bkelly

Comment 38

[Tom Tung [:tt, :ttung]]

Attachment: [Final] Bug 1251238 - Part 8: Add a test to make sure that timestamps track time as expected and modify the test since we notify the chrome listener when updating. r=bkelly

Comment 39

[Tom Tung [:tt, :ttung]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=87fbfabdab632ffedca1686842cb0bcbefae9b30

Comment 40

[Ben Kelly [:bkelly, not reviewing]]

Clearing this NI since I think I did all the reviews here.

Comment 41

[Tom Tung [:tt, :ttung]]

(In reply to Ben Kelly [not reviewing due to deadline][:bkelly] from comment #40)
> Clearing this NI since I think I did all the reviews here.

Thanks for the review!

Comment 42

[Tom Tung [:tt, :ttung]]

Attachment: [Final] Bug 1251238 - Part 8: Add a test to make sure that timestamps track time as expected and modify the test since we notify the chrome listener when updating. r=bkelly

Update patch since there is a conflict for ini file

Comment 43

[Tom Tung [:tt, :ttung]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=bd201913bd67641a850eed92f4d86cd53feac734

Comment 44

[Tom Tung [:tt, :ttung]]

Set the checkin-needed flag since try looks good!

Comment 45

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/66e18dd6ceff
Part 1: Update service worker's state before notifying the chrome listeners to enure they get correct state information. r=bkelly
https://hg.mozilla.org/integration/autoland/rev/c179e84b040f
Part 2: Modify test because we notify chrome listener each time when service worker's state is updated. r=bkelly
https://hg.mozilla.org/integration/autoland/rev/9d157c0976e5
Part 3: Add timestamps to track when a service worker is installed/activated/redundant and when a service worker's registration is updated. r=bkelly
https://hg.mozilla.org/integration/autoland/rev/35fafa7f1a8d
Part 4: Remove calling SetActivateStateUncheckedWithoutEvent() after calling SetActive(), since we've called it on SetActive(). r=bkelly
https://hg.mozilla.org/integration/autoland/rev/9e42a7e438e9
Part 5: Store installed/activated time for a service worker and last updated time for a service worker's registration into serviceWorkerRegistrar. r=bkelly
https://hg.mozilla.org/integration/autoland/rev/3bb85700229e
Part 6: Merge mLastUpdateCheckTime and mLastUpdateTime. r=bkelly
https://hg.mozilla.org/integration/autoland/rev/8f3b554401e8
Part 7: Modify Gtest to verify storing installed/activated time and last updated time works in SWRegistrar. r=bkelly
https://hg.mozilla.org/integration/autoland/rev/d485179f4a27
Part 8: Add a test to make sure that timestamps track time as expected and modify the test since we notify the chrome listener when updating. r=bkelly

Comment 46

[Iris Hsiao [:ihsiao]]

https://hg.mozilla.org/mozilla-central/rev/66e18dd6ceff
https://hg.mozilla.org/mozilla-central/rev/c179e84b040f
https://hg.mozilla.org/mozilla-central/rev/9d157c0976e5
https://hg.mozilla.org/mozilla-central/rev/35fafa7f1a8d
https://hg.mozilla.org/mozilla-central/rev/9e42a7e438e9
https://hg.mozilla.org/mozilla-central/rev/3bb85700229e
https://hg.mozilla.org/mozilla-central/rev/8f3b554401e8
https://hg.mozilla.org/mozilla-central/rev/d485179f4a27