Store time until next interaction metric
If the device rebooted while it was ready to reboot, the time
until next interaction will be the time between the device
becoming ready to reboot, and the first USER_PRESENT broadcast
sent after the reboot.
If it reboots while the device is not ready to reboot (i.e. organically),
then the logged value is the time between the device becoming ready to
reboot and not ready to reboot. This value is persisted in a file
during the previous boot.
Also adds logic to delete logging information if reboot readiness
checks are cancelled while the device is ready to reboot.
Test: atest RebootReadinessUnitTests
Test: Manual: inspect reboot-stats.xml
Test: Manual: reboot in both reboot readiness states, and verify
the UnattendedRebootOccurred atom that is logged
Bug: 192056476
Change-Id: Ic0febc8ea561736e80616c6ef564b069f7fe34f4
diff --git a/service/java/com/android/server/scheduling/RebootReadinessLogger.java b/service/java/com/android/server/scheduling/RebootReadinessLogger.java
index 1a10aae..61ed254 100644
--- a/service/java/com/android/server/scheduling/RebootReadinessLogger.java
+++ b/service/java/com/android/server/scheduling/RebootReadinessLogger.java
@@ -78,6 +78,9 @@
private int mTimesBlockedByAppActivity;
@GuardedBy("mLock")
+ private long mTimeUntilNextInteractionMs;
+
+ @GuardedBy("mLock")
private boolean mNeedsToLogMetrics;
@GuardedBy("mLock")
@@ -136,16 +139,7 @@
rebootStats.setTimesBlockedByInteractivity(timesBlockedByInteractivity);
rebootStats.setTimesBlockedBySubsystems(timesBlockedBySubsystems);
rebootStats.setTimesBlockedByAppActivity(timesBlockedByAppActivity);
- try (
- FileOutputStream stream = rebootStatsFile.startWrite()
- ) {
- XmlWriter writer = new XmlWriter(new PrintWriter(stream));
- XmlWriter.write(writer, rebootStats);
- writer.close();
- rebootStatsFile.finishWrite(stream);
- } catch (Exception e) {
- Log.e(TAG, "Could not write reboot readiness stats: " + e);
- }
+ writeRebootStatsToFile(rebootStats, rebootStatsFile);
}
}
@@ -164,6 +158,31 @@
}
/**
+ * Amend logging file when the device becomes not ready to reboot. If a logging file exists,
+ * add information about the time between the device becoming ready to reboot and subsequently
+ * not ready to reboot.
+ */
+ void writeAfterNotRebootReadyBroadcast() {
+ synchronized (mLock) {
+ AtomicFile rebootStatsFile = getRebootStatsFile();
+ if (rebootStatsFile != null) {
+ RebootStats rebootStats;
+ try (FileInputStream stream = rebootStatsFile.openRead()) {
+ rebootStats = XmlParser.read(stream);
+ } catch (Exception e) {
+ Log.e(TAG, "Could not read reboot readiness stats: " + e);
+ return;
+ }
+
+ mTimeUntilNextInteractionMs = System.currentTimeMillis() - mReadyTime;
+ rebootStats.setTimeUntilNextInteractionMs(mTimeUntilNextInteractionMs);
+ writeRebootStatsToFile(rebootStats, rebootStatsFile);
+ }
+
+ }
+ }
+
+ /**
* If any metrics were stored before the last reboot, reads them into local variables. These
* local variables will be logged when the device is first unlocked after reboot.
*/
@@ -178,6 +197,9 @@
mTimesBlockedByInteractivity = rebootStats.getTimesBlockedByInteractivity();
mTimesBlockedBySubsystems = rebootStats.getTimesBlockedBySubsystems();
mTimesBlockedByAppActivity = rebootStats.getTimesBlockedByAppActivity();
+ if (rebootStats.hasTimeUntilNextInteractionMs()) {
+ mTimeUntilNextInteractionMs = rebootStats.getTimeUntilNextInteractionMs();
+ }
mNeedsToLogMetrics = true;
} catch (Exception e) {
Log.e(TAG, "Could not read reboot readiness stats: " + e);
@@ -198,18 +220,24 @@
mNeedsToLogMetrics = false;
long timeToUnlockMs = SystemClock.elapsedRealtime();
long timeToRebootReadyMs = mReadyTime - mStartTime;
+ long timeToNextInteractionMs = System.currentTimeMillis() - mReadyTime;
+ if (mTimeUntilNextInteractionMs != 0) {
+ timeToNextInteractionMs = mTimeUntilNextInteractionMs;
+ }
Log.i(TAG, "UnattendedRebootOccurred"
+ " rebootReadyMs=" + timeToRebootReadyMs
+ " timeUntilFirstUnlockMs=" + timeToUnlockMs
+ " blockedByInteractivity=" + mTimesBlockedByInteractivity
+ " blockedBySubsystems=" + mTimesBlockedBySubsystems
- + " blockedByAppActivity=" + mTimesBlockedByAppActivity);
+ + " blockedByAppActivity=" + mTimesBlockedByAppActivity
+ + " timeToNextInteractionMs=" + timeToNextInteractionMs);
SchedulingStatsLog.write(SchedulingStatsLog.UNATTENDED_REBOOT_OCCURRED,
timeToRebootReadyMs,
timeToUnlockMs,
mTimesBlockedByAppActivity,
mTimesBlockedBySubsystems,
- mTimesBlockedByInteractivity);
+ mTimesBlockedByInteractivity,
+ timeToNextInteractionMs);
mShouldDumpMetrics = true;
}
}
@@ -309,6 +337,17 @@
}
}
+ private void writeRebootStatsToFile(RebootStats rebootStats, AtomicFile rebootStatsFile) {
+ try (FileOutputStream stream = rebootStatsFile.startWrite()) {
+ XmlWriter writer = new XmlWriter(new PrintWriter(stream));
+ XmlWriter.write(writer, rebootStats);
+ writer.close();
+ rebootStatsFile.finishWrite(stream);
+ } catch (Exception e) {
+ Log.e(TAG, "Could not write reboot readiness stats: " + e);
+ }
+ }
+
void dump(PrintWriter pw) {
synchronized (mLock) {
if (mBlockingComponents.size() > 0) {
@@ -326,6 +365,7 @@
pw.println(" Times blocked by interactivity " + mTimesBlockedByInteractivity);
pw.println(" Times blocked by subsystems " + mTimesBlockedBySubsystems);
pw.println(" Times blocked by app activity " + mTimesBlockedByAppActivity);
+ pw.println(" Time until next interaction " + mTimeUntilNextInteractionMs);
}
}
}
diff --git a/service/java/com/android/server/scheduling/RebootReadinessManagerService.java b/service/java/com/android/server/scheduling/RebootReadinessManagerService.java
index 94683e5..b480857 100644
--- a/service/java/com/android/server/scheduling/RebootReadinessManagerService.java
+++ b/service/java/com/android/server/scheduling/RebootReadinessManagerService.java
@@ -306,6 +306,11 @@
mHandler.removeCallbacksAndMessages(null);
mAlarmManager.cancel(mPollStateListener);
mCanceled = true;
+ // Delete any logging information if the device is ready to reboot, since an
+ // unattended reboot should not take place if the checks are cancelled.
+ if (mReadyToReboot) {
+ mRebootReadinessLogger.deleteLoggingInformation();
+ }
mReadyToReboot = false;
}
} else {
@@ -509,7 +514,7 @@
}
}
} else {
- mRebootReadinessLogger.deleteLoggingInformation();
+ mRebootReadinessLogger.writeAfterNotRebootReadyBroadcast();
}
}
}
diff --git a/service/reboot-stats-parser/Android.bp b/service/reboot-stats-parser/Android.bp
index 4962a84..c4703e7 100644
--- a/service/reboot-stats-parser/Android.bp
+++ b/service/reboot-stats-parser/Android.bp
@@ -20,5 +20,6 @@
name: "reboot-stats-parser",
srcs: ["reboot_stats_manifest.xsd"],
package_name: "com.android.server.scheduling",
+ api_dir: "schema",
gen_writer: true,
}
diff --git a/service/reboot-stats-parser/reboot_stats_manifest.xsd b/service/reboot-stats-parser/reboot_stats_manifest.xsd
index f416e39..39e0d4c 100644
--- a/service/reboot-stats-parser/reboot_stats_manifest.xsd
+++ b/service/reboot-stats-parser/reboot_stats_manifest.xsd
@@ -24,6 +24,7 @@
<xsd:element name="timesBlockedByInteractivity" type="xsd:int"/>
<xsd:element name="timesBlockedByAppActivity" type="xsd:int"/>
<xsd:element name="timesBlockedBySubsystems" type="xsd:int"/>
+ <xsd:element name="timeUntilNextInteractionMs" type="xsd:long"/>
</xsd:sequence>
</xsd:complexType>
</xsd:element>
diff --git a/service/reboot-stats-parser/api/current.txt b/service/reboot-stats-parser/schema/current.txt
similarity index 92%
rename from service/reboot-stats-parser/api/current.txt
rename to service/reboot-stats-parser/schema/current.txt
index 75da6eb..f42ffb6 100644
--- a/service/reboot-stats-parser/api/current.txt
+++ b/service/reboot-stats-parser/schema/current.txt
@@ -5,11 +5,13 @@
ctor public RebootStats();
method public long getReadyTimeMs();
method public long getStartTimeMs();
+ method public long getTimeUntilNextInteractionMs();
method public int getTimesBlockedByAppActivity();
method public int getTimesBlockedByInteractivity();
method public int getTimesBlockedBySubsystems();
method public void setReadyTimeMs(long);
method public void setStartTimeMs(long);
+ method public void setTimeUntilNextInteractionMs(long);
method public void setTimesBlockedByAppActivity(int);
method public void setTimesBlockedByInteractivity(int);
method public void setTimesBlockedBySubsystems(int);
diff --git a/service/reboot-stats-parser/api/last_current.txt b/service/reboot-stats-parser/schema/last_current.txt
similarity index 100%
rename from service/reboot-stats-parser/api/last_current.txt
rename to service/reboot-stats-parser/schema/last_current.txt
diff --git a/service/reboot-stats-parser/api/last_removed.txt b/service/reboot-stats-parser/schema/last_removed.txt
similarity index 100%
rename from service/reboot-stats-parser/api/last_removed.txt
rename to service/reboot-stats-parser/schema/last_removed.txt
diff --git a/service/reboot-stats-parser/api/removed.txt b/service/reboot-stats-parser/schema/removed.txt
similarity index 100%
rename from service/reboot-stats-parser/api/removed.txt
rename to service/reboot-stats-parser/schema/removed.txt
diff --git a/tests/unittests/src/com/android/server/scheduling/RebootReadinessUnitTest.java b/tests/unittests/src/com/android/server/scheduling/RebootReadinessUnitTest.java
index b6da0ee..ff4c84c 100644
--- a/tests/unittests/src/com/android/server/scheduling/RebootReadinessUnitTest.java
+++ b/tests/unittests/src/com/android/server/scheduling/RebootReadinessUnitTest.java
@@ -30,7 +30,6 @@
import static org.mockito.ArgumentMatchers.eq;
import static org.mockito.Mockito.atLeastOnce;
-import static org.mockito.Mockito.never;
import static org.mockito.Mockito.spy;
import static org.mockito.Mockito.times;
@@ -112,6 +111,9 @@
@Captor
private ArgumentCaptor<Integer> mIntCaptor;
+ @Captor
+ private ArgumentCaptor<Long> mLongCaptor;
+
private MockitoSession mSession;
@@ -425,14 +427,15 @@
mLogger.readMetricsPostReboot();
mLogger.writePostRebootMetrics();
verify(() -> SchedulingStatsLog.write(eq(SchedulingStatsLog.UNATTENDED_REBOOT_OCCURRED),
- eq(1000L), anyLong(), eq(0), eq(0), eq(0)));
+ eq(1000L), anyLong(), eq(0), eq(0), eq(0), anyLong()));
}
/**
- * Test that no metrics are logged if the device became not ready to reboot before rebooting.
+ * Test that logging information is correctly written in the case that the device becomes not
+ * ready to reboot.
*/
@Test
- public void testMetricsClearedWhenNotReadyToReboot() throws Exception {
+ public void testMetricsLoggedWhenNotReadyToReboot() throws Exception {
mService.markRebootPending(TEST_PACKAGE);
Thread.sleep(STATE_CHANGE_DELAY);
assertThat(mService.isReadyToReboot()).isTrue();
@@ -448,8 +451,13 @@
// The device has become not ready to reboot, therefore no metrics should be logged.
mLogger.readMetricsPostReboot();
mLogger.writePostRebootMetrics();
+
+ // Verify that the time_to_next_interaction_millis field is correctly populated.
verify(() -> SchedulingStatsLog.write(eq(SchedulingStatsLog.UNATTENDED_REBOOT_OCCURRED),
- anyLong(), anyLong(), anyInt(), anyInt(), anyInt()), never());
+ anyLong(), anyLong(), anyInt(), anyInt(),
+ anyInt(), mLongCaptor.capture()), times(1));
+ assertThat(mLongCaptor.getValue()).isGreaterThan(STATE_CHANGE_DELAY + DEVICE_CONFIG_DELAY);
+ assertThat(mLongCaptor.getValue()).isLessThan(TimeUnit.MINUTES.toMillis(1));
}
/**
