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

Commit 05dfe305 authored by Dmitri Plotnikov's avatar Dmitri Plotnikov Committed by Android (Google) Code Review
Browse files

Merge changes I267f4590,Iefb6a273,Id35f7ba3 into main 

* changes:
  Add Log.wtf to help diagnose out-of-order battery history events
  Address some out-of-order battery history event timestamps
  Add a persistent log to facilitate debugging of battery history issues
parents 17d1674a 30996daa

core/java/android/os/BatteryStats.java

+9 −1
Original line number Diff line number Diff line
@@ -6711,6 +6711,8 @@ public abstract class BatteryStats { 
        // This constant MUST be incremented whenever the history dump format changes.

        private static final int FORMAT_VERSION = 2;



        private static final boolean DEBUG_TIMELINE = false;



        private final boolean mPerformanceBaseline;

        private final HistoryLogTimeFormatter mHistoryLogTimeFormatter;

        private final SimpleDateFormat mHistoryItemTimestampFormat;
@@ -6811,6 +6813,12 @@ public abstract class BatteryStats { 
                    } else {

                        mHistoryLogTimeFormatter.append(item, rec.currentTime);

                        item.append(' ');

                        if (DEBUG_TIMELINE) {

                            if (rec.time < lastTime) {

                                item.append("[Earlier timestamp by ")

                                        .append(rec.time - lastTime).append("] ");

                            }

                        }

                    }

                }

            } else {
@@ -6821,8 +6829,8 @@ public abstract class BatteryStats { 
                } else {

                    item.append(rec.time - lastTime);

                }

                lastTime = rec.time;

            }

            lastTime = rec.time;

            if (rec.cmd == HistoryItem.CMD_START) {

                if (checkin) {

                    item.append(":");

core/java/com/android/internal/os/BatteryStatsHistory.java

+79 −0
Original line number Diff line number Diff line
@@ -38,12 +38,17 @@ import android.os.SystemClock; 
import android.os.SystemProperties;

import android.os.Trace;

import android.util.ArraySet;

import android.util.Log;

import android.util.LogWriter;

import android.util.Slog;

import android.util.SparseArray;



import com.android.internal.annotations.GuardedBy;

import com.android.internal.annotations.VisibleForTesting;



import java.io.File;

import java.io.FileOutputStream;

import java.io.IOException;

import java.io.PrintWriter;

import java.util.ArrayDeque;

import java.util.ArrayList;
@@ -369,6 +374,10 @@ public class BatteryStatsHistory { 
    private int mIteratorCookie;

    private final BatteryStatsHistory mWritableHistory;



    // Enable this locally in order to collect the persistent log generated by `debugLog` calls

    private static final boolean DEBUG_LOG_ENABLED = false;

    private static final String DEBUG_LOG_FILE = "/data/system/battery-history/debuglog.txt";



    /**

     * A delegate for android.os.Trace to allow testing static calls. Due to

     * limitations in Android Tracing (b/153319140), the delegate also records
@@ -628,6 +637,9 @@ public class BatteryStatsHistory { 
     */

    public void reset() {

        synchronized (this) {

            // The file is optional. If missing, the call is a no-op

            new File(DEBUG_LOG_FILE).delete();



            mMonotonicHistorySize = 0;

            initHistoryBuffer();

            if (mStore != null) {
@@ -1912,6 +1924,16 @@ public class BatteryStatsHistory { 
        int deltaTimeToken;

        if (deltaTime < 0 || deltaTime > Integer.MAX_VALUE) {

            deltaTimeToken = BatteryStatsHistory.DELTA_TIME_LONG;

            if (DEBUG_LOG_ENABLED) {

                // Negative or excessively large time deltas are unexpected.

                debugLog(cur, last, "Unexpected time delta: " + deltaTime, true);

            }

            if (com.android.server.power.optimization.Flags

                    .reportOutOfOrderBatteryHistoryEvents()) {

                // Generate verbose syslog to help root-cause the issue

                debugLog(Log.ERROR, cur, last, "Unexpected time delta: " + deltaTime, false);

                Slog.wtfStack(TAG, "Out-of-order battery history event. Check logcat for details");

            }

        } else if (deltaTime >= BatteryStatsHistory.DELTA_TIME_ABS) {

            deltaTimeToken = BatteryStatsHistory.DELTA_TIME_INT;

        } else {
@@ -2452,4 +2474,61 @@ public class BatteryStatsHistory { 
            }

        }

    }



    private long mDebugLogBaseTimeUtc;

    private long mDebugLogBaseMonotonicTime;



    /**

     * Logs a detailed message to {@link #DEBUG_LOG_FILE}. This should only be enabled

     * on a local built with the purposes of researching battery history issues.

     */

    private void debugLog(HistoryItem item, HistoryItem last, String message,

            boolean includeStack) {

        if (!DEBUG_LOG_ENABLED) {

            return;

        }



        try {

            PrintWriter logWriter = new PrintWriter(

                    new FileOutputStream(DEBUG_LOG_FILE, /* append */ true));

            debugLog(logWriter, item, last, message, includeStack);

            logWriter.println();

            logWriter.close();

        } catch (IOException e) {

            Slog.e(TAG, "Cannot create debug log file");

            debugLog(Log.DEBUG, item, last, message, includeStack);

        }

    }



    private void debugLog(int priority, HistoryItem item, HistoryItem last, String message,

            boolean includeStack) {

        debugLog(new PrintWriter(new LogWriter(priority, TAG), /* autoflash */ true),

                item, last, message, includeStack);

    }



    private void debugLog(PrintWriter writer, HistoryItem item, HistoryItem last, String message,

            boolean includeStack) {

        if (mDebugLogBaseTimeUtc == 0) {

            mDebugLogBaseTimeUtc = mClock.currentTimeMillis();

            mDebugLogBaseMonotonicTime = mMonotonicClock.monotonicTime();

        }



        BatteryStats.HistoryPrinter historyPrinter = new BatteryStats.HistoryPrinter();



        long currentTimeSaved = last.currentTime;

        last.currentTime = mDebugLogBaseTimeUtc + (last.time - mDebugLogBaseMonotonicTime);

        historyPrinter.printNextItem(writer, last, 0, false, true);

        last.currentTime = currentTimeSaved;



        currentTimeSaved = item.currentTime;

        item.currentTime = mDebugLogBaseTimeUtc + (item.time - mDebugLogBaseMonotonicTime);

        historyPrinter.printNextItem(writer, item, 0, false, true);

        item.currentTime = currentTimeSaved;



        writer.println("    " + message);



        if (includeStack) {

            new Exception("Stack trace").printStackTrace(writer);

        }

    }

}

services/core/java/com/android/server/am/BatteryStatsService.java

+329 −325

File changed.

Preview size limit exceeded, changes collapsed.

services/core/java/com/android/server/power/stats/BatteryExternalStatsWorker.java

+78 −75
Original line number Diff line number Diff line
@@ -28,7 +28,6 @@ import android.os.Handler; 
import android.os.OutcomeReceiver;

import android.os.Parcelable;

import android.os.SynchronousResultReceiver;

import android.os.SystemClock;

import android.os.connectivity.WifiActivityEnergyInfo;

import android.telephony.ModemActivityInfo;

import android.telephony.TelephonyManager;
@@ -36,6 +35,7 @@ import android.util.Slog; 


import com.android.internal.annotations.GuardedBy;

import com.android.internal.annotations.VisibleForTesting;

import com.android.internal.os.Clock;

import com.android.server.LocalServices;



import java.util.concurrent.CompletableFuture;
@@ -80,6 +80,7 @@ public class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStat 
    private static final int SYNC_USER_REMOVAL = 5;



    private final Handler mHandler;

    private final Clock mClock;



    @GuardedBy("mStats")

    private final BatteryStatsImpl mStats;
@@ -122,7 +123,7 @@ public class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStat 


    /**

     * Timestamp at which all external stats were last collected in

     * {@link SystemClock#elapsedRealtime()} time base.

     * {@link Clock#elapsedRealtime()} time base.

     */

    @GuardedBy("this")

    private long mLastCollectionTimeStamp;
@@ -146,15 +147,18 @@ public class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStat 
        }

    }



    public BatteryExternalStatsWorker(Context context, BatteryStatsImpl stats, Handler handler) {

        this(new Injector(context), stats, handler);

    public BatteryExternalStatsWorker(Context context, BatteryStatsImpl stats, Handler handler,

            Clock clock) {

        this(new Injector(context), stats, handler, clock);

    }



    @VisibleForTesting

    BatteryExternalStatsWorker(Injector injector, BatteryStatsImpl stats, Handler handler) {

    BatteryExternalStatsWorker(Injector injector, BatteryStatsImpl stats, Handler handler,

            Clock clock) {

        mInjector = injector;

        mStats = stats;

        mHandler = handler;

        mClock = clock;

    }



    public void systemServicesReady() {
@@ -301,7 +305,11 @@ public class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStat 
        if (!mHandler.hasMessages(SYNC_UPDATE)) {

            mUpdateFlags = flags;

            mCurrentReason = reason;

            mHandler.postDelayed(mSyncTask, SYNC_UPDATE, 0);

            synchronized (mClock) {

                long elapsedRealtimeMs = mClock.elapsedRealtime();

                long uptimeMs = mClock.uptimeMillis();

                mHandler.postDelayed(() -> sync(elapsedRealtimeMs, uptimeMs), SYNC_UPDATE, 0);

            }

        }

        mUpdateFlags |= flags;

    }
@@ -312,9 +320,7 @@ public class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStat 
        }

    }



    private final Runnable mSyncTask = new Runnable() {

        @Override

        public void run() {

    private void sync(long elapsedRealtimeMs, long uptimeMs) {

        // Capture a snapshot of the state we are meant to process.

        final int updateFlags;

        final String reason;
@@ -353,7 +359,7 @@ public class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStat 
                try {

                    updateExternalStatsLocked(reason, updateFlags, onBattery,

                            onBatteryScreenOff, screenState, displayScreenStates,

                                useLatestStates);

                            useLatestStates, elapsedRealtimeMs, uptimeMs);

                } finally {

                    if ((updateFlags & UPDATE_ALL) == UPDATE_ALL) {

                        synchronized (mStats) {
@@ -385,8 +391,7 @@ public class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStat 
            }

        } else if ((updateFlags & UPDATE_ALL) == UPDATE_ALL) {

            synchronized (BatteryExternalStatsWorker.this) {

                    mLastCollectionTimeStamp = SystemClock.elapsedRealtime();

                }

                mLastCollectionTimeStamp = elapsedRealtimeMs;

            }

        }

    };
@@ -403,7 +408,7 @@ public class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStat 
    @GuardedBy("mWorkerLock")

    private void updateExternalStatsLocked(final String reason, int updateFlags, boolean onBattery,

            boolean onBatteryScreenOff, int screenState, int[] displayScreenStates,

            boolean useLatestStates) {

            boolean useLatestStates, long elapsedRealtime, long uptime) {

        // We will request data from external processes asynchronously, and wait on a timeout.

        SynchronousResultReceiver wifiReceiver = null;

        SynchronousResultReceiver bluetoothReceiver = null;
@@ -528,8 +533,6 @@ public class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStat 
            Slog.w(TAG, "exception reading modem stats: " + e.getCause());

        }



        final long elapsedRealtime = SystemClock.elapsedRealtime();

        final long uptime = SystemClock.uptimeMillis();

        final long elapsedRealtimeUs = elapsedRealtime * 1000;

        final long uptimeUs = uptime * 1000;

services/core/java/com/android/server/power/stats/BatteryHistoryStepDetailsProvider.java

+23 −9
Original line number Diff line number Diff line
@@ -25,6 +25,7 @@ import android.power.PowerStatsInternal; 
import android.util.Slog;

import android.util.SparseArray;



import com.android.internal.os.Clock;

import com.android.server.LocalServices;



import java.util.HashMap;
@@ -42,6 +43,7 @@ class BatteryHistoryStepDetailsProvider { 
    private final BatteryStatsImpl mBatteryStats;



    private final BatteryStats.HistoryStepDetails mDetails = new BatteryStats.HistoryStepDetails();

    private final Clock mClock;



    private boolean mHasHistoryStepDetails;
@@ -78,10 +80,11 @@ class BatteryHistoryStepDetailsProvider { 
    private Map<Integer, Map<Integer, String>> mStateNames;



    private boolean mFirstUpdate = true;

    private final Runnable mUpdateRunnable = this::update;

    private final Object mUpdateToken = new Object();



    BatteryHistoryStepDetailsProvider(BatteryStatsImpl batteryStats) {

    BatteryHistoryStepDetailsProvider(BatteryStatsImpl batteryStats, Clock clock) {

        mBatteryStats = batteryStats;

        mClock = clock;

    }



    void onSystemReady() {
@@ -89,22 +92,33 @@ class BatteryHistoryStepDetailsProvider { 
    }



    void requestUpdate() {

        mBatteryStats.mHandler.removeCallbacks(mUpdateRunnable);

        mBatteryStats.mHandler.removeCallbacksAndMessages(mUpdateToken);

        if (!mSystemReady || mFirstUpdate) {

            mBatteryStats.mHandler.postDelayed(mUpdateRunnable, BOOT_TIME_UPDATE_DELAY_MILLIS);

            // System is busy; schedule an update at a later time.

            mBatteryStats.mHandler.postDelayed(() -> {

                synchronized (mClock) {

                    long elapsedRealtimeMs = mClock.elapsedRealtime();

                    long uptimeMs = mClock.uptimeMillis();

                    update(elapsedRealtimeMs, uptimeMs);

                }

            }, mUpdateToken, BOOT_TIME_UPDATE_DELAY_MILLIS);

        } else {

            mBatteryStats.mHandler.post(mUpdateRunnable);

            synchronized (mClock) {

                // Grab the timestamp before posting to the handler to keep the timeline consistent

                long elapsedRealtimeMs = mClock.elapsedRealtime();

                long uptimeMs = mClock.uptimeMillis();

                mBatteryStats.mHandler.postDelayed(() -> update(elapsedRealtimeMs, uptimeMs),

                        mUpdateToken, 0);

            }

        }

    }



    void update() {

    void update(long elapsedRealtimeMs, long uptimeMs) {

        mHasHistoryStepDetails = false;

        mBatteryStats.updateCpuDetails();

        calculateHistoryStepDetails();

        updateStateResidency();

        mBatteryStats.getHistory().recordHistoryStepDetails(mDetails,

                mBatteryStats.mClock.elapsedRealtime(),

                mBatteryStats.mClock.uptimeMillis());

        mBatteryStats.getHistory().recordHistoryStepDetails(mDetails, elapsedRealtimeMs, uptimeMs);

        mFirstUpdate = false;

    }