diff --git a/core/java/com/android/internal/util/LatencyTracker.java b/core/java/com/android/internal/util/LatencyTracker.java index f040462dafdcd..5144a91706a1c 100644 --- a/core/java/com/android/internal/util/LatencyTracker.java +++ b/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 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) { - return "L<" + getNameOfAction(STATSD_ACTION[action]) + ">"; + private static String getTraceNameOfAction(@Action int action, String tag) { + 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. This needs to be called from the main thread. * * @param action The action to start. One of the ACTION_* values. */ public void onActionStart(@Action int action) { - if (!isEnabled()) { - return; - } - Trace.asyncTraceBegin(Trace.TRACE_TAG_APP, getTraceNameOfAction(action), 0); - mStartRtc.put(action, SystemClock.elapsedRealtime()); + onActionStart(action, null); } /** - * Notifies that an action has ended. This needs to be called from the main thread. + * Notifies that an action is starting. This needs to be called from the main thread. + * + * @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. This needs to be called from the main thread. * * @param action The action to end. One of the ACTION_* values. */ public void onActionEnd(@Action int action) { - if (!isEnabled()) { - return; + synchronized (mLock) { + 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. This needs to be called from the main thread. + * + * @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); + } + } } diff --git a/packages/SystemUI/src/com/android/systemui/LatencyTester.java b/packages/SystemUI/src/com/android/systemui/LatencyTester.java index 186917fc8807f..d325b92cf89f9 100644 --- a/packages/SystemUI/src/com/android/systemui/LatencyTester.java +++ b/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( diff --git a/packages/SystemUI/src/com/android/systemui/keyguard/KeyguardViewMediator.java b/packages/SystemUI/src/com/android/systemui/keyguard/KeyguardViewMediator.java index 281771860cb73..a104e97ef13fe 100644 --- a/packages/SystemUI/src/com/android/systemui/keyguard/KeyguardViewMediator.java +++ b/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(); diff --git a/services/core/java/com/android/server/power/PowerManagerService.java b/services/core/java/com/android/server/power/PowerManagerService.java index e7e0425d91717..97847565690a1 100644 --- a/services/core/java/com/android/server/power/PowerManagerService.java +++ b/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));