1072075 - [Telemetry] App usage time is wrong after system time changed forward

Status: VERIFIED FIXED

(Firefox OS Graveyard :: Gaia::System, defect)

Description

[Shing Lyu [:shinglyu]]

# Summary:
  When the system time is changed manually, the app usage time is wrong.

# Steps:
  * (optional) Change the app usage upload interval to 1 min.
  * Enable Wi-Fi or 3G, and enable app usage tracking in Settings > Improve B2G OS > Submit data
  * Go to Settings > Date & Time, Uncheck "Set automatically"
  * Set the date to a future date (e.g. if today is 9/24, set to 9/30.)
  * Press the home key to return to the homescreen. 
  * Wait for the app usage metrics to be transmitted to the server.

# Expected:
  The actual time spent on the settings app should be tracked correctly.

# Actual:
  The usageTime for settings app is extremely large (9/24~9/30).

# Repoduction Frequency:
  Always

# Additional Info:
  Time change trigger by time zone change doesn't seem to trigger this bug.

Comment 1

[Gerry Chang [:gchang]]

[Blocking Requested - why for this release]:

Comment 2

[Ravi Dandu]

Needed for 2.1. App time metrics will be inaccurate if this is not fixed.

Comment 3

[David Flanagan [:djf]]

We might be able to fix this by switching from Date.now() to peformance.now()

I think (but need to test) that it will not change when the system time changes.

For just measuring seconds of time used, performance.now() is fine.  For the start and end dates of each batch of usage data, we still need absolute dates with Date.now().  So we could get corrupt start and end dates on batches if the time shifts.  We can measure the distance between date.now() and performance.now() and then remeasure that when we get a moztimechange event. The difference between those will tell us how much the time has shifted and we could use that to adjust the batch start time.

Comment 4

[David Flanagan [:djf]]

Actually, that solution for fixing the batch start time won't work in general because performance.now restarts on each reboot.  So if we're working with a saved batch start time we won't be able to adjust that.  But in the case where we start a new batch of data and then get a time change during the system startup process, we will be able to adjust that.  But not when we read a saved batch start time from asyncStorage.

Comment 5

[David Flanagan [:djf]]

Taking this bug because I think that fixing this will fix the 2.1+ blocker in bug 1071372.

Comment 6

[David Flanagan [:djf]]

Attachment: link to v2.1 patch on github

Marshall,

This patch is for the 2.1 branch because today's nightly for the master branch seemed broken. I expect the patch to apply cleanly to master as well as 2.1.

This patch converts to using performance.now() for app timings so that they are not affected when the system time changes.  It still uses Date.now() for the batch start time and comparisons with it, because those need to be persisted.

The second (possibliy unnecessary) part of this patch is the code that adjusts the batch start time when the system time changes. If NTP only adjusts our clock by a few minutes, this batch start time adjustment would not be necessary.  But since you've been seeing much larger time adjustments, I added this code to deal with them.  If there is some other bug causing the phone to lose track of time, and that is fixed, then maybe we can remove the adjustment code since that is the trickiest part of this patch.

Comment 7

[Marshall Culpepper [:marshall_law]]

Comment on attachment 8499896 [details] [review]
link to v2.1 patch on github

This is great! I have a suggestion for how we could better track time since batch start / failed transmission..

Maybe we should only store the aggregate amount of time since the batch began, and increment it by comparing performance timestamps the same way we do for apps in the event handler.

When it comes time to transmit, we just subtract the aggregate from Date.now() and have an actual date to pass to the telemetry server.

We wouldn't need to have special logic for persisting this way..

Leaving r+ For now in case you don't want to make this change :)

Comment 8

[Marshall Culpepper [:marshall_law]]

BTW, the Flame time reset problem is being tracked in Bug 1069863

Comment 9

[David Flanagan [:djf]]

(In reply to Marshall Culpepper [:marshall_law] from comment #7)
> Comment on attachment 8499896 [details] [review]
> link to v2.1 patch on github
> 
> This is great! I have a suggestion for how we could better track time since
> batch start / failed transmission..
> 
> Maybe we should only store the aggregate amount of time since the batch
> began, and increment it by comparing performance timestamps the same way we
> do for apps in the event handler.
> 

But then we can't persist it across reboots, can we? If we just have a time-since-batch-began but not the start time itself, then when we're turned off and back on we don't know if a minute has passed or a week...

Or am I missing something?

Comment 11

[Hema Koka [:hema]]

Blocking Reason: Agree with comment 2

Comment 13

[David Flanagan [:djf]]

Attachment: PR for master

Comment 14

[David Flanagan [:djf]]

I've got r+, but it looks like I broke the unit tests.

Comment 15

[David Flanagan [:djf]]

Comment on attachment 8500724 [details] [review]
PR for master

Marshall,

This is the same patch you already reviewed for 2.1 except that it includes changes to the unit tests because the patch broke them. Also, it includes comments that refer to the underlying "time won't stay set" bug.

Comment 16

[David Flanagan [:djf]]

Both pull requests have the updated unit tests. Now just waiting for TBPL to turn green.

Comment 17

[David Flanagan [:djf]]

And now TBPL is down. It is looking like this patch may not land until tomorrow.

Comment 18

[David Flanagan [:djf]]

landed on master: https://github.com/mozilla-b2g/gaia/commit/8c164486554cf1f2a0d926732b92ce19be8771f4

Comment 19

[David Flanagan [:djf]]

Comment on attachment 8500724 [details] [review]
PR for master

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #): this was an omission not a regression

[User impact] if declined: We will sometimes submit bad telemetry data

[Testing completed]: yes

[Risk to taking this patch] (and alternatives if risky): not really risky

[String changes made]: none

Comment 20

[Ryan VanderMeulen [:RyanVM]]

v2.1: https://github.com/mozilla-b2g/gaia/commit/a13a3f83e73f8ec0d01d031c0136f2b68bfcd594

Comment 21

[Shing Lyu [:shinglyu]]

Verified on flame (319M) v2.1.

Version:
  Gaia      1e48e3e40e0780c0cd07a3457e5fe2efeeb542d1
  Gecko     https://hg.mozilla.org/releases/mozilla-aurora/rev/7fa82c9acdf2
  BuildID   20141008000201
  Version   34.0a2
  ro.build.date   Mon Sep 29 19:42:41 EDT 2014
  ro.bootloader   L1TC10011800
  ro.build.version.incremental   eng.cltbld.20140929.194231

Logcat output:
  E/GeckoConsole( 2656): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] app://verticalhome.gaiamobile.org/manifest.webapp ran for 2
  E/GeckoConsole( 2656): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] Saved app usage data
  E/GeckoConsole( 2656): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] System time change; converted batch start time from: Thu Oct 23 2014 10:34:04  GMT+0800 (CST) to: Sun Oct 26 2014 10:33:30 GMT+0800 (CST)
  E/GeckoConsole( 2656): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] app://settings.gaiamobile.org/manifest.webapp ran for 17
  E/GeckoConsole( 2656): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] Saved app usage data