From 291f63bb548473a75d3053927c0a94c9af11e28b Mon Sep 17 00:00:00 2001 From: Fyodor Kupolov Date: Fri, 25 Aug 2017 16:59:08 -0700 Subject: [PATCH] Added tron metrics for shutdown time The metrics are persisted in /data/system/shutdown-metrics.txt file property and logged after reboot. MetricsLogger API cannot be directly used during shutdown since event log is cleared on reboot/power off. Test: manual reboot/shutdown and verify that metrics are logged Bug: 64815357 Change-Id: I7fa1af8be58a80a3d5bae26d55c1ed40bf98f4c0 --- core/java/com/android/server/BootReceiver.java | 49 +++++++++++- .../com/android/server/power/ShutdownThread.java | 93 +++++++++++++++++++--- 2 files changed, 130 insertions(+), 12 deletions(-) diff --git a/core/java/com/android/server/BootReceiver.java b/core/java/com/android/server/BootReceiver.java index 18990cff1f83..43544862b5ec 100644 --- a/core/java/com/android/server/BootReceiver.java +++ b/core/java/com/android/server/BootReceiver.java @@ -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) { diff --git a/services/core/java/com/android/server/power/ShutdownThread.java b/services/core/java/com/android/server/power/ShutdownThread.java index 63900e0eb067..0867a6c66b70 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.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 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")); @@ -478,10 +502,12 @@ public final class ShutdownThread extends Thread { 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 @@ 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..."); -- 2.11.0