Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 291f63bb authored by Fyodor Kupolov's avatar Fyodor Kupolov
Browse files

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
parent d1736cb2

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