From fae485faba0d3e2b4bee71d8c68f75c90967f264 Mon Sep 17 00:00:00 2001 From: Suprabh Shukla Date: Tue, 21 Mar 2023 22:47:16 -0700 Subject: [PATCH] Add wakeup attribution to trace Adding two events to trace: - Log the timestamp and the raw reason provided by the kernel when the wakeup happens. - Log the attribution once it is computed by CpuWakeupStats. This attribution will also start with the timestamp of the wakeup. The timestamps are added to both events to allow easy association. Test: Manually, by collecting a trace containing a wakeup. Bug: 269169212 Change-Id: If61ceef6af591b5a050b931a35b512837383fe69 --- .../server/am/BatteryStatsService.java | 6 +++++ .../server/power/stats/CpuWakeupStats.java | 23 +++++++++++++++++-- 2 files changed, 27 insertions(+), 2 deletions(-) diff --git a/services/core/java/com/android/server/am/BatteryStatsService.java b/services/core/java/com/android/server/am/BatteryStatsService.java index 7c84b72308163..d9ba8453fffa9 100644 --- a/services/core/java/com/android/server/am/BatteryStatsService.java +++ b/services/core/java/com/android/server/am/BatteryStatsService.java @@ -66,6 +66,7 @@ import android.os.Process; import android.os.RemoteException; import android.os.ServiceManager; import android.os.SystemClock; +import android.os.Trace; import android.os.UserHandle; import android.os.WakeLockStats; import android.os.WorkSource; @@ -140,6 +141,7 @@ public final class BatteryStatsService extends IBatteryStats.Stub BatteryStatsImpl.EnergyStatsRetriever, Watchdog.Monitor { static final String TAG = "BatteryStatsService"; + static final String TRACE_TRACK_WAKEUP_REASON = "wakeup_reason"; static final boolean DBG = false; private static final boolean BATTERY_USAGE_STORE_ENABLED = true; @@ -2482,6 +2484,10 @@ public final class BatteryStatsService extends IBatteryStats.Stub while ((reason = waitWakeup()) != null) { final long nowElapsed = SystemClock.elapsedRealtime(); final long nowUptime = SystemClock.uptimeMillis(); + + Trace.instantForTrack(Trace.TRACE_TAG_POWER, TRACE_TRACK_WAKEUP_REASON, + nowElapsed + " " + reason); + // Wait for the completion of pending works if there is any awaitCompletion(); mCpuWakeupStats.noteWakeupTimeAndReason(nowElapsed, nowUptime, reason); diff --git a/services/core/java/com/android/server/power/stats/CpuWakeupStats.java b/services/core/java/com/android/server/power/stats/CpuWakeupStats.java index b05b662dc1e89..d55fbc27e109d 100644 --- a/services/core/java/com/android/server/power/stats/CpuWakeupStats.java +++ b/services/core/java/com/android/server/power/stats/CpuWakeupStats.java @@ -23,6 +23,7 @@ import static android.os.BatteryStatsInternal.CPU_WAKEUP_SUBSYSTEM_WIFI; import android.content.Context; import android.os.Handler; import android.os.HandlerExecutor; +import android.os.Trace; import android.os.UserHandle; import android.provider.DeviceConfig; import android.util.IndentingPrintWriter; @@ -55,6 +56,7 @@ public class CpuWakeupStats { private static final String SUBSYSTEM_ALARM_STRING = "Alarm"; private static final String SUBSYSTEM_ALARM_WIFI = "Wifi"; + private static final String TRACE_TRACK_WAKEUP_ATTRIBUTION = "wakeup_attribution"; @VisibleForTesting static final long WAKEUP_REASON_HALF_WINDOW_MS = 500; private static final long WAKEUP_WRITE_DELAY_MS = TimeUnit.MINUTES.toMillis(2); @@ -94,13 +96,15 @@ public class CpuWakeupStats { return FrameworkStatsLog.KERNEL_WAKEUP_ATTRIBUTED__REASON__UNKNOWN; } - private synchronized void logWakeupToStatsLog(Wakeup wakeupToLog) { + private synchronized void logWakeupAttribution(Wakeup wakeupToLog) { if (ArrayUtils.isEmpty(wakeupToLog.mDevices)) { FrameworkStatsLog.write(FrameworkStatsLog.KERNEL_WAKEUP_ATTRIBUTED, FrameworkStatsLog.KERNEL_WAKEUP_ATTRIBUTED__TYPE__TYPE_UNKNOWN, FrameworkStatsLog.KERNEL_WAKEUP_ATTRIBUTED__REASON__UNKNOWN, null, wakeupToLog.mElapsedMillis); + Trace.instantForTrack(Trace.TRACE_TAG_POWER, TRACE_TRACK_WAKEUP_ATTRIBUTION, + wakeupToLog.mElapsedMillis + " --"); return; } @@ -112,6 +116,9 @@ public class CpuWakeupStats { Slog.wtf(TAG, "Unexpected null attribution found for " + wakeupToLog); return; } + + final StringBuilder traceEventBuilder = new StringBuilder(); + for (int i = 0; i < wakeupAttribution.size(); i++) { final int subsystem = wakeupAttribution.keyAt(i); final SparseBooleanArray uidMap = wakeupAttribution.valueAt(i); @@ -132,7 +139,19 @@ public class CpuWakeupStats { subsystemToStatsReason(subsystem), uids, wakeupToLog.mElapsedMillis); + + if (Trace.isTagEnabled(Trace.TRACE_TAG_POWER)) { + if (i == 0) { + traceEventBuilder.append(wakeupToLog.mElapsedMillis + " "); + } + traceEventBuilder.append((subsystemToString(subsystem))); + traceEventBuilder.append(":"); + traceEventBuilder.append(Arrays.toString(uids)); + traceEventBuilder.append(" "); + } } + Trace.instantForTrack(Trace.TRACE_TAG_POWER, TRACE_TRACK_WAKEUP_ATTRIBUTION, + traceEventBuilder.toString().trim()); } /** Notes a wakeup reason as reported by SuspendControlService to battery stats. */ @@ -160,7 +179,7 @@ public class CpuWakeupStats { for (int i = lastIdx; i >= 0; i--) { mWakeupAttribution.removeAt(i); } - mHandler.postDelayed(() -> logWakeupToStatsLog(parsedWakeup), WAKEUP_WRITE_DELAY_MS); + mHandler.postDelayed(() -> logWakeupAttribution(parsedWakeup), WAKEUP_WRITE_DELAY_MS); } /** Notes a waking activity that could have potentially woken up the CPU. */