Merge "Added tron metrics for shutdown time" into oc-mr1-dev
diff --git a/core/java/com/android/server/BootReceiver.java b/core/java/com/android/server/BootReceiver.java
index 18990cf..4354486 100644
--- a/core/java/com/android/server/BootReceiver.java
+++ b/core/java/com/android/server/BootReceiver.java
@@ -31,13 +31,13 @@
import android.os.SystemProperties;
import android.os.storage.StorageManager;
import android.provider.Downloads;
+import android.text.TextUtils;
import android.util.AtomicFile;
import android.util.Slog;
import android.util.Xml;
import com.android.internal.annotations.VisibleForTesting;
import com.android.internal.logging.MetricsLogger;
-import com.android.internal.util.ArrayUtils;
import com.android.internal.util.FastXmlSerializer;
import com.android.internal.util.XmlUtils;
@@ -106,6 +106,11 @@
"powerctl_shutdown_time_ms:([0-9]+):([0-9]+)";
private static final int UMOUNT_STATUS_NOT_AVAILABLE = 4; // should match with init/reboot.h
+ // Location of file with metrics recorded during shutdown
+ private static final String SHUTDOWN_METRICS_FILE = "/data/system/shutdown-metrics.txt";
+
+ private static final String SHUTDOWN_TRON_METRICS_PREFIX = "shutdown_";
+
@Override
public void onReceive(final Context context, Intent intent) {
// Log boot events in the background to avoid blocking the main thread with I/O
@@ -232,6 +237,7 @@
logFsShutdownTime();
logFsMountTime();
addFsckErrorsToDropBoxAndLogFsStat(db, timestamps, headers, -LOG_SIZE, "SYSTEM_FSCK");
+ logSystemServerShutdownTimeMetrics();
// Scan existing tombstones (in case any new ones appeared)
File[] tombstoneFiles = TOMBSTONE_DIR.listFiles();
@@ -380,6 +386,47 @@
}
}
+ // TODO b/64815357 Move to bootstat.cpp and log AbsoluteRebootTime
+ private static void logSystemServerShutdownTimeMetrics() {
+ File metricsFile = new File(SHUTDOWN_METRICS_FILE);
+ String metricsStr = null;
+ if (metricsFile.exists()) {
+ try {
+ metricsStr = FileUtils.readTextFile(metricsFile, 0, null);
+ } catch (IOException e) {
+ Slog.e(TAG, "Problem reading " + metricsFile, e);
+ }
+ }
+ if (!TextUtils.isEmpty(metricsStr)) {
+ String[] array = metricsStr.split(",");
+ for (String keyValueStr : array) {
+ String[] keyValue = keyValueStr.split(":");
+ if (keyValue.length != 2) {
+ Slog.e(TAG, "Wrong format of shutdown metrics - " + metricsStr);
+ continue;
+ }
+ // Ignore keys that are not indended for tron
+ if (keyValue[0].startsWith(SHUTDOWN_TRON_METRICS_PREFIX)) {
+ logTronShutdownMetric(keyValue[0], keyValue[1]);
+ }
+ }
+ }
+ metricsFile.delete();
+ }
+
+ private static void logTronShutdownMetric(String metricName, String valueStr) {
+ int value;
+ try {
+ value = Integer.parseInt(valueStr);
+ } catch (NumberFormatException e) {
+ Slog.e(TAG, "Cannot parse metric " + metricName + " int value - " + valueStr);
+ return;
+ }
+ if (value >= 0) {
+ MetricsLogger.histogram(null, metricName, value);
+ }
+ }
+
private static void logFsShutdownTime() {
File f = null;
for (String fileName : LAST_KMSG_FILES) {
diff --git a/services/core/java/com/android/server/power/ShutdownThread.java b/services/core/java/com/android/server/power/ShutdownThread.java
index 63900e0..0867a6c 100644
--- a/services/core/java/com/android/server/power/ShutdownThread.java
+++ b/services/core/java/com/android/server/power/ShutdownThread.java
@@ -51,6 +51,7 @@
import android.os.Vibrator;
import android.os.storage.IStorageManager;
import android.os.storage.IStorageShutdownObserver;
+import android.util.ArrayMap;
import android.util.Log;
import android.util.TimingsTraceLog;
import android.view.WindowManager;
@@ -62,7 +63,9 @@
import com.android.server.statusbar.StatusBarManagerInternal;
import java.io.File;
+import java.io.FileOutputStream;
import java.io.IOException;
+import java.nio.charset.StandardCharsets;
public final class ShutdownThread extends Thread {
// constants
@@ -110,6 +113,23 @@
private static final TimingsTraceLog SHUTDOWN_TIMINGS_LOG = new TimingsTraceLog(
"ShutdownTiming", Trace.TRACE_TAG_SYSTEM_SERVER);
+ // Metrics that will be reported to tron after reboot
+ private static final ArrayMap<String, Long> TRON_METRICS = new ArrayMap<>();
+
+ // File to use for save metrics
+ private static final String METRICS_FILE_BASENAME = "/data/system/shutdown-metrics";
+
+ // Metrics names to be persisted in shutdown-metrics file
+ private static String METRIC_SYSTEM_SERVER = "shutdown_system_server";
+ private static String METRIC_SEND_BROADCAST = "shutdown_send_shutdown_broadcast";
+ private static String METRIC_AM = "shutdown_activity_manager";
+ private static String METRIC_PM = "shutdown_package_manager";
+ private static String METRIC_RADIOS = "shutdown_radios";
+ private static String METRIC_BT = "shutdown_bt";
+ private static String METRIC_RADIO = "shutdown_radio";
+ private static String METRIC_NFC = "shutdown_nfc";
+ private static String METRIC_SM = "shutdown_storage_manager";
+
private final Object mActionDoneSync = new Object();
private boolean mActionDone;
private Context mContext;
@@ -349,6 +369,7 @@
private static void beginShutdownSequence(Context context) {
SHUTDOWN_TIMINGS_LOG.traceBegin("SystemServerShutdown");
+ metricStarted(METRIC_SYSTEM_SERVER);
synchronized (sIsStartedGuard) {
if (sIsStarted) {
Log.d(TAG, "Shutdown sequence already running, returning.");
@@ -430,6 +451,7 @@
SystemProperties.set(REBOOT_SAFEMODE_PROPERTY, "1");
}
+ metricStarted(METRIC_SEND_BROADCAST);
SHUTDOWN_TIMINGS_LOG.traceBegin("SendShutdownBroadcast");
Log.i(TAG, "Sending shutdown broadcast...");
@@ -463,9 +485,11 @@
sInstance.setRebootProgress(BROADCAST_STOP_PERCENT, null);
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // SendShutdownBroadcast
+ metricEnded(METRIC_SEND_BROADCAST);
Log.i(TAG, "Shutting down activity manager...");
SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownActivityManager");
+ metricStarted(METRIC_AM);
final IActivityManager am =
IActivityManager.Stub.asInterface(ServiceManager.checkService("activity"));
@@ -478,10 +502,12 @@
if (mRebootHasProgressBar) {
sInstance.setRebootProgress(ACTIVITY_MANAGER_STOP_PERCENT, null);
}
- SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownActivityManager
+ SHUTDOWN_TIMINGS_LOG.traceEnd();// ShutdownActivityManager
+ metricEnded(METRIC_AM);
Log.i(TAG, "Shutting down package manager...");
SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownPackageManager");
+ metricStarted(METRIC_PM);
final PackageManagerService pm = (PackageManagerService)
ServiceManager.getService("package");
@@ -492,14 +518,17 @@
sInstance.setRebootProgress(PACKAGE_MANAGER_STOP_PERCENT, null);
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownPackageManager
+ metricEnded(METRIC_PM);
// Shutdown radios.
SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownRadios");
+ metricStarted(METRIC_RADIOS);
shutdownRadios(MAX_RADIO_WAIT_TIME);
if (mRebootHasProgressBar) {
sInstance.setRebootProgress(RADIO_STOP_PERCENT, null);
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownRadios
+ metricEnded(METRIC_RADIOS);
// Shutdown StorageManagerService to ensure media is in a safe state
IStorageShutdownObserver observer = new IStorageShutdownObserver.Stub() {
@@ -511,6 +540,7 @@
Log.i(TAG, "Shutting down StorageManagerService");
SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownStorageManager");
+ metricStarted(METRIC_SM);
// Set initial variables and time out time.
mActionDone = false;
@@ -546,6 +576,7 @@
}
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownStorageManager
+ metricEnded(METRIC_SM);
if (mRebootHasProgressBar) {
sInstance.setRebootProgress(MOUNT_SERVICE_STOP_PERCENT, null);
@@ -558,6 +589,14 @@
rebootOrShutdown(mContext, mReboot, mReason);
}
+ private static void metricStarted(String metricKey) {
+ TRON_METRICS.put(metricKey, -1 * SystemClock.elapsedRealtime());
+ }
+
+ private static void metricEnded(String metricKey) {
+ TRON_METRICS.put(metricKey, SystemClock.elapsedRealtime() + TRON_METRICS.get(metricKey));
+ }
+
private void setRebootProgress(final int progress, final CharSequence message) {
mHandler.post(new Runnable() {
@Override
@@ -590,12 +629,12 @@
final IBluetoothManager bluetooth =
IBluetoothManager.Stub.asInterface(ServiceManager.checkService(
BluetoothAdapter.BLUETOOTH_MANAGER_SERVICE));
- final long nfcShutdownStarted = SystemClock.elapsedRealtime();
try {
nfcOff = nfc == null ||
nfc.getState() == NfcAdapter.STATE_OFF;
if (!nfcOff) {
Log.w(TAG, "Turning off NFC...");
+ metricStarted(METRIC_NFC);
nfc.disable(false); // Don't persist new state
}
} catch (RemoteException ex) {
@@ -603,12 +642,12 @@
nfcOff = true;
}
- final long btShutdownStarted = SystemClock.elapsedRealtime();
try {
bluetoothReadyForShutdown = bluetooth == null ||
bluetooth.getState() == BluetoothAdapter.STATE_OFF;
if (!bluetoothReadyForShutdown) {
Log.w(TAG, "Disabling Bluetooth...");
+ metricStarted(METRIC_BT);
bluetooth.disable(mContext.getPackageName(), false); // disable but don't persist new state
}
} catch (RemoteException ex) {
@@ -616,11 +655,11 @@
bluetoothReadyForShutdown = true;
}
- final long radioShutdownStarted = SystemClock.elapsedRealtime();
try {
radioOff = phone == null || !phone.needMobileRadioShutdown();
if (!radioOff) {
Log.w(TAG, "Turning off cellular radios...");
+ metricStarted(METRIC_RADIO);
phone.shutdownMobileRadios();
}
} catch (RemoteException ex) {
@@ -653,8 +692,9 @@
}
if (bluetoothReadyForShutdown) {
Log.i(TAG, "Bluetooth turned off.");
- SHUTDOWN_TIMINGS_LOG.logDuration("ShutdownBt",
- SystemClock.elapsedRealtime() - btShutdownStarted);
+ metricEnded(METRIC_BT);
+ SHUTDOWN_TIMINGS_LOG
+ .logDuration("ShutdownBt", TRON_METRICS.get(METRIC_BT));
}
}
if (!radioOff) {
@@ -666,8 +706,9 @@
}
if (radioOff) {
Log.i(TAG, "Radio turned off.");
- SHUTDOWN_TIMINGS_LOG.logDuration("ShutdownRadio",
- SystemClock.elapsedRealtime() - radioShutdownStarted);
+ metricEnded(METRIC_RADIO);
+ SHUTDOWN_TIMINGS_LOG
+ .logDuration("ShutdownRadio", TRON_METRICS.get(METRIC_RADIO));
}
}
if (!nfcOff) {
@@ -679,8 +720,9 @@
}
if (nfcOff) {
Log.i(TAG, "NFC turned off.");
- SHUTDOWN_TIMINGS_LOG.logDuration("ShutdownNfc",
- SystemClock.elapsedRealtime() - nfcShutdownStarted);
+ metricEnded(METRIC_NFC);
+ SHUTDOWN_TIMINGS_LOG
+ .logDuration("ShutdownNfc", TRON_METRICS.get(METRIC_NFC));
}
}
@@ -708,7 +750,7 @@
/**
* Do not call this directly. Use {@link #reboot(Context, String, boolean)}
- * or {@link #shutdown(Context, boolean)} instead.
+ * or {@link #shutdown(Context, String, boolean)} instead.
*
* @param context Context used to vibrate or null without vibration
* @param reboot true to reboot or false to shutdown
@@ -716,6 +758,8 @@
*/
public static void rebootOrShutdown(final Context context, boolean reboot, String reason) {
SHUTDOWN_TIMINGS_LOG.traceEnd(); // SystemServerShutdown
+ metricEnded(METRIC_SYSTEM_SERVER);
+ saveMetrics(reboot);
if (reboot) {
Log.i(TAG, "Rebooting, reason: " + reason);
PowerManagerService.lowLevelReboot(reason);
@@ -742,6 +786,33 @@
PowerManagerService.lowLevelShutdown(reason);
}
+ private static void saveMetrics(boolean reboot) {
+ StringBuilder metricValue = new StringBuilder();
+ metricValue.append("reboot:");
+ metricValue.append(reboot ? "y" : "n");
+ final int metricsSize = TRON_METRICS.size();
+ for (int i = 0; i < metricsSize; i++) {
+ final String name = TRON_METRICS.keyAt(i);
+ final long value = TRON_METRICS.valueAt(i);
+ if (value < 0) {
+ Log.e(TAG, "metricEnded wasn't called for " + name);
+ continue;
+ }
+ metricValue.append(',').append(name).append(':').append(value);
+ }
+ File tmp = new File(METRICS_FILE_BASENAME + ".tmp");
+ boolean saved = false;
+ try (FileOutputStream fos = new FileOutputStream(tmp)) {
+ fos.write(metricValue.toString().getBytes(StandardCharsets.UTF_8));
+ saved = true;
+ } catch (IOException e) {
+ Log.e(TAG,"Cannot save shutdown metrics", e);
+ }
+ if (saved) {
+ tmp.renameTo(new File(METRICS_FILE_BASENAME + ".txt"));
+ }
+ }
+
private void uncrypt() {
Log.i(TAG, "Calling uncrypt and monitoring the progress...");