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

VERIFIED FIXED in 2.1 S6 (10oct)

Status

defect
VERIFIED FIXED
5 years ago
5 years ago

People

(Reporter: shinglyu, Assigned: djf)

Tracking

unspecified
2.1 S6 (10oct)
ARM
Gonk (Firefox OS)

Firefox Tracking Flags

(blocking-b2g:2.1+, b2g-v2.1 fixed, b2g-v2.2 fixed)

Details

(Whiteboard: [ft:media])

Attachments

(1 attachment, 1 obsolete attachment)

46 bytes, text/x-github-pull-request
marshall
: review+
Details | Review
# 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.
Flags: needinfo?(marshall)
See Also: → 1072078
Summary: [Telemetry] App usage time is wrong after system time changed foward. → [Telemetry] App usage time is wrong after system time changed forward
[Blocking Requested - why for this release]:
blocking-b2g: --- → 2.1?
Needed for 2.1. App time metrics will be inaccurate if this is not fixed.
Assignee: nobody → marshall
Flags: needinfo?(marshall)
Target Milestone: --- → 2.1 S6 (10oct)
Status: NEW → ASSIGNED
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.
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.
Taking this bug because I think that fixing this will fix the 2.1+ blocker in bug 1071372.
Assignee: marshall → dflanagan
Posted file link to v2.1 patch on github (obsolete) —
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.
Attachment #8499896 - Flags: review?(marshall)
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 :)
Attachment #8499896 - Flags: review?(marshall) → review+
BTW, the Flame time reset problem is being tracked in Bug 1069863
(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?
Duplicate of this bug: 1071372
Blocking Reason: Agree with comment 2
blocking-b2g: 2.1? → 2.1+
Component: Gaia → Gaia::System
Whiteboard: [ft:media]
Duplicate of this bug: 1078120
Posted file PR for master
I've got r+, but it looks like I broke the unit tests.
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.
Attachment #8500724 - Flags: review?(marshall)
Attachment #8500724 - Flags: review?(marshall) → review+
Both pull requests have the updated unit tests. Now just waiting for TBPL to turn green.
And now TBPL is down. It is looking like this patch may not land until tomorrow.
landed on master: https://github.com/mozilla-b2g/gaia/commit/8c164486554cf1f2a0d926732b92ce19be8771f4
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Attachment #8499896 - Attachment is obsolete: true
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
Attachment #8500724 - Flags: approval-gaia-v2.1?(fabrice)
Attachment #8500724 - Flags: approval-gaia-v2.1?(fabrice) → approval-gaia-v2.1+
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
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.