1 /*
2  * Copyright (C) 2020 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 package com.android.car.user;
18 
19 import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_STARTING;
20 import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_STOPPED;
21 import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_STOPPING;
22 import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_SWITCHING;
23 import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_UNLOCKED;
24 import static android.car.user.CarUserManager.USER_LIFECYCLE_EVENT_TYPE_UNLOCKING;
25 import static android.car.user.CarUserManager.lifecycleEventTypeToString;
26 
27 import android.annotation.NonNull;
28 import android.annotation.Nullable;
29 import android.annotation.UserIdInt;
30 import android.car.user.CarUserManager.UserLifecycleEventType;
31 import android.util.LocalLog;
32 import android.util.Slog;
33 import android.util.SparseArray;
34 import android.util.SparseLongArray;
35 import android.util.TimeUtils;
36 
37 import com.android.internal.annotations.GuardedBy;
38 import com.android.internal.annotations.VisibleForTesting;
39 
40 import java.io.PrintWriter;
41 import java.io.StringWriter;
42 
43 /**
44  * Metrics for user switches.
45  *
46  * <p>It stores 2 types of metrics:
47  *
48  * <ol>
49  *   <li>Time to start a user (from start to unlock)
50  *   <li>Time to stop a user (from stop to shutdown)
51  * </ol>
52  *
53  * <p>It keeps track of the users being started and stopped, then logs the last
54  * {{@link #INITIAL_CAPACITY}} occurrences of each when the operation finished (so it can be dumped
55  * later).
56  */
57 final class UserMetrics {
58 
59     private static final String TAG = UserMetrics.class.getSimpleName();
60 
61     /**
62      * Initial capacity for the current operations.
63      */
64     // Typically there are at most 2 users (system and 1st full), although it could be higher on
65     // garage mode
66     private static final int INITIAL_CAPACITY = 2;
67 
68     // TODO(b/150413515): read from resources
69     private static final int LOG_SIZE = 10;
70 
71     private final Object mLock = new Object();
72 
73     @GuardedBy("mLock")
74     private SparseArray<UserStartingMetric> mUserStartingMetrics;
75     @GuardedBy("mLock")
76     private SparseArray<UserStoppingMetric> mUserStoppingMetrics;
77 
78     @GuardedBy("mLock")
79     private final LocalLog mUserStartedLogs = new LocalLog(LOG_SIZE);
80     @GuardedBy("mLock")
81     private final LocalLog mUserStoppedLogs = new LocalLog(LOG_SIZE);
82 
83     @GuardedBy("mLock")
84     private final SparseLongArray mFirstUserUnlockDuration = new SparseLongArray(1);
85 
86     @GuardedBy("mLock")
87     private int mHalResponseTime;
88 
89     /**
90      * Logs a user lifecycle event.
91      */
onEvent(@serLifecycleEventType int eventType, long timestampMs, @UserIdInt int fromUserId, @UserIdInt int toUserId)92     public void onEvent(@UserLifecycleEventType int eventType, long timestampMs,
93             @UserIdInt int fromUserId, @UserIdInt int toUserId) {
94         synchronized (mLock) {
95             switch(eventType) {
96                 case USER_LIFECYCLE_EVENT_TYPE_STARTING:
97                     onUserStartingEventLocked(timestampMs, toUserId);
98                     return;
99                 case USER_LIFECYCLE_EVENT_TYPE_SWITCHING:
100                     onUserSwitchingEventLocked(timestampMs, fromUserId, toUserId);
101                     return;
102                 case USER_LIFECYCLE_EVENT_TYPE_UNLOCKING:
103                     onUserUnlockingEventLocked(timestampMs, toUserId);
104                     return;
105                 case USER_LIFECYCLE_EVENT_TYPE_UNLOCKED:
106                     onUserUnlockedEventLocked(timestampMs, toUserId);
107                     return;
108                 case USER_LIFECYCLE_EVENT_TYPE_STOPPING:
109                     onUserStoppingEventLocked(timestampMs, toUserId);
110                     return;
111                 case USER_LIFECYCLE_EVENT_TYPE_STOPPED:
112                     onUserStoppedEventLocked(timestampMs, toUserId);
113                     return;
114                 default:
115                     Slog.w(TAG, "Invalid event: " + lifecycleEventTypeToString(eventType));
116             }
117         }
118     }
119 
120     /**
121      * Logs when the first user was unlocked.
122      */
logFirstUnlockedUser(int userId, long timestampMs, long duration, int halResponseTime)123     public void logFirstUnlockedUser(int userId, long timestampMs, long duration,
124             int halResponseTime) {
125         synchronized (mLock) {
126             mHalResponseTime = halResponseTime;
127             mFirstUserUnlockDuration.put(userId, duration);
128             onUserUnlockedEventLocked(timestampMs, userId);
129         }
130     }
131 
132     @VisibleForTesting
getUserStartMetrics()133     SparseArray<UserStartingMetric> getUserStartMetrics() {
134         synchronized (mLock) {
135             return mUserStartingMetrics;
136         }
137     }
138 
139     @VisibleForTesting
getUserStopMetrics()140     SparseArray<UserStoppingMetric> getUserStopMetrics() {
141         synchronized (mLock) {
142             return mUserStoppingMetrics;
143         }
144     }
145 
onUserStartingEventLocked(long timestampMs, @UserIdInt int userId)146     private void onUserStartingEventLocked(long timestampMs, @UserIdInt int userId) {
147         if (mUserStartingMetrics == null) {
148             mUserStartingMetrics = new SparseArray<>(INITIAL_CAPACITY);
149         }
150 
151         UserStartingMetric existingMetrics = mUserStartingMetrics.get(userId);
152         if (existingMetrics != null) {
153             Slog.w(TAG, "user re-started: " + existingMetrics);
154             finishUserStartingLocked(existingMetrics, /* removeMetric= */ false);
155         }
156 
157         mUserStartingMetrics.put(userId, new UserStartingMetric(userId, timestampMs));
158     }
159 
onUserSwitchingEventLocked(long timestampMs, @UserIdInt int fromUserId, @UserIdInt int toUserId)160     private void onUserSwitchingEventLocked(long timestampMs, @UserIdInt int fromUserId,
161             @UserIdInt int toUserId) {
162         UserStartingMetric metrics = getExistingMetricsLocked(mUserStartingMetrics, toUserId);
163         if (metrics == null) return;
164 
165         metrics.switchFromUserId = fromUserId;
166         metrics.switchTime = timestampMs;
167     }
168 
onUserUnlockingEventLocked(long timestampMs, @UserIdInt int userId)169     private void onUserUnlockingEventLocked(long timestampMs, @UserIdInt int userId) {
170         UserStartingMetric metrics = getExistingMetricsLocked(mUserStartingMetrics, userId);
171         if (metrics == null) return;
172 
173         metrics.unlockingTime = timestampMs;
174     }
175 
onUserUnlockedEventLocked(long timestampMs, @UserIdInt int userId)176     private void onUserUnlockedEventLocked(long timestampMs, @UserIdInt int userId) {
177         UserStartingMetric metrics = getExistingMetricsLocked(mUserStartingMetrics, userId);
178         if (metrics == null) return;
179 
180         metrics.unlockedTime = timestampMs;
181 
182         finishUserStartingLocked(metrics, /* removeMetric= */ true);
183     }
184 
onUserStoppingEventLocked(long timestampMs, @UserIdInt int userId)185     private void onUserStoppingEventLocked(long timestampMs, @UserIdInt int userId) {
186         if (mUserStoppingMetrics == null) {
187             mUserStoppingMetrics = new SparseArray<>(INITIAL_CAPACITY);
188         }
189         UserStoppingMetric existingMetrics = mUserStoppingMetrics.get(userId);
190         if (existingMetrics != null) {
191             Slog.w(TAG, "user re-stopped: " + existingMetrics);
192             finishUserStoppingLocked(existingMetrics, /* removeMetric= */ false);
193         }
194         mUserStoppingMetrics.put(userId, new UserStoppingMetric(userId, timestampMs));
195     }
196 
onUserStoppedEventLocked(long timestampMs, @UserIdInt int userId)197     private void onUserStoppedEventLocked(long timestampMs, @UserIdInt int userId) {
198         UserStoppingMetric metrics = getExistingMetricsLocked(mUserStoppingMetrics, userId);
199         if (metrics == null) return;
200 
201         metrics.shutdownTime = timestampMs;
202         finishUserStoppingLocked(metrics, /* removeMetric= */ true);
203     }
204 
205     @Nullable
getExistingMetricsLocked( @onNull SparseArray<? extends BaseUserMetric> metrics, @UserIdInt int userId)206     private <T extends BaseUserMetric> T getExistingMetricsLocked(
207             @NonNull SparseArray<? extends BaseUserMetric> metrics, @UserIdInt int userId) {
208         if (metrics == null) {
209             Slog.w(TAG, "getExistingMetricsLocked() should not pass null metrics, except on tests");
210             return null;
211         }
212         @SuppressWarnings("unchecked")
213         T metric = (T) metrics.get(userId);
214         if (metric == null) {
215             String name = metrics == mUserStartingMetrics ? "starting" : "stopping";
216             Slog.w(TAG, "no " + name + " metrics for user " + userId);
217         }
218         return metric;
219     }
220 
removeExistingMetricsLogged(@onNull SparseArray<? extends BaseUserMetric> metrics, @UserIdInt int userId)221     private void removeExistingMetricsLogged(@NonNull SparseArray<? extends BaseUserMetric> metrics,
222             @UserIdInt int userId) {
223         metrics.remove(userId);
224         if (metrics.size() != 0) return;
225 
226         if (metrics == mUserStartingMetrics) {
227             mUserStartingMetrics = null;
228         } else {
229             mUserStoppingMetrics = null;
230         }
231     }
232 
finishUserStartingLocked(@onNull UserStartingMetric metrics, boolean removeMetric)233     private void finishUserStartingLocked(@NonNull UserStartingMetric metrics,
234             boolean removeMetric) {
235         mUserStartedLogs.log(metrics.toString());
236         if (removeMetric) {
237             removeExistingMetricsLogged(mUserStartingMetrics, metrics.userId);
238         }
239     }
240 
finishUserStoppingLocked(@onNull UserStoppingMetric metrics, boolean removeMetric)241     private void finishUserStoppingLocked(@NonNull UserStoppingMetric metrics,
242             boolean removeMetric) {
243         mUserStoppedLogs.log(metrics.toString());
244         if (removeMetric) {
245             removeExistingMetricsLogged(mUserStoppingMetrics, metrics.userId);
246         }
247     }
248 
249     /**
250      * Dumps its contents.
251      */
dump(@onNull PrintWriter pw)252     public void dump(@NonNull PrintWriter pw) {
253         pw.println("* User Metrics *");
254         synchronized (mLock) {
255 
256             if (mFirstUserUnlockDuration.size() == 0) {
257                 pw.println("First user not unlocked yet");
258             } else {
259                 pw.printf("First user (%d) unlocked in ", mFirstUserUnlockDuration.keyAt(0));
260                 TimeUtils.formatDuration(mFirstUserUnlockDuration.valueAt(0), pw);
261                 pw.println();
262             }
263 
264             dump(pw, "starting", mUserStartingMetrics);
265             dump(pw, "stopping", mUserStoppingMetrics);
266 
267             pw.printf("Last %d started users\n", LOG_SIZE);
268             mUserStartedLogs.dump("  ", pw);
269 
270             pw.printf("Last %d stopped users\n", LOG_SIZE);
271             mUserStoppedLogs.dump("  ", pw);
272 
273             pw.print("HAL response time: ");
274             if (mHalResponseTime == 0) {
275                 pw.print("N/A");
276             } else if (mHalResponseTime < 0) {
277                 pw.print("not replied yet, sent at ");
278                 TimeUtils.formatUptime(-mHalResponseTime);
279             } else {
280                 TimeUtils.formatDuration(mHalResponseTime, pw);
281             }
282             pw.println();
283         }
284     }
285 
286     /**
287      * Dumps only how long it took to unlock the first user (or {@code -1} if not available).
288      */
dumpFirstUserUnlockDuration(@onNull PrintWriter pw)289     public void dumpFirstUserUnlockDuration(@NonNull PrintWriter pw) {
290         synchronized (mLock) {
291             if (mFirstUserUnlockDuration.size() == 0) {
292                 pw.println(-1);
293                 return;
294             }
295             pw.println(mFirstUserUnlockDuration.valueAt(0));
296         }
297     }
298 
dump(@onNull PrintWriter pw, @NonNull String message, @NonNull SparseArray<? extends BaseUserMetric> metrics)299     private void dump(@NonNull PrintWriter pw, @NonNull String message,
300             @NonNull SparseArray<? extends BaseUserMetric> metrics) {
301         String indent = "  ";
302         if (metrics == null) {
303             pw.printf("%sno users %s\n", indent, message);
304             return;
305         }
306         int size = metrics.size();
307         pw.printf("%d users %s\n", size, message);
308         for (int i = 0; i < size; i++) {
309             BaseUserMetric metric = metrics.valueAt(i);
310             pw.printf("%s%d: ", indent, i);
311             metric.dump(pw);
312             pw.println();
313         }
314     }
315 
316     private abstract class BaseUserMetric {
317         public final @UserIdInt int userId;
318 
BaseUserMetric(@serIdInt int userId)319         protected BaseUserMetric(@UserIdInt int userId) {
320             this.userId = userId;
321         }
322 
323         @Override
toString()324         public String toString() {
325             StringWriter sw = new StringWriter();
326             PrintWriter pw = new PrintWriter(sw);
327             dump(pw);
328             pw.flush();
329             return sw.toString();
330         }
331 
dump(@onNull PrintWriter pw)332         abstract void dump(@NonNull PrintWriter pw);
333     }
334 
335     @VisibleForTesting
336     final class UserStartingMetric extends BaseUserMetric {
337         public final long startTime;
338         public long switchTime;
339         public long unlockingTime;
340         public long unlockedTime;
341         public @UserIdInt int switchFromUserId;
342 
UserStartingMetric(@serIdInt int userId, long startTime)343         UserStartingMetric(@UserIdInt int userId, long startTime) {
344             super(userId);
345             this.startTime = startTime;
346         }
347 
348         @Override
dump(@onNull PrintWriter pw)349         public void dump(@NonNull PrintWriter pw) {
350             pw.printf("user=%d start=", userId);
351             TimeUtils.dumpTime(pw, startTime);
352 
353             if (switchTime > 0) {
354                 long delta = switchTime - startTime;
355                 pw.print(" switch");
356                 if (switchFromUserId != 0) {
357                     pw.printf("(from %d)", switchFromUserId);
358                 }
359                 pw.print('=');
360                 TimeUtils.formatDuration(delta, pw);
361             }
362 
363             if (unlockingTime > 0) {
364                 long delta = unlockingTime - startTime;
365                 pw.print(" unlocking=");
366                 TimeUtils.formatDuration(delta, pw);
367             }
368             if (unlockedTime > 0) {
369                 long delta = unlockedTime - startTime;
370                 pw.print(" unlocked=");
371                 TimeUtils.formatDuration(delta, pw);
372             }
373         }
374     }
375 
376     @VisibleForTesting
377     final class UserStoppingMetric extends BaseUserMetric {
378         public final long stopTime;
379         public long shutdownTime;
380 
UserStoppingMetric(@serIdInt int userId, long stopTime)381         UserStoppingMetric(@UserIdInt int userId, long stopTime) {
382             super(userId);
383             this.stopTime = stopTime;
384         }
385 
386         @Override
dump(@onNull PrintWriter pw)387         public void dump(@NonNull PrintWriter pw) {
388             pw.printf("user=%d stop=", userId);
389             TimeUtils.dumpTime(pw, stopTime);
390 
391             if (shutdownTime > 0) {
392                 long delta = shutdownTime - stopTime;
393                 pw.print(" shutdown=");
394                 TimeUtils.formatDuration(delta, pw);
395             }
396         }
397     }
398 }
399