Merge "Added tron metrics for shutdown time" into oc-mr1-dev (8908b418) · Commits · e / os / android_frameworks_base

core/java/com/android/server/BootReceiver.java

+48 −1

Original line number	Diff line number	Diff line
		@@ -31,13 +31,13 @@ import android.os.ServiceManager;
		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 @@ public class BootReceiver extends BroadcastReceiver {
		"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 @@ public class BootReceiver extends BroadcastReceiver {
		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 @@ public class BootReceiver extends BroadcastReceiver {
		}
		}

		// 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) {

services/core/java/com/android/server/power/ShutdownThread.java

+82 −11

Original line number	Diff line number	Diff line
		@@ -51,6 +51,7 @@ import android.os.UserManager;
		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.pm.PackageManagerService;
		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 @@ public final class ShutdownThread extends Thread {
		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 @@ public final class ShutdownThread extends Thread {

		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 @@ public final class ShutdownThread extends Thread {
		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 @@ public final class ShutdownThread extends Thread {
		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"));
		@@ -479,9 +503,11 @@ public final class ShutdownThread extends Thread {
		sInstance.setRebootProgress(ACTIVITY_MANAGER_STOP_PERCENT, null);
		}
		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 @@ public final class ShutdownThread extends Thread {
		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 @@ public final class ShutdownThread extends Thread {

		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 @@ public final class ShutdownThread extends Thread {
		}
		}
		SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownStorageManager
		metricEnded(METRIC_SM);

		if (mRebootHasProgressBar) {
		sInstance.setRebootProgress(MOUNT_SERVICE_STOP_PERCENT, null);
		@@ -558,6 +589,14 @@ public final class ShutdownThread extends Thread {
		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 @@ public final class ShutdownThread extends Thread {
		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 @@ public final class ShutdownThread extends Thread {
		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 @@ public final class ShutdownThread extends Thread {
		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 @@ public final class ShutdownThread extends Thread {
		}
		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 @@ public final class ShutdownThread extends Thread {
		}
		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 @@ public final class ShutdownThread extends Thread {
		}
		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 @@ public final class ShutdownThread extends Thread {

		/**
		* 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 final class ShutdownThread extends Thread {
		*/
		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 @@ public final class ShutdownThread extends Thread {
		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...");