server/scheduling/RebootReadinessLogger.java

/*
 * Copyright (C) 2021 The Android Open Source Project
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */

package com.android.server.scheduling;

import static com.android.server.scheduling.SchedulingStatsLog.LONG_REBOOT_BLOCKING_REPORTED;
import static com.android.server.scheduling.SchedulingStatsLog.LONG_REBOOT_BLOCKING_REPORTED__REBOOT_BLOCK_REASON__APP_UID;
import static com.android.server.scheduling.SchedulingStatsLog.LONG_REBOOT_BLOCKING_REPORTED__REBOOT_BLOCK_REASON__SYSTEM_COMPONENT;

import android.annotation.CurrentTimeMillisLong;
import android.annotation.IntDef;
import android.content.ApexEnvironment;
import android.content.Context;
import android.content.pm.PackageManager;
import android.os.SystemClock;
import android.util.ArrayMap;
import android.util.AtomicFile;
import android.util.Log;
import android.util.SparseArray;

import com.android.internal.annotations.GuardedBy;
import com.android.internal.annotations.VisibleForTesting;

import java.io.File;
import java.io.FileInputStream;
import java.io.FileOutputStream;
import java.io.PrintWriter;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.util.ArrayList;
import java.util.List;


/**
 * Class for handling the storage of logging information related to reboot readiness.
 */
final class RebootReadinessLogger {
    private static final String TAG = "RebootReadinessLogger";

    private static final String MODULE_NAME = "com.android.scheduling";

    private static final String REBOOT_STATS_FILE = "reboot-readiness/reboot-stats.xml";

    private final Object mLock = new Object();

    @GuardedBy("mLock")
    private final SparseArray<BlockingEntityRecord> mBlockingApps = new SparseArray<>();

    @GuardedBy("mLock")
    private final ArrayMap<String, BlockingEntityRecord> mBlockingComponents = new ArrayMap<>();

    @GuardedBy("mLock")
    private long mStartTime;

    @GuardedBy("mLock")
    private long mReadyTime;

    @GuardedBy("mLock")
    private int mTimesBlockedByInteractivity;

    @GuardedBy("mLock")
    private int mTimesBlockedBySubsystems;

    @GuardedBy("mLock")
    private int mTimesBlockedByAppActivity;

    @GuardedBy("mLock")
    private long mTimeUntilNextInteractionMs;

    @GuardedBy("mLock")
    private boolean mNeedsToLogMetrics;

    @GuardedBy("mLock")
    private boolean mShouldDumpMetrics;

    // Directory for storing reboot readiness metrics. By default, this is the module's DE
    // data directory, but a different directory may be injected for testing purposes.
    private final File mDeDir;

    private final Context mContext;

    private final PackageManager mPackageManager;

    @VisibleForTesting
    RebootReadinessLogger(File deDir, Context context) {
        mDeDir = deDir;
        mContext = context;
        mPackageManager = mContext.getPackageManager();
    }

    RebootReadinessLogger(Context context) {
        mDeDir = ApexEnvironment.getApexEnvironment(MODULE_NAME).getDeviceProtectedDataDir();
        mContext = context;
        mPackageManager = mContext.getPackageManager();
    }

    /**
     * Persists important information about recent reboot readiness checks. This information is
     * stored when the device first becomes reboot-ready.
     *
     * @param startTime the time the reboot readiness state started to be polled
     * @param readyTime the time the device became reboot-ready
     * @param timesBlockedByInteractivity the number of times the reboot was blocked by device
     *                                    interactivity
     * @param timesBlockedBySubsystems the number of times the reboot was blocked by subsystems
     *                                 that registered callbacks
     * @param timesBlockedByAppActivity the number of times the reboot was blocked by background
     *                                  app activity
     */
    void writeAfterRebootReadyBroadcast(@CurrentTimeMillisLong long startTime,
            @CurrentTimeMillisLong long readyTime, int timesBlockedByInteractivity,
            int timesBlockedBySubsystems, int timesBlockedByAppActivity) {
        synchronized (mLock) {
            AtomicFile rebootStatsFile = new AtomicFile(new File(mDeDir, REBOOT_STATS_FILE));

            mStartTime = startTime;
            mReadyTime = readyTime;
            mTimesBlockedByInteractivity = timesBlockedByInteractivity;
            mTimesBlockedBySubsystems = timesBlockedBySubsystems;
            mTimesBlockedByAppActivity = timesBlockedByAppActivity;
            mShouldDumpMetrics = true;

            RebootStats rebootStats = new RebootStats();
            rebootStats.setStartTimeMs(startTime);
            rebootStats.setReadyTimeMs(readyTime);
            rebootStats.setTimesBlockedByInteractivity(timesBlockedByInteractivity);
            rebootStats.setTimesBlockedBySubsystems(timesBlockedBySubsystems);
            rebootStats.setTimesBlockedByAppActivity(timesBlockedByAppActivity);
            writeRebootStatsToFile(rebootStats, rebootStatsFile);
        }
    }

