Merge "Add latency instrument point for ACTION_TURN_ON_SCREEN" into sc-v2-dev

core/java/com/android/internal/util/LatencyTracker.java

@@ -14,15 +14,20 @@
 
 package com.android.internal.util;
 
+import static android.os.Trace.TRACE_TAG_APP;
+
 import android.annotation.IntDef;
+import android.annotation.NonNull;
+import android.annotation.Nullable;
 import android.content.Context;
 import android.os.Build;
 import android.os.SystemClock;
 import android.os.Trace;
 import android.provider.DeviceConfig;
+import android.text.TextUtils;
 import android.util.EventLog;
 import android.util.Log;
-import android.util.SparseLongArray;
+import android.util.SparseArray;
 
 import com.android.internal.annotations.GuardedBy;
 import com.android.internal.logging.EventLogTags;
@@ -31,6 +36,7 @@ import com.android.internal.os.BackgroundThread;
 import java.lang.annotation.Retention;
 import java.lang.annotation.RetentionPolicy;
 import java.util.concurrent.ThreadLocalRandom;
+import java.util.concurrent.TimeUnit;
 
 /**
  * Class to track various latencies in SystemUI. It then writes the latency to statsd and also
@@ -44,6 +50,7 @@ public class LatencyTracker {
     private static final String TAG = "LatencyTracker";
     private static final String SETTINGS_ENABLED_KEY = "enabled";
     private static final String SETTINGS_SAMPLING_INTERVAL_KEY = "sampling_interval";
+    private static final boolean DEBUG = false;
     /** Default to being enabled on debug builds. */
     private static final boolean DEFAULT_ENABLED = Build.IS_DEBUGGABLE;
     /** Default to collecting data for 1/5 of all actions (randomly sampled). */
@@ -162,7 +169,8 @@ public class LatencyTracker {
     private static LatencyTracker sLatencyTracker;
 
     private final Object mLock = new Object();
-    private final SparseLongArray mStartRtc = new SparseLongArray();
+    @GuardedBy("mLock")
+    private final SparseArray<Session> mSessions = new SparseArray<>();
     @GuardedBy("mLock")
     private final int[] mTraceThresholdPerAction = new int[ACTIONS_ALL.length];
     @GuardedBy("mLock")
@@ -244,8 +252,12 @@ public class LatencyTracker {
         }
     }
 
