diff --git a/CHANGELOG.md b/CHANGELOG.md index e88a407dd..d54c9cee2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -49,6 +49,7 @@ * The token request is filed under the device ID that is current when it is queued. * Mitigated an issue where fatal crash reports were lost in explicit storage mode. * Mitigated an issue where a remote config download that finished after "halt()" stored the previous user's values. +* Mitigated an issue where durations changed when the device clock was adjusted: sessions, views, timed events, APM traces, foreground and background time, and the running time in crash reports. Timestamps still follow the device clock. * Mitigated an issue where "requestQueue().flushQueues()" kept the recorded events that were not in a request yet, so they were still sent. * Removed the following deprecated calls from "CountlyConfig": diff --git a/sdk/src/androidTest/java/ly/count/android/sdk/CountlyTests.java b/sdk/src/androidTest/java/ly/count/android/sdk/CountlyTests.java index 41bba791d..e45debd44 100644 --- a/sdk/src/androidTest/java/ly/count/android/sdk/CountlyTests.java +++ b/sdk/src/androidTest/java/ly/count/android/sdk/CountlyTests.java @@ -352,7 +352,7 @@ public void testOnStart_firstCall() { assertEquals(1, mCountly.getActivityCount()); final long prevSessionDurationStartTime = mCountly.getPrevSessionDurationStartTime(); assertTrue(prevSessionDurationStartTime > 0); - assertTrue(prevSessionDurationStartTime <= System.currentTimeMillis()); + assertTrue(prevSessionDurationStartTime <= UtilsTime.monotonicTimeMs()); TestUtils.verifyBeginSessionValues(requestQueueProvider, false, null, null, null, null); } @@ -557,19 +557,19 @@ public void testOnTimer_activeSession_nonEmptyEventQueue() { @Test public void testRoundedSecondsSinceLastSessionDurationUpdate() { - long prevSessionDurationStartTime = System.currentTimeMillis() - 1000; + long prevSessionDurationStartTime = UtilsTime.monotonicTimeMs() - 1000; mCountly.setPrevSessionDurationStartTime(prevSessionDurationStartTime); assertEquals(1, mCountly.moduleSessions.roundedSecondsSinceLastSessionDurationUpdate()); - prevSessionDurationStartTime = System.currentTimeMillis() - 2000; + prevSessionDurationStartTime = UtilsTime.monotonicTimeMs() - 2000; mCountly.setPrevSessionDurationStartTime(prevSessionDurationStartTime); assertEquals(2, mCountly.moduleSessions.roundedSecondsSinceLastSessionDurationUpdate()); - prevSessionDurationStartTime = System.currentTimeMillis() - 1600; + prevSessionDurationStartTime = UtilsTime.monotonicTimeMs() - 1600; mCountly.setPrevSessionDurationStartTime(prevSessionDurationStartTime); assertEquals(2, mCountly.moduleSessions.roundedSecondsSinceLastSessionDurationUpdate()); - prevSessionDurationStartTime = System.currentTimeMillis() - 1200; + prevSessionDurationStartTime = UtilsTime.monotonicTimeMs() - 1200; mCountly.setPrevSessionDurationStartTime(prevSessionDurationStartTime); assertEquals(1, mCountly.moduleSessions.roundedSecondsSinceLastSessionDurationUpdate()); } diff --git a/sdk/src/androidTest/java/ly/count/android/sdk/DeviceInfoTests.java b/sdk/src/androidTest/java/ly/count/android/sdk/DeviceInfoTests.java index a0c1b8c90..99158799a 100644 --- a/sdk/src/androidTest/java/ly/count/android/sdk/DeviceInfoTests.java +++ b/sdk/src/androidTest/java/ly/count/android/sdk/DeviceInfoTests.java @@ -63,6 +63,16 @@ public void testGetOS() { assertEquals("Android", regularDeviceInfo.mp.getOS()); } + /** + * The running time sent with crash reports comes from the monotonic clock, which a change of the device clock + * does not move + */ + @Test + public void testGetRunningTime_monotonicClock() { + long runningTime = Long.parseLong(regularDeviceInfo.mp.getRunningTime()); + assertEquals(UtilsTime.monotonicTimeSeconds() - DeviceInfo.startTime, runningTime, 1); + } + @Test public void testGetOSVersion() { assertEquals(android.os.Build.VERSION.RELEASE, regularDeviceInfo.mp.getOSVersion()); diff --git a/sdk/src/androidTest/java/ly/count/android/sdk/ModuleAPMTests.java b/sdk/src/androidTest/java/ly/count/android/sdk/ModuleAPMTests.java index 4a8f6e514..fe0a860ce 100644 --- a/sdk/src/androidTest/java/ly/count/android/sdk/ModuleAPMTests.java +++ b/sdk/src/androidTest/java/ly/count/android/sdk/ModuleAPMTests.java @@ -146,7 +146,6 @@ public void recordNetworkTraceStartStop() { mCountly.apm().startNetworkRequest("abc", "111"); Assert.assertTrue(mCountly.moduleAPM.networkTraces.containsKey(internalTraceKey)); - Long starVal = mCountly.moduleAPM.networkTraces.get(internalTraceKey); mCountly.apm().endNetworkRequest("abc", "111", 345, 222, 555); @@ -154,21 +153,20 @@ public void recordNetworkTraceStartStop() { verify(requestQueueProvider).sendAPMNetworkTrace(eq("abc"), duration.capture(), eq(345), eq(222), eq(555), start.capture(), stop.capture()); - Assert.assertEquals(starVal, start.getValue()); - Assert.assertTrue(stop.getValue() > start.getValue()); - Assert.assertTrue((stop.getValue() - start.getValue()) < 100); + Assert.assertEquals(stop.getValue() - start.getValue(), (long) duration.getValue()); + Assert.assertTrue(duration.getValue() >= 0 && duration.getValue() < 100); } @Test public void customTrace() { String key = "ddd"; - Long ts1 = UtilsTime.currentTimestampMs(); + long ts1 = UtilsTime.monotonicTimeMs(); mCountly.apm().startTrace(key); - Long ts2 = UtilsTime.currentTimestampMs(); + long ts2 = UtilsTime.monotonicTimeMs(); Assert.assertTrue(mCountly.moduleAPM.codeTraces.containsKey(key)); Long keyTs = mCountly.moduleAPM.codeTraces.get(key); - Assert.assertTrue(ts1 < keyTs && keyTs < ts2); + Assert.assertTrue(ts1 <= keyTs && keyTs <= ts2); mCountly.apm().endTrace(key, null); @@ -178,9 +176,64 @@ public void customTrace() { verify(requestQueueProvider).sendAPMCustomTrace(eq(key), duration.capture(), start.capture(), stop.capture(), eq("")); - Assert.assertEquals(keyTs, start.getValue()); - Assert.assertTrue(stop.getValue() > start.getValue()); - Assert.assertTrue((stop.getValue() - start.getValue()) < 100); + Assert.assertEquals(stop.getValue() - start.getValue(), (long) duration.getValue()); + Assert.assertTrue(duration.getValue() >= 0 && duration.getValue() < 100); + } + + /** + * A custom trace's duration comes from the monotonic clock, and its start timestamp is its end timestamp minus + * that duration + */ + @Test + public void customTrace_monotonicClock() { + mCountly.apm().startTrace("ddd"); + mCountly.moduleAPM.codeTraces.put("ddd", UtilsTime.monotonicTimeMs() - 2000); + mCountly.apm().endTrace("ddd", null); + + ArgumentCaptor duration = ArgumentCaptor.forClass(Long.class); + ArgumentCaptor start = ArgumentCaptor.forClass(Long.class); + ArgumentCaptor stop = ArgumentCaptor.forClass(Long.class); + verify(requestQueueProvider).sendAPMCustomTrace(eq("ddd"), duration.capture(), start.capture(), stop.capture(), eq("")); + + Assert.assertTrue("duration: " + duration.getValue(), duration.getValue() >= 2000 && duration.getValue() < 2100); + Assert.assertEquals(stop.getValue() - start.getValue(), (long) duration.getValue()); + } + + /** + * A network trace's response time comes from the monotonic clock, and its start timestamp is its end timestamp + * minus that response time + */ + @Test + public void networkTrace_monotonicClock() { + mCountly.apm().startNetworkRequest("abc", "111"); + mCountly.moduleAPM.networkTraces.put("abc|111", UtilsTime.monotonicTimeMs() - 2000); + mCountly.apm().endNetworkRequest("abc", "111", 200, 10, 20); + + ArgumentCaptor duration = ArgumentCaptor.forClass(Long.class); + ArgumentCaptor start = ArgumentCaptor.forClass(Long.class); + ArgumentCaptor stop = ArgumentCaptor.forClass(Long.class); + verify(requestQueueProvider).sendAPMNetworkTrace(eq("abc"), duration.capture(), eq(200), eq(10), eq(20), start.capture(), stop.capture()); + + Assert.assertTrue("response time: " + duration.getValue(), duration.getValue() >= 2000 && duration.getValue() < 2100); + Assert.assertEquals(stop.getValue() - start.getValue(), (long) duration.getValue()); + } + + /** + * Foreground and background time comes from the monotonic clock, and its start timestamp is its end timestamp + * minus that time + */ + @Test + public void foregroundBackgroundTime_monotonicClock() { + mCountly.moduleAPM.lastScreenSwitchTime = UtilsTime.monotonicTimeMs() - 3000; + mCountly.moduleAPM.doForegroundBackgroundCalculations(true, false); + + ArgumentCaptor duration = ArgumentCaptor.forClass(Long.class); + ArgumentCaptor start = ArgumentCaptor.forClass(Long.class); + ArgumentCaptor stop = ArgumentCaptor.forClass(Long.class); + verify(requestQueueProvider).sendAPMScreenTime(eq(true), duration.capture(), start.capture(), stop.capture()); + + Assert.assertTrue("foreground time: " + duration.getValue(), duration.getValue() >= 3000 && duration.getValue() < 3100); + Assert.assertEquals(stop.getValue() - start.getValue(), (long) duration.getValue()); } @Test diff --git a/sdk/src/androidTest/java/ly/count/android/sdk/ModuleEventsTests.java b/sdk/src/androidTest/java/ly/count/android/sdk/ModuleEventsTests.java index 531f11db0..66a0ee560 100644 --- a/sdk/src/androidTest/java/ly/count/android/sdk/ModuleEventsTests.java +++ b/sdk/src/androidTest/java/ly/count/android/sdk/ModuleEventsTests.java @@ -269,6 +269,44 @@ public void startEndEvent_withSegments() throws InterruptedException { Assert.assertEquals(2, captD, 0.1d); } + /** + * The device clock moving an hour forward between "startEvent" and "endEvent" does not change the duration + */ + @Test + public void startEndEvent_deviceClockMovedForward() { + startEndEventDeviceClockChangedBase(3_600_000L); + } + + /** + * The device clock moving an hour back between "startEvent" and "endEvent" does not change the duration + */ + @Test + public void startEndEvent_deviceClockMovedBack() { + startEndEventDeviceClockChangedBase(-3_600_000L); + } + + /** + * Ends a timed event right after moving its wall-clock start by "clockChangeMs" the other way, which is how a + * device clock change between start and end looks to the SDK. The duration must stay near zero, and the + * event must keep its wall-clock start as its timestamp. + */ + void startEndEventDeviceClockChangedBase(long clockChangeMs) { + EventProvider ep = TestUtils.setEventProviderToMock(mCountly, mock(EventProvider.class)); + Assert.assertTrue(mCountly.events().startEvent(eventKey)); + + Event startEvent = mCountly.moduleEvents.timedEvents.get(eventKey); + startEvent.timestamp -= clockChangeMs; + + Assert.assertTrue(mCountly.events().endEvent(eventKey)); + + ArgumentCaptor arg = ArgumentCaptor.forClass(UtilsTime.Instant.class); + ArgumentCaptor argD = ArgumentCaptor.forClass(Double.class); + verify(ep).recordEventInternal(eq(eventKey), isNull(Map.class), eq(1), eq(0.0d), argD.capture(), arg.capture(), isNull(String.class)); + + Assert.assertEquals(startEvent.timestamp, arg.getValue().timestampMs); + Assert.assertEquals(0, argD.getValue(), 0.1d); + } + @Test public void startCancelEndEvent() { EventProvider ep = TestUtils.setEventProviderToMock(mCountly, mock(EventProvider.class)); diff --git a/sdk/src/androidTest/java/ly/count/android/sdk/ModuleViewsTests.java b/sdk/src/androidTest/java/ly/count/android/sdk/ModuleViewsTests.java index 4c424d919..bf6aa9742 100644 --- a/sdk/src/androidTest/java/ly/count/android/sdk/ModuleViewsTests.java +++ b/sdk/src/androidTest/java/ly/count/android/sdk/ModuleViewsTests.java @@ -1105,6 +1105,21 @@ public void stopPausedViewBase(boolean useID) throws InterruptedException { stopViewInFlow(viewNames[0], viewID[0], null, null, 0, useID, mCountly, ep); } + /** + * A view's duration is measured on the monotonic clock, which a change of the device clock does not move + */ + @Test + public void viewDurationOnMonotonicClock() { + @NonNull CountlyConfig cc = TestUtils.createViewCountlyConfig(false, false, false, safeViewIDGenerator, null); + Countly mCountly = new Countly().init(cc); + @NonNull EventProvider ep = TestUtils.setEventProviderToMock(mCountly, mock(EventProvider.class)); + + String viewID = startViewInFlow(viewNames[0], vals[0], null, null, false, mCountly, ep); + mCountly.moduleViews.viewDataMap.get(viewID).viewStartTimeSeconds = UtilsTime.monotonicTimeSeconds() - 3; + + stopViewInFlow(viewNames[0], viewID, null, null, 3, true, mCountly, ep); + } + /** * Validate that segmentation can be provided as expected * Use ID to stop view: yes @@ -2233,7 +2248,7 @@ static void validateView(String viewName, Double viewDuration, int idx, int size viewSegmentation.put("cly_pvn", pvn); } - //The SDK reports view durations in WHOLE SECONDS (currentTimestampSeconds() - viewStartTimeSeconds), + //The SDK reports view durations in WHOLE SECONDS (monotonicTimeSeconds() - viewStartTimeSeconds), //and the tests that expect a non-zero duration produce it with Thread.sleep. A 1000 ms sleep plus any //scheduling delay therefore measures 1 or 2 depending on which side of a second boundary the clock //lands on, which is why CI failed with expected:<1.0> but was:<2.0> on a test that is not about diff --git a/sdk/src/androidTest/java/ly/count/android/sdk/TestUtils.java b/sdk/src/androidTest/java/ly/count/android/sdk/TestUtils.java index c3cc7f08b..4259728cb 100644 --- a/sdk/src/androidTest/java/ly/count/android/sdk/TestUtils.java +++ b/sdk/src/androidTest/java/ly/count/android/sdk/TestUtils.java @@ -380,11 +380,11 @@ public static void validateRecordEventInternalMock(EventProvider ep, String even } /** - * Waits until the current wall-clock second has enough room left that a test cannot accidentally cross a - * second boundary while it runs. + * Waits until the current second of {@link UtilsTime#monotonicTimeMs()} has enough room left that a test + * cannot accidentally cross a second boundary while it runs. *

- * The SDK measures durations with {@link UtilsTime#currentTimestampSeconds()}, which truncates - * ({@code System.currentTimeMillis() / 1000}). A view started at x.999 and stopped at x+1.001 therefore + * The SDK measures view durations with {@link UtilsTime#monotonicTimeSeconds()}, which truncates + * ({@code monotonicTimeMs() / 1000}). A view started at x.999 and stopped at x+1.001 therefore * reports one whole second for two milliseconds of work, and a test that sleeps 1000ms starting from * x.900 reports two. Both are pure boundary luck, not slowness, and they are why the ModuleViews duration * tests failed intermittently - one of them carrying the comment "duration comes off sometimes". @@ -394,7 +394,7 @@ public static void validateRecordEventInternalMock(EventProvider ep, String even * for the tests that call it. */ public static void alignToSecondBoundary() { - long remainderMs = System.currentTimeMillis() % 1000L; + long remainderMs = UtilsTime.monotonicTimeMs() % 1000L; //500ms of headroom: enough for a "no duration" test to start and stop a view, and enough that a //sleep(1000) plus its overshoot still lands inside the next second if (remainderMs <= 500L) { @@ -469,8 +469,8 @@ public static void validateRecordEventInternalMock(final @NonNull EventProvider Assert.assertTrue(cDuration >= 0); if (duration != null) { - //Exact, deliberately. Durations come from UtilsTime.currentTimestampSeconds(), which truncates - //(System.currentTimeMillis() / 1000), so a view spanning a second boundary reports a whole second + //Exact, deliberately. View durations come from UtilsTime.monotonicTimeSeconds(), which truncates + //(monotonicTimeMs() / 1000), so a view spanning a second boundary reports a whole second //for microseconds of work. That is handled by starting these tests inside a fresh second - see //alignToSecondBoundary - rather than by loosening this assertion: "this view recorded no duration" //is exactly the kind of thing these tests exist to catch. diff --git a/sdk/src/main/java/ly/count/android/sdk/DeviceInfo.java b/sdk/src/main/java/ly/count/android/sdk/DeviceInfo.java index ff0d77536..0bea8faa3 100644 --- a/sdk/src/main/java/ly/count/android/sdk/DeviceInfo.java +++ b/sdk/src/main/java/ly/count/android/sdk/DeviceInfo.java @@ -60,7 +60,7 @@ of this software and associated documentation files (the "Software"), to deal * the current device and operating environment. */ class DeviceInfo { - private final static int startTime = UtilsTime.currentTimestampSeconds(); + final static long startTime = UtilsTime.monotonicTimeSeconds(); private boolean inBackground = true; private static volatile long totalMemory = -1; // -1 until resolved, so a failed read is not retried private static volatile String rootedStatus = null; @@ -497,7 +497,7 @@ public String hasHinge(Context context) { @Override public String getRunningTime() { String ov = DeviceInfo.this.mpOverride.getRunningTime(); if (ov != null) return ov; - return Integer.toString(UtilsTime.currentTimestampSeconds() - startTime); + return Long.toString(UtilsTime.monotonicTimeSeconds() - startTime); } }; } diff --git a/sdk/src/main/java/ly/count/android/sdk/Event.java b/sdk/src/main/java/ly/count/android/sdk/Event.java index a106b4214..a63a1d690 100644 --- a/sdk/src/main/java/ly/count/android/sdk/Event.java +++ b/sdk/src/main/java/ly/count/android/sdk/Event.java @@ -63,6 +63,7 @@ class Event { public String pvid; public String cvid; public String peid; + long monotonicStartMs; // start of a timed event on UtilsTime.monotonicTimeMs(), not serialized Event() { } diff --git a/sdk/src/main/java/ly/count/android/sdk/ModuleAPM.java b/sdk/src/main/java/ly/count/android/sdk/ModuleAPM.java index c2fdf38b0..f26416fe0 100644 --- a/sdk/src/main/java/ly/count/android/sdk/ModuleAPM.java +++ b/sdk/src/main/java/ly/count/android/sdk/ModuleAPM.java @@ -15,6 +15,7 @@ public class ModuleAPM extends ModuleBase { Apm apmInterface = null; + //trace starts are on UtilsTime.monotonicTimeMs(); a trace is sent with its end timestamp minus its duration as start, so all three agree Map codeTraces; Map networkTraces; @@ -22,7 +23,7 @@ public class ModuleAPM extends ModuleBase { //used to determine app start time boolean hasFirstOnResumeHappened = false; - long lastScreenSwitchTime = -1;// timestamp of when the app last changed from foreground to background + long lastScreenSwitchTime = -1;// UtilsTime.monotonicTimeMs() of when the app last changed from foreground to background int activitiesOpen; @@ -72,25 +73,25 @@ void startTraceInternal(String traceKey) { return; } - Long currentTimestamp = UtilsTime.currentTimestampMs(); - codeTraces.put(traceKey, currentTimestamp); + codeTraces.put(traceKey, UtilsTime.monotonicTimeMs()); } void endTraceInternal(@NonNull String traceKey, @NonNull Map customMetrics) { //end time counting as fast as possible - Long currentTimestamp = UtilsTime.currentTimestampMs(); + long endMonotonicMs = UtilsTime.monotonicTimeMs(); + long currentTimestamp = UtilsTime.currentTimestampMs(); assert traceKey != null && !traceKey.isEmpty(); assert customMetrics != null; L.d("[ModuleAPM] Calling 'endTraceInternal' with key:[" + traceKey + "]"); if (codeTraces.containsKey(traceKey)) { - Long startTimestamp = codeTraces.remove(traceKey); + Long startMonotonicMs = codeTraces.remove(traceKey); - if (startTimestamp == null) { - L.e("[ModuleAPM] endTraceInternal, retrieved 'startTimestamp' is null, dropping trace"); + if (startMonotonicMs == null) { + L.e("[ModuleAPM] endTraceInternal, retrieved trace start is null, dropping trace"); } else { - Long durationMs = currentTimestamp - startTimestamp; + long durationMs = endMonotonicMs - startMonotonicMs; if (!customMetrics.isEmpty()) { //custom metrics provided @@ -104,7 +105,7 @@ void endTraceInternal(@NonNull String traceKey, @NonNull Map cu String truncatedTraceKey = UtilsInternalLimits.truncateKeyLength(traceKey, _cly.sdkInternalLimits_.maxKeyLength, L, "[ModuleAPM] endTraceInternal"); String modifiedTraceKey = validateAndModifyTraceKey(truncatedTraceKey); - requestQueueProvider.sendAPMCustomTrace(modifiedTraceKey, durationMs, startTimestamp, currentTimestamp, metricString); + requestQueueProvider.sendAPMCustomTrace(modifiedTraceKey, durationMs, currentTimestamp - durationMs, currentTimestamp, metricString); } } else { L.w("[ModuleAPM] endTraceInternal, trying to end trace which was not started"); @@ -230,8 +231,7 @@ void startNetworkRequestInternal(String networkTraceKey, String uniqueId) { } String internalTraceKey = networkTraceKey + "|" + uniqueId; - Long currentTimestamp = UtilsTime.currentTimestampMs(); - networkTraces.put(internalTraceKey, currentTimestamp); + networkTraces.put(internalTraceKey, UtilsTime.monotonicTimeMs()); } /** @@ -246,6 +246,7 @@ void startNetworkRequestInternal(String networkTraceKey, String uniqueId) { */ void endNetworkRequestInternal(String networkTraceKey, String uniqueId, int responseCode, int requestPayloadSize, int responsePayloadSize) { //end time counting as fast as possible + long endMonotonicMs = UtilsTime.monotonicTimeMs(); long currentTimestamp = UtilsTime.currentTimestampMs(); L.d("[ModuleAPM] Calling 'endNetworkRequestInternal' with key:[" + networkTraceKey + "]"); @@ -263,12 +264,13 @@ void endNetworkRequestInternal(String networkTraceKey, String uniqueId, int resp String internalTraceKey = networkTraceKey + "|" + uniqueId; if (networkTraces.containsKey(internalTraceKey)) { - Long startTimestamp = networkTraces.remove(internalTraceKey); + Long startMonotonicMs = networkTraces.remove(internalTraceKey); - if (startTimestamp == null) { - L.e("[ModuleAPM] endNetworkRequestInternal, retrieved 'startTimestamp' is null"); + if (startMonotonicMs == null) { + L.e("[ModuleAPM] endNetworkRequestInternal, retrieved trace start is null"); } else { - recordNetworkRequestInternal(networkTraceKey, responseCode, requestPayloadSize, responsePayloadSize, startTimestamp, currentTimestamp); + long durationMs = endMonotonicMs - startMonotonicMs; + recordNetworkRequestInternal(networkTraceKey, responseCode, requestPayloadSize, responsePayloadSize, currentTimestamp - durationMs, currentTimestamp); } } else { L.w("[ModuleAPM] endNetworkRequestInternal, trying to end trace which was not started"); @@ -367,24 +369,25 @@ void doForegroundBackgroundCalculations(boolean goingToBackground, boolean going L.d("[ModuleAPM] Calling 'doForegroundBackgroundCalculations', [" + goingToBackground + "] [" + goingToForeground + "]"); if (goingToBackground || goingToForeground) { - long currentTimeMs = UtilsTime.currentTimestampMs(); + long currentMonotonicMs = UtilsTime.monotonicTimeMs(); if (lastScreenSwitchTime != -1) { // if it was '-1' then it just started, todo might be a issue with halt where it is only reset on first screen change - long durationMs = currentTimeMs - lastScreenSwitchTime; + long durationMs = currentMonotonicMs - lastScreenSwitchTime; + long currentTimeMs = UtilsTime.currentTimestampMs(); if (goingToForeground) { // coming from a background mode to the foreground - requestQueueProvider.sendAPMScreenTime(false, durationMs, lastScreenSwitchTime, currentTimeMs); + requestQueueProvider.sendAPMScreenTime(false, durationMs, currentTimeMs - durationMs, currentTimeMs); } else if (goingToBackground) { // going form the foreground to the background - requestQueueProvider.sendAPMScreenTime(true, durationMs, lastScreenSwitchTime, currentTimeMs); + requestQueueProvider.sendAPMScreenTime(true, durationMs, currentTimeMs - durationMs, currentTimeMs); } } else { L.d("[ModuleAPM] 'doForegroundBackgroundCalculations' last screen switch time was '-1', doing nothing"); } - lastScreenSwitchTime = currentTimeMs; + lastScreenSwitchTime = currentMonotonicMs; } else { L.d("[ModuleAPM] Calling 'doForegroundBackgroundCalculations', just changing screens, ignoring request"); // changing screens normally diff --git a/sdk/src/main/java/ly/count/android/sdk/ModuleEvents.java b/sdk/src/main/java/ly/count/android/sdk/ModuleEvents.java index dd15a8d88..a08d3961d 100644 --- a/sdk/src/main/java/ly/count/android/sdk/ModuleEvents.java +++ b/sdk/src/main/java/ly/count/android/sdk/ModuleEvents.java @@ -360,7 +360,9 @@ boolean startEventInternal(final String key) { } L.d("[ModuleEvents] Starting event: [" + key + "]"); UtilsTime.Instant instant = UtilsTime.getCurrentInstant(); - timedEvents.put(key, new Event(key, instant.timestampMs, instant.hour, instant.dow)); + Event timedEvent = new Event(key, instant.timestampMs, instant.hour, instant.dow); + timedEvent.monotonicStartMs = UtilsTime.monotonicTimeMs(); + timedEvents.put(key, timedEvent); return true; } @@ -385,8 +387,7 @@ boolean endEventInternal(@Nullable final String key, @Nullable final Map viewSegmentation = null; // segmentation that can be updated while a view is on @@ -223,7 +223,7 @@ void autoCloseRequiredViews(boolean closeAllViews, @Nullable Map ViewData currentViewData = new ViewData(); currentViewData.viewID = safeViewIDGenerator.GenerateValue(); currentViewData.viewName = viewName; - currentViewData.viewStartTimeSeconds = UtilsTime.currentTimestampSeconds(); + currentViewData.viewStartTimeSeconds = UtilsTime.monotonicTimeSeconds(); currentViewData.isAutoStoppedView = viewShouldBeAutomaticallyStopped; viewDataMap.put(currentViewData.viewID, currentViewData); @@ -294,7 +294,7 @@ void stopViewWithIDInternal(@Nullable String viewID, @Nullable Map customViewSeg } else if (vd.viewStartTimeSeconds == 0) { L.i("[ModuleViews] " + viewRecordingSource + ", view is either paused or didn't run, ignoring start timestamp"); } else { - lastElapsedDurationSeconds = UtilsTime.currentTimestampSeconds() - vd.viewStartTimeSeconds; + lastElapsedDurationSeconds = UtilsTime.monotonicTimeSeconds() - vd.viewStartTimeSeconds; } //only record view if the view name is not null @@ -415,7 +415,7 @@ void resumeViewWithIDInternal(String viewID) { return; } - vd.viewStartTimeSeconds = UtilsTime.currentTimestampSeconds(); + vd.viewStartTimeSeconds = UtilsTime.monotonicTimeSeconds(); } public void addSegmentationToViewWithIDInternal(@Nullable String viewID, @Nullable Map viewSegmentation) { diff --git a/sdk/src/main/java/ly/count/android/sdk/UtilsTime.java b/sdk/src/main/java/ly/count/android/sdk/UtilsTime.java index 99d731f6e..8ab567443 100644 --- a/sdk/src/main/java/ly/count/android/sdk/UtilsTime.java +++ b/sdk/src/main/java/ly/count/android/sdk/UtilsTime.java @@ -1,5 +1,6 @@ package ly.count.android.sdk; +import android.os.SystemClock; import java.util.ArrayList; import java.util.Calendar; import java.util.Collections; @@ -62,6 +63,26 @@ public static synchronized long getNanoTime() { return System.nanoTime(); } + /** + * Milliseconds since boot, including deep sleep, on a clock that a change of the device clock + * does not move. Only the difference between two values is meaningful, so durations are measured + * with it while timestamps stay on {@link #currentTimestampMs()}. + * + * @return monotonic time in milliseconds + */ + static long monotonicTimeMs() { + return SystemClock.elapsedRealtime(); + } + + /** + * Whole seconds of {@link #monotonicTimeMs()}, for durations reported in seconds. + * + * @return monotonic time in seconds + */ + static long monotonicTimeSeconds() { + return monotonicTimeMs() / 1000L; + } + /** * Utility method to return a current timestamp in seconds. */