    /**
     * Deletes any information that would have been logged post-reboot. This is called when
     * the device becomes not ready to reboot.
     */
    void deleteLoggingInformation() {
        synchronized (mLock) {
            AtomicFile rebootStatsFile = getRebootStatsFile();
            if (rebootStatsFile != null) {
                rebootStatsFile.delete();
                mNeedsToLogMetrics = false;
            }
        }
    }

    /**
     * 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.
     */
    void readMetricsPostReboot() {
        synchronized (mLock) {
            AtomicFile rebootStatsFile = getRebootStatsFile();
            if (rebootStatsFile != null) {
                try (FileInputStream stream = rebootStatsFile.openRead()) {
                    RebootStats rebootStats = XmlParser.read(stream);
                    mReadyTime = rebootStats.getReadyTimeMs();
                    mStartTime = rebootStats.getStartTimeMs();
                    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);
                } finally {
                    rebootStatsFile.delete();
                }
            }
        }
    }

    /**
     * Logs metrics which have been stored across reboots, if any exist. This method will be called
     * after the first time the device is unlocked after reboot.
     */
    void writePostRebootMetrics() {
        synchronized (mLock) {
            if (mNeedsToLogMetrics) {
                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
                        + " timeToNextInteractionMs=" + timeToNextInteractionMs);
                SchedulingStatsLog.write(SchedulingStatsLog.UNATTENDED_REBOOT_OCCURRED,
                        timeToRebootReadyMs,
                        timeToUnlockMs,
                        mTimesBlockedByAppActivity,
                        mTimesBlockedBySubsystems,
                        mTimesBlockedByInteractivity,
                        timeToNextInteractionMs);
                mShouldDumpMetrics = true;
            }
        }
    }

    /**
     * Tracks any components which are currently blocking the reboot. If any of the components have
     * been blocking the reboot for longer than the given threshold, this information will be logged
     * to SchedulingStatsLog. Any components which previously blocked the reboot but are currently
     * not blocking the reboot will be pruned from the set of tracked components.
     *
     * @param blockingComponentNames list of component names which are blocking the reboot.
     * @param thresholdMs the time a component may block the reboot for before being logged.
     */
    void maybeLogLongBlockingComponents(List<String> blockingComponentNames, long thresholdMs) {
        synchronized (mLock) {
            for (String component : blockingComponentNames) {
                BlockingEntityRecord record = mBlockingComponents.get(component);
                if (record == null) {
                    record = new BlockingEntityRecord(component);
                    mBlockingComponents.put(component, record);
                }
                record.logLongRebootBlockingIfNecessary(thresholdMs);
            }

            for (String existingRecordName : mBlockingComponents.keySet()) {
                if (!blockingComponentNames.contains(existingRecordName)) {
                    mBlockingComponents.remove(existingRecordName);
                }
            }
        }
    }

    /**
     * Tracks any app uids which are currently blocking the reboot. If any of the apps have been
     * blocking the reboot for longer than the given threshold, this information will be logged
     * to SchedulingStatsLog. Any apps which previously blocked the reboot but are currently
     * not blocking the reboot will be pruned from the set of tracked uids.
     *
     * @param blockingAppUids list of app uids which are blocking the reboot.
     * @param thresholdMs the time an app may block the reboot for before being logged.
     *
     * TODO(b/184165442): Use IntArray instead.
     */
    void maybeLogLongBlockingApps(List<Integer> blockingAppUids, long thresholdMs) {
        synchronized (mLock) {
            for (Integer uid : blockingAppUids) {
                BlockingEntityRecord record = mBlockingApps.get(uid);
                if (record == null) {
                    record = new BlockingEntityRecord(uid);
                    mBlockingApps.put(uid, record);
                }
                record.logLongRebootBlockingIfNecessary(thresholdMs);
            }

            List<Integer> uidsToPrune = new ArrayList<>();
            for (int i = 0; i < mBlockingApps.size(); i++) {
                int uid = mBlockingApps.keyAt(i);
                if (!blockingAppUids.contains(uid)) {
                    uidsToPrune.add(uid);
                }
            }

            for (Integer uid : uidsToPrune) {
                mBlockingApps.remove(uid);
            }
        }
    }

    @VisibleForTesting
    AtomicFile getRebootStatsFile() {
        File file = new File(mDeDir, REBOOT_STATS_FILE);
        if (file.exists()) {
            return new AtomicFile(new File(mDeDir, REBOOT_STATS_FILE));
        } else {
            return null;
        }
    }

    /** Writes information about any UIDs which are blocking the reboot. */
    void writeBlockingUids(PrintWriter pw) {
        synchronized (mLock) {
            for (int i = 0; i < mBlockingApps.size(); i++) {
                int appUid = mBlockingApps.valueAt(i).mAppUid;
                String[] pkgs = mPackageManager.getPackagesForUid(appUid);
                pw.println("Blocking uid: " + appUid + ", package(s): " + String.join(",", pkgs));
            }
        }
    }

    /** Writes information about any subsystems which are blocking the reboot. */
    void writeBlockingSubsystems(PrintWriter pw) {
        synchronized (mLock) {
            for (String subsystem : mBlockingComponents.keySet()) {
                pw.println("Blocking subsystem: " + subsystem);
            }
        }
    }

    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) {
                writeBlockingSubsystems(pw);
            }

            if (mBlockingApps.size() > 0) {
                writeBlockingUids(pw);
            }

            if (mShouldDumpMetrics) {
                pw.println("Previous reboot readiness checks:");
                pw.println("    Start timestamp: " + mStartTime);
                pw.println("    Ready timestamp: " +  mReadyTime);
                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);
            }
        }
    }


    /**
     * Class for tracking system components or app uids which are blocking the reboot. Handles
     * the tracking of how long an entity has blocked the reboot for, and handles the logging
     * of LongRebootBlockingReported events to SchedulingStatsLog.
     */
    private static final class BlockingEntityRecord {

        private final int mType;
        private String mComponentName;
        private int mAppUid;
        @CurrentTimeMillisLong private long mLastMetricLoggedTime;

        @Retention(RetentionPolicy.SOURCE)
        @IntDef({
            ENTITY_TYPE_COMPONENT,
            ENTITY_TYPE_APP,
        })
        private @interface EntityType {}

        private static final int ENTITY_TYPE_COMPONENT = 1;
        private static final int ENTITY_TYPE_APP = 2;

        private BlockingEntityRecord(String name) {
            mType = ENTITY_TYPE_COMPONENT;
            mComponentName = name;
            mLastMetricLoggedTime = System.currentTimeMillis();
        }

        private BlockingEntityRecord(int uid) {
            mType = ENTITY_TYPE_APP;
            mComponentName = "";
            mAppUid = uid;
            mLastMetricLoggedTime = System.currentTimeMillis();
        }

        /**
         * Writes to SchedulingStatsLog if this entity has been blocking the reboot for longer
         * than the given threshold. If this entity has been previously written to
         * SchedulingStatsLog, the threshold will be compared with the time since the previous
         * metric was recorded.
         */
        private void logLongRebootBlockingIfNecessary(long thresholdMs) {
            final long now = System.currentTimeMillis();
            if ((now - mLastMetricLoggedTime) > thresholdMs) {
                int rebootBlockReason = mapEntityTypeToRebootBlockReason(mType);
                SchedulingStatsLog.write(LONG_REBOOT_BLOCKING_REPORTED, rebootBlockReason,
                        mComponentName, mAppUid);
                Log.i(TAG, "LongRebootBlockingReported "
                        + " rebootBlockReason=" + rebootBlockReasonToString(rebootBlockReason)
                        + " componentName=" + mComponentName
                        + " appUid=" + mAppUid);
                mLastMetricLoggedTime = now;
            }
        }

        /**
         * Returns the reboot block reason which should be logged to SchedulingStatsLog if a given
         * EntityType is blocking the reboot for a long time.
         */
        private static int mapEntityTypeToRebootBlockReason(@EntityType int type) {
            if (type == ENTITY_TYPE_COMPONENT) {
                return LONG_REBOOT_BLOCKING_REPORTED__REBOOT_BLOCK_REASON__SYSTEM_COMPONENT;
            } else {
                return LONG_REBOOT_BLOCKING_REPORTED__REBOOT_BLOCK_REASON__APP_UID;
            }
        }

        /**
         * Maps a reboot block reason to a readable string for logging purposes.
         */
        private static String rebootBlockReasonToString(int rebootBlockReason) {
            switch (rebootBlockReason) {
                case LONG_REBOOT_BLOCKING_REPORTED__REBOOT_BLOCK_REASON__APP_UID:
                    return "APP_UID";
                case LONG_REBOOT_BLOCKING_REPORTED__REBOOT_BLOCK_REASON__SYSTEM_COMPONENT:
                    return "SYSTEM_COMPONENT";
                default:
                    return "UNKNOWN";
            }
        }
    }
}