| /* |
| * Copyright (C) 2020 The Android Open Source Project |
| * |
| * Licensed under the Apache License, Version 2.0 (the "License"); |
| * you may not use this file except in compliance with the License. |
| * You may obtain a copy of the License at |
| * |
| * http://www.apache.org/licenses/LICENSE-2.0 |
| * |
| * Unless required by applicable law or agreed to in writing, software |
| * distributed under the License is distributed on an "AS IS" BASIS, |
| * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| * See the License for the specific language governing permissions and |
| * limitations under the License. |
| */ |
| |
| package com.android.car.user; |
| |
| import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_STARTING; |
| import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_STOPPED; |
| import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_STOPPING; |
| import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_SWITCHING; |
| import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_UNLOCKED; |
| import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_UNLOCKING; |
| import static android.car.user.CarUserManager.lifecycleEventTypeToString; |
| |
| import android.annotation.NonNull; |
| import android.annotation.Nullable; |
| import android.annotation.UserIdInt; |
| import android.car.user.CarUserManager.UserLifecycleEventType; |
| import android.util.LocalLog; |
| import android.util.Slog; |
| import android.util.SparseArray; |
| import android.util.SparseLongArray; |
| import android.util.TimeUtils; |
| |
| import com.android.internal.annotations.GuardedBy; |
| import com.android.internal.annotations.VisibleForTesting; |
| |
| import java.io.PrintWriter; |
| import java.io.StringWriter; |
| |
| /** |
| * Metrics for user switches. |
| * |
| * <p>It stores 2 types of metrics: |
| * |
| * <ol> |
| * <li>Time to start a user (from start to unlock) |
| * <li>Time to stop a user (from stop to shutdown) |
| * </ol> |
| * |
| * <p>It keeps track of the users being started and stopped, then logs the last |
| * {{@link #INITIAL_CAPACITY}} occurrences of each when the operation finished (so it can be dumped |
| * later). |
| */ |
| final class UserMetrics { |
| |
| private static final String TAG = UserMetrics.class.getSimpleName(); |
| |
| /** |
| * Initial capacity for the current operations. |
| */ |
| // Typically there are at most 2 users (system and 1st full), although it could be higher on |
| // garage mode |
| private static final int INITIAL_CAPACITY = 2; |
| |
| // TODO(b/150413515): read from resources |
| private static final int LOG_SIZE = 10; |
| |
| private final Object mLock = new Object(); |
| |
| @GuardedBy("mLock") |
| private SparseArray<UserStartingMetric> mUserStartingMetrics; |
| @GuardedBy("mLock") |
| private SparseArray<UserStoppingMetric> mUserStoppingMetrics; |
| |
| @GuardedBy("mLock") |
| private final LocalLog mUserStartedLogs = new LocalLog(LOG_SIZE); |
| @GuardedBy("mLock") |
| private final LocalLog mUserStoppedLogs = new LocalLog(LOG_SIZE); |
| |
| @GuardedBy("mLock") |
| private final SparseLongArray mFirstUserUnlockDuration = new SparseLongArray(1); |
| |
| @GuardedBy("mLock") |
| private int mHalResponseTime; |
| |
| /** |
| * Logs a user lifecycle event. |
| */ |
| public void onEvent(@UserLifecycleEventType int eventType, long timestampMs, |
| @UserIdInt int fromUserId, @UserIdInt int toUserId) { |
| synchronized (mLock) { |
| switch(eventType) { |
| case USER_LIFECYCLE_EVENT_TYPE_STARTING: |
| onUserStartingEventLocked(timestampMs, toUserId); |
| return; |
| case USER_LIFECYCLE_EVENT_TYPE_SWITCHING: |
| onUserSwitchingEventLocked(timestampMs, fromUserId, toUserId); |
| return; |
| case USER_LIFECYCLE_EVENT_TYPE_UNLOCKING: |
| onUserUnlockingEventLocked(timestampMs, toUserId); |
| return; |
| case USER_LIFECYCLE_EVENT_TYPE_UNLOCKED: |
| onUserUnlockedEventLocked(timestampMs, toUserId); |
| return; |
| case USER_LIFECYCLE_EVENT_TYPE_STOPPING: |
| onUserStoppingEventLocked(timestampMs, toUserId); |
| return; |
| case USER_LIFECYCLE_EVENT_TYPE_STOPPED: |
| onUserStoppedEventLocked(timestampMs, toUserId); |
| return; |
| default: |
| Slog.w(TAG, "Invalid event: " + lifecycleEventTypeToString(eventType)); |
| } |
| } |
| } |
| |
| /** |
| * Logs when the first user was unlocked. |
| */ |
| public void logFirstUnlockedUser(int userId, long timestampMs, long duration, |
| int halResponseTime) { |
| synchronized (mLock) { |
| mHalResponseTime = halResponseTime; |
| mFirstUserUnlockDuration.put(userId, duration); |
| } |
| } |
| |
| @VisibleForTesting |
| SparseArray<UserStartingMetric> getUserStartMetrics() { |
| synchronized (mLock) { |
| return mUserStartingMetrics; |
| } |
| } |
| |
| @VisibleForTesting |
| SparseArray<UserStoppingMetric> getUserStopMetrics() { |
| synchronized (mLock) { |
| return mUserStoppingMetrics; |
| } |
| } |
| |
| private void onUserStartingEventLocked(long timestampMs, @UserIdInt int userId) { |
| if (mUserStartingMetrics == null) { |
| mUserStartingMetrics = new SparseArray<>(INITIAL_CAPACITY); |
| } |
| |
| UserStartingMetric existingMetrics = mUserStartingMetrics.get(userId); |
| if (existingMetrics != null) { |
| Slog.w(TAG, "user re-started: " + existingMetrics); |
| finishUserStartingLocked(existingMetrics, /* removeMetric= */ false); |
| } |
| |
| mUserStartingMetrics.put(userId, new UserStartingMetric(userId, timestampMs)); |
| } |
| |
| private void onUserSwitchingEventLocked(long timestampMs, @UserIdInt int fromUserId, |
| @UserIdInt int toUserId) { |
| UserStartingMetric metrics = getExistingMetricsLocked(mUserStartingMetrics, toUserId); |
| if (metrics == null) return; |
| |
| metrics.switchFromUserId = fromUserId; |
| metrics.switchTime = timestampMs; |
| } |
| |
| private void onUserUnlockingEventLocked(long timestampMs, @UserIdInt int userId) { |
| UserStartingMetric metrics = getExistingMetricsLocked(mUserStartingMetrics, userId); |
| if (metrics == null) return; |
| |
| metrics.unlockingTime = timestampMs; |
| } |
| |
| private void onUserUnlockedEventLocked(long timestampMs, @UserIdInt int userId) { |
| UserStartingMetric metrics = getExistingMetricsLocked(mUserStartingMetrics, userId); |
| if (metrics == null) return; |
| |
| metrics.unlockedTime = timestampMs; |
| |
| finishUserStartingLocked(metrics, /* removeMetric= */ true); |
| } |
| |
| private void onUserStoppingEventLocked(long timestampMs, @UserIdInt int userId) { |
| if (mUserStoppingMetrics == null) { |
| mUserStoppingMetrics = new SparseArray<>(INITIAL_CAPACITY); |
| } |
| UserStoppingMetric existingMetrics = mUserStoppingMetrics.get(userId); |
| if (existingMetrics != null) { |
| Slog.w(TAG, "user re-stopped: " + existingMetrics); |
| finishUserStoppingLocked(existingMetrics, /* removeMetric= */ false); |
| } |
| mUserStoppingMetrics.put(userId, new UserStoppingMetric(userId, timestampMs)); |
| } |
| |
| private void onUserStoppedEventLocked(long timestampMs, @UserIdInt int userId) { |
| UserStoppingMetric metrics = getExistingMetricsLocked(mUserStoppingMetrics, userId); |
| if (metrics == null) return; |
| |
| metrics.shutdownTime = timestampMs; |
| finishUserStoppingLocked(metrics, /* removeMetric= */ true); |
| } |
| |
| @Nullable |
| private <T extends BaseUserMetric> T getExistingMetricsLocked( |
| @NonNull SparseArray<? extends BaseUserMetric> metrics, @UserIdInt int userId) { |
| if (metrics == null) { |
| Slog.w(TAG, "getExistingMetricsLocked() should not pass null metrics, except on tests"); |
| return null; |
| } |
| @SuppressWarnings("unchecked") |
| T metric = (T) metrics.get(userId); |
| if (metric == null) { |
| String name = metrics == mUserStartingMetrics ? "starting" : "stopping"; |
| Slog.w(TAG, "no " + name + " metrics for user " + userId); |
| } |
| return metric; |
| } |
| |
| private void removeExistingMetricsLogged(@NonNull SparseArray<? extends BaseUserMetric> metrics, |
| @UserIdInt int userId) { |
| metrics.remove(userId); |
| if (metrics.size() != 0) return; |
| |
| if (metrics == mUserStartingMetrics) { |
| mUserStartingMetrics = null; |
| } else { |
| mUserStoppingMetrics = null; |
| } |
| } |
| |
| private void finishUserStartingLocked(@NonNull UserStartingMetric metrics, |
| boolean removeMetric) { |
| mUserStartedLogs.log(metrics.toString()); |
| if (removeMetric) { |
| removeExistingMetricsLogged(mUserStartingMetrics, metrics.userId); |
| } |
| } |
| |
| private void finishUserStoppingLocked(@NonNull UserStoppingMetric metrics, |
| boolean removeMetric) { |
| mUserStoppedLogs.log(metrics.toString()); |
| if (removeMetric) { |
| removeExistingMetricsLogged(mUserStoppingMetrics, metrics.userId); |
| } |
| } |
| |
| /** |
| * Dumps its contents. |
| */ |
| public void dump(@NonNull PrintWriter pw) { |
| pw.println("* User Metrics *"); |
| synchronized (mLock) { |
| |
| if (mFirstUserUnlockDuration.size() == 0) { |
| pw.println("First user not unlocked yet"); |
| } else { |
| pw.printf("First user (%d) unlocked in ", mFirstUserUnlockDuration.keyAt(0)); |
| TimeUtils.formatDuration(mFirstUserUnlockDuration.valueAt(0), pw); |
| pw.println(); |
| } |
| |
| dump(pw, "starting", mUserStartingMetrics); |
| dump(pw, "stopping", mUserStoppingMetrics); |
| |
| pw.printf("Last %d started users\n", LOG_SIZE); |
| mUserStartedLogs.dump(" ", pw); |
| |
| pw.printf("Last %d stopped users\n", LOG_SIZE); |
| mUserStoppedLogs.dump(" ", pw); |
| |
| pw.print("HAL response time: "); |
| if (mHalResponseTime == 0) { |
| pw.print("N/A"); |
| } else if (mHalResponseTime < 0) { |
| pw.print("not replied yet, sent at "); |
| TimeUtils.formatUptime(-mHalResponseTime); |
| } else { |
| TimeUtils.formatDuration(mHalResponseTime, pw); |
| } |
| pw.println(); |
| } |
| } |
| |
| /** |
| * Dumps only how long it took to unlock the first user (or {@code -1} if not available). |
| */ |
| public void dumpFirstUserUnlockDuration(@NonNull PrintWriter pw) { |
| synchronized (mLock) { |
| if (mFirstUserUnlockDuration.size() == 0) { |
| pw.println(-1); |
| return; |
| } |
| pw.println(mFirstUserUnlockDuration.valueAt(0)); |
| } |
| } |
| |
| private void dump(@NonNull PrintWriter pw, @NonNull String message, |
| @NonNull SparseArray<? extends BaseUserMetric> metrics) { |
| String indent = " "; |
| if (metrics == null) { |
| pw.printf("%sno users %s\n", indent, message); |
| return; |
| } |
| int size = metrics.size(); |
| pw.printf("%d users %s\n", size, message); |
| for (int i = 0; i < size; i++) { |
| BaseUserMetric metric = metrics.valueAt(i); |
| pw.printf("%s%d: ", indent, i); |
| metric.dump(pw); |
| pw.println(); |
| } |
| } |
| |
| private abstract class BaseUserMetric { |
| public final @UserIdInt int userId; |
| |
| protected BaseUserMetric(@UserIdInt int userId) { |
| this.userId = userId; |
| } |
| |
| @Override |
| public String toString() { |
| StringWriter sw = new StringWriter(); |
| PrintWriter pw = new PrintWriter(sw); |
| dump(pw); |
| pw.flush(); |
| return sw.toString(); |
| } |
| |
| abstract void dump(@NonNull PrintWriter pw); |
| } |
| |
| @VisibleForTesting |
| final class UserStartingMetric extends BaseUserMetric { |
| public final long startTime; |
| public long switchTime; |
| public long unlockingTime; |
| public long unlockedTime; |
| public @UserIdInt int switchFromUserId; |
| |
| UserStartingMetric(@UserIdInt int userId, long startTime) { |
| super(userId); |
| this.startTime = startTime; |
| } |
| |
| @Override |
| public void dump(@NonNull PrintWriter pw) { |
| pw.printf("user=%d start=", userId); |
| TimeUtils.dumpTime(pw, startTime); |
| |
| if (switchTime > 0) { |
| long delta = switchTime - startTime; |
| pw.print(" switch"); |
| if (switchFromUserId != 0) { |
| pw.printf("(from %d)", switchFromUserId); |
| } |
| pw.print('='); |
| TimeUtils.formatDuration(delta, pw); |
| } |
| |
| if (unlockingTime > 0) { |
| long delta = unlockingTime - startTime; |
| pw.print(" unlocking="); |
| TimeUtils.formatDuration(delta, pw); |
| } |
| if (unlockedTime > 0) { |
| long delta = unlockedTime - startTime; |
| pw.print(" unlocked="); |
| TimeUtils.formatDuration(delta, pw); |
| } |
| } |
| } |
| |
| @VisibleForTesting |
| final class UserStoppingMetric extends BaseUserMetric { |
| public final long stopTime; |
| public long shutdownTime; |
| |
| UserStoppingMetric(@UserIdInt int userId, long stopTime) { |
| super(userId); |
| this.stopTime = stopTime; |
| } |
| |
| @Override |
| public void dump(@NonNull PrintWriter pw) { |
| pw.printf("user=%d stop=", userId); |
| TimeUtils.dumpTime(pw, stopTime); |
| |
| if (shutdownTime > 0) { |
| long delta = shutdownTime - stopTime; |
| pw.print(" shutdown="); |
| TimeUtils.formatDuration(delta, pw); |
| } |
| } |
| } |
| } |