Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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":
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}

Expand Down Expand Up @@ -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());
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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());
Expand Down
73 changes: 63 additions & 10 deletions sdk/src/androidTest/java/ly/count/android/sdk/ModuleAPMTests.java
Original file line number Diff line number Diff line change
Expand Up @@ -146,29 +146,27 @@ 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);

Assert.assertFalse(mCountly.moduleAPM.networkTraces.containsKey(internalTraceKey));

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);

Expand All @@ -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<Long> duration = ArgumentCaptor.forClass(Long.class);
ArgumentCaptor<Long> start = ArgumentCaptor.forClass(Long.class);
ArgumentCaptor<Long> 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<Long> duration = ArgumentCaptor.forClass(Long.class);
ArgumentCaptor<Long> start = ArgumentCaptor.forClass(Long.class);
ArgumentCaptor<Long> 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<Long> duration = ArgumentCaptor.forClass(Long.class);
ArgumentCaptor<Long> start = ArgumentCaptor.forClass(Long.class);
ArgumentCaptor<Long> 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
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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<UtilsTime.Instant> arg = ArgumentCaptor.forClass(UtilsTime.Instant.class);
ArgumentCaptor<Double> 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));
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
14 changes: 7 additions & 7 deletions sdk/src/androidTest/java/ly/count/android/sdk/TestUtils.java
Original file line number Diff line number Diff line change
Expand Up @@ -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.
* <p>
* 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".
Expand All @@ -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) {
Expand Down Expand Up @@ -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.
Expand Down
4 changes: 2 additions & 2 deletions sdk/src/main/java/ly/count/android/sdk/DeviceInfo.java
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
}
};
}
Expand Down
1 change: 1 addition & 0 deletions sdk/src/main/java/ly/count/android/sdk/Event.java
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
}
Expand Down
Loading
Loading