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

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

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. */