-    private static String getTraceNameOfAction(@Action int action) {
+    private static String getTraceNameOfAction(@Action int action, String tag) {
-        return "L<" + getNameOfAction(STATSD_ACTION[action]) + ">";
+        if (TextUtils.isEmpty(tag)) {
+            return "L<" + getNameOfAction(STATSD_ACTION[action]) + ">";
+        } else {
+            return "L<" + getNameOfAction(STATSD_ACTION[action]) + "::" + tag + ">";
+        }
     }
 
     private static String getTraceTriggerNameForAction(@Action int action) {
@@ -263,35 +275,82 @@ public class LatencyTracker {
     }
 
     /**
-     * Notifies that an action is starting. This needs to be called from the main thread.
+     * Notifies that an action is starting. <s>This needs to be called from the main thread.</s>
      *
      * @param action The action to start. One of the ACTION_* values.
      */
     public void onActionStart(@Action int action) {
-        if (!isEnabled()) {
+        onActionStart(action, null);
-            return;
-        }
-        Trace.asyncTraceBegin(Trace.TRACE_TAG_APP, getTraceNameOfAction(action), 0);
-        mStartRtc.put(action, SystemClock.elapsedRealtime());
     }
 
     /**
-     * Notifies that an action has ended. This needs to be called from the main thread.
+     * Notifies that an action is starting. <s>This needs to be called from the main thread.</s>
+     *
+     * @param action The action to start. One of the ACTION_* values.
+     * @param tag The brief description of the action.
+     */
+    public void onActionStart(@Action int action, String tag) {
+        synchronized (mLock) {
+            if (!isEnabled()) {
+                return;
+            }
+            // skip if the action is already instrumenting.
+            if (mSessions.get(action) != null) {
+                return;
+            }
+            Session session = new Session(action, tag);
+            session.begin(() -> onActionCancel(action));
+            mSessions.put(action, session);
+
+            if (DEBUG) {
+                Log.d(TAG, "onActionStart: " + session.name() + ", start=" + session.mStartRtc);
+            }
+        }
+    }
+
+    /**
+     * Notifies that an action has ended. <s>This needs to be called from the main thread.</s>
      *
      * @param action The action to end. One of the ACTION_* values.
      */
     public void onActionEnd(@Action int action) {
-        if (!isEnabled()) {
+        synchronized (mLock) {
-            return;
+            if (!isEnabled()) {
+                return;
+            }
+            Session session = mSessions.get(action);
+            if (session == null) {
+                return;
+            }
+            session.end();
+            mSessions.delete(action);
+            logAction(action, session.duration());
+
+            if (DEBUG) {
+                Log.d(TAG, "onActionEnd:" + session.name() + ", duration=" + session.duration());
+            }
         }
-        long endRtc = SystemClock.elapsedRealtime();
+    }
-        long startRtc = mStartRtc.get(action, -1);
+
-        if (startRtc == -1) {
+    /**
-            return;
+     * Notifies that an action has canceled. <s>This needs to be called from the main thread.</s>
+     *
+     * @param action The action to cancel. One of the ACTION_* values.
+     * @hide
+     */
+    public void onActionCancel(@Action int action) {
+        synchronized (mLock) {
+            Session session = mSessions.get(action);
+            if (session == null) {
+                return;
+            }
+            session.cancel();
+            mSessions.delete(action);
+
+            if (DEBUG) {
+                Log.d(TAG, "onActionCancel: " + session.name());
+            }
         }
-        mStartRtc.delete(action);
-        Trace.asyncTraceEnd(Trace.TRACE_TAG_APP, getTraceNameOfAction(action), 0);
-        logAction(action, (int) (endRtc - startRtc));
     }
 
     /**
@@ -332,4 +391,57 @@ public class LatencyTracker {
                     FrameworkStatsLog.UI_ACTION_LATENCY_REPORTED, STATSD_ACTION[action], duration);
         }
     }
+
+    static class Session {
+        @Action
+        private final int mAction;
+        private final String mTag;
+        private final String mName;
+        private Runnable mTimeoutRunnable;
+        private long mStartRtc = -1;
+        private long mEndRtc = -1;
+
+        Session(@Action int action, @Nullable String tag) {
+            mAction = action;
+            mTag = tag;
+            mName = TextUtils.isEmpty(mTag)
+                    ? getNameOfAction(STATSD_ACTION[mAction])
+                    : getNameOfAction(STATSD_ACTION[mAction]) + "::" + mTag;
+        }
+
+        String name() {
+            return mName;
+        }
+
+        String traceName() {
+            return getTraceNameOfAction(mAction, mTag);
+        }
+
+        void begin(@NonNull Runnable timeoutAction) {
+            mStartRtc = SystemClock.elapsedRealtime();
+            Trace.asyncTraceBegin(TRACE_TAG_APP, traceName(), 0);
+
+            // start counting timeout.
+            mTimeoutRunnable = timeoutAction;
+            BackgroundThread.getHandler()
+                    .postDelayed(mTimeoutRunnable, TimeUnit.SECONDS.toMillis(2));
+        }
+
+        void end() {
+            mEndRtc = SystemClock.elapsedRealtime();
+            Trace.asyncTraceEnd(TRACE_TAG_APP, traceName(), 0);
+            BackgroundThread.getHandler().removeCallbacks(mTimeoutRunnable);
+            mTimeoutRunnable = null;
+        }
+
+        void cancel() {
+            Trace.asyncTraceEnd(TRACE_TAG_APP, traceName(), 0);
+            BackgroundThread.getHandler().removeCallbacks(mTimeoutRunnable);
+            mTimeoutRunnable = null;
+        }
+
+        int duration() {
+            return (int) (mEndRtc - mStartRtc);
+        }
+    }
 }

packages/SystemUI/src/com/android/systemui/LatencyTester.java

@@ -16,18 +16,13 @@
 
 package com.android.systemui;
 
-import static android.os.PowerManager.WAKE_REASON_UNKNOWN;
-
 import android.content.BroadcastReceiver;
 import android.content.Context;
 import android.content.Intent;
 import android.content.IntentFilter;
 import android.hardware.biometrics.BiometricSourceType;
 import android.os.Build;
-import android.os.PowerManager;
-import android.os.SystemClock;
 
-import com.android.internal.util.LatencyTracker;
 import com.android.keyguard.KeyguardUpdateMonitor;
 import com.android.systemui.broadcast.BroadcastDispatcher;
 import com.android.systemui.dagger.SysUISingleton;
@@ -48,20 +43,15 @@ public class LatencyTester extends SystemUI {
     private static final String
             ACTION_FACE_WAKE =
             "com.android.systemui.latency.ACTION_FACE_WAKE";
-    private static final String
-            ACTION_TURN_ON_SCREEN =
-            "com.android.systemui.latency.ACTION_TURN_ON_SCREEN";
     private final BiometricUnlockController mBiometricUnlockController;
-    private final PowerManager mPowerManager;
     private final BroadcastDispatcher mBroadcastDispatcher;
 
     @Inject
     public LatencyTester(Context context, BiometricUnlockController biometricUnlockController,
-            PowerManager powerManager, BroadcastDispatcher broadcastDispatcher) {
+            BroadcastDispatcher broadcastDispatcher) {
         super(context);
 
         mBiometricUnlockController = biometricUnlockController;
-        mPowerManager = powerManager;
         mBroadcastDispatcher = broadcastDispatcher;
     }
 
@@ -74,7 +64,6 @@ public class LatencyTester extends SystemUI {
         IntentFilter filter = new IntentFilter();
         filter.addAction(ACTION_FINGERPRINT_WAKE);
         filter.addAction(ACTION_FACE_WAKE);
-        filter.addAction(ACTION_TURN_ON_SCREEN);
         mBroadcastDispatcher.registerReceiver(new BroadcastReceiver() {
             @Override
             public void onReceive(Context context, Intent intent) {
@@ -83,22 +72,11 @@ public class LatencyTester extends SystemUI {
                     fakeWakeAndUnlock(BiometricSourceType.FINGERPRINT);
                 } else if (ACTION_FACE_WAKE.equals(action)) {
                     fakeWakeAndUnlock(BiometricSourceType.FACE);
-                } else if (ACTION_TURN_ON_SCREEN.equals(action)) {
-                    fakeTurnOnScreen();
                 }
             }
         }, filter);
     }
 
-    private void fakeTurnOnScreen() {
-        if (LatencyTracker.isEnabled(mContext)) {
-            LatencyTracker.getInstance(mContext).onActionStart(
-                    LatencyTracker.ACTION_TURN_ON_SCREEN);
-        }
-        mPowerManager.wakeUp(
-                SystemClock.uptimeMillis(), WAKE_REASON_UNKNOWN, "android.policy:LATENCY_TESTS");
-    }
-
     private void fakeWakeAndUnlock(BiometricSourceType type) {
         mBiometricUnlockController.onBiometricAcquired(type);
         mBiometricUnlockController.onBiometricAuthenticated(

packages/SystemUI/src/com/android/systemui/keyguard/KeyguardViewMediator.java

@@ -2565,9 +2565,6 @@ public class KeyguardViewMediator extends SystemUI implements Dumpable,
 
     private void handleNotifyScreenTurnedOn() {
         Trace.beginSection("KeyguardViewMediator#handleNotifyScreenTurnedOn");
-        if (LatencyTracker.isEnabled(mContext)) {
-            LatencyTracker.getInstance(mContext).onActionEnd(LatencyTracker.ACTION_TURN_ON_SCREEN);
-        }
         synchronized (this) {
             if (DEBUG) Log.d(TAG, "handleNotifyScreenTurnedOn");
             mKeyguardViewControllerLazy.get().onScreenTurnedOn();

services/core/java/com/android/server/power/PowerManagerService.java

@@ -31,6 +31,8 @@ import static android.os.PowerManagerInternal.WAKEFULNESS_DOZING;
 import static android.os.PowerManagerInternal.WAKEFULNESS_DREAMING;
 import static android.os.PowerManagerInternal.wakefulnessToString;
 
+import static com.android.internal.util.LatencyTracker.ACTION_TURN_ON_SCREEN;
+
 import android.annotation.IntDef;
 import android.annotation.NonNull;
 import android.annotation.Nullable;
@@ -104,6 +106,7 @@ import com.android.internal.display.BrightnessSynchronizer;
 import com.android.internal.os.BackgroundThread;
 import com.android.internal.util.ArrayUtils;
 import com.android.internal.util.DumpUtils;
+import com.android.internal.util.LatencyTracker;
 import com.android.internal.util.Preconditions;
 import com.android.server.EventLogTags;
 import com.android.server.LockGuard;
@@ -1842,6 +1845,9 @@ public final class PowerManagerService extends SystemService
                     + ", details=" + details
                     + ")...");
             Trace.asyncTraceBegin(Trace.TRACE_TAG_POWER, TRACE_SCREEN_ON, groupId);
+            // The instrument will be timed out automatically after 2 seconds.
+            LatencyTracker.getInstance(mContext)
+                    .onActionStart(ACTION_TURN_ON_SCREEN, String.valueOf(groupId));
 
             setWakefulnessLocked(groupId, WAKEFULNESS_AWAKE, eventTime, uid, reason, opUid,
                     opPackageName, details);
@@ -3225,6 +3231,7 @@ public final class PowerManagerService extends SystemService
                         && mDisplayGroupPowerStateMapper.getWakefulnessLocked(
                         groupId) == WAKEFULNESS_AWAKE) {
                     mDisplayGroupPowerStateMapper.setPoweringOnLocked(groupId, false);
+                    LatencyTracker.getInstance(mContext).onActionEnd(ACTION_TURN_ON_SCREEN);
                     Trace.asyncTraceEnd(Trace.TRACE_TAG_POWER, TRACE_SCREEN_ON, groupId);
                     final int latencyMs = (int) (mClock.uptimeMillis()
                             - mDisplayGroupPowerStateMapper.getLastPowerOnTimeLocked(groupId));