1 /* 2 * Copyright (C) 2022 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.server.inputmethod; 18 19 import android.Manifest; 20 import android.annotation.EnforcePermission; 21 import android.annotation.NonNull; 22 import android.annotation.Nullable; 23 import android.os.Binder; 24 import android.os.Handler; 25 import android.os.IBinder; 26 import android.util.Log; 27 import android.view.inputmethod.ImeTracker; 28 29 import com.android.internal.annotations.GuardedBy; 30 import com.android.internal.infra.AndroidFuture; 31 import com.android.internal.inputmethod.IImeTracker; 32 import com.android.internal.inputmethod.InputMethodDebug; 33 import com.android.internal.inputmethod.SoftInputShowHideReason; 34 import com.android.internal.util.FrameworkStatsLog; 35 36 import java.io.PrintWriter; 37 import java.time.Instant; 38 import java.time.ZoneId; 39 import java.time.format.DateTimeFormatter; 40 import java.util.ArrayDeque; 41 import java.util.Locale; 42 import java.util.WeakHashMap; 43 import java.util.concurrent.atomic.AtomicInteger; 44 45 /** 46 * Service for managing and logging {@link ImeTracker.Token} instances. 47 * 48 * @implNote Suppresses {@link GuardedBy} warnings, as linter reports that {@link #mHistory} 49 * interactions are guarded by {@code this} instead of {@code ImeTrackerService.this}, which should 50 * be identical. 51 * 52 * @hide 53 */ 54 @SuppressWarnings("GuardedBy") 55 public final class ImeTrackerService extends IImeTracker.Stub { 56 57 private static final String TAG = ImeTracker.TAG; 58 59 /** The threshold in milliseconds after which a history entry is considered timed out. */ 60 private static final long TIMEOUT_MS = 10_000; 61 62 /** Handler for registering timeouts for live entries. */ 63 @GuardedBy("mLock") 64 private final Handler mHandler; 65 66 /** Singleton instance of the History. */ 67 @GuardedBy("mLock") 68 private final History mHistory = new History(); 69 70 private final Object mLock = new Object(); 71 ImeTrackerService(@onNull Handler handler)72 ImeTrackerService(@NonNull Handler handler) { 73 mHandler = handler; 74 } 75 76 @NonNull 77 @Override onStart(@onNull String tag, int uid, @ImeTracker.Type int type, @ImeTracker.Origin int origin, @SoftInputShowHideReason int reason, boolean fromUser)78 public ImeTracker.Token onStart(@NonNull String tag, int uid, @ImeTracker.Type int type, 79 @ImeTracker.Origin int origin, @SoftInputShowHideReason int reason, boolean fromUser) { 80 final var binder = new Binder(); 81 final var token = new ImeTracker.Token(binder, tag); 82 final var entry = new History.Entry(tag, uid, type, ImeTracker.STATUS_RUN, origin, reason, 83 fromUser); 84 synchronized (mLock) { 85 mHistory.addEntry(binder, entry); 86 87 // Register a delayed task to handle the case where the new entry times out. 88 mHandler.postDelayed(() -> { 89 synchronized (mLock) { 90 mHistory.setFinished(token, ImeTracker.STATUS_TIMEOUT, 91 ImeTracker.PHASE_NOT_SET); 92 } 93 }, TIMEOUT_MS); 94 } 95 return token; 96 } 97 98 @Override onProgress(@onNull IBinder binder, @ImeTracker.Phase int phase)99 public void onProgress(@NonNull IBinder binder, @ImeTracker.Phase int phase) { 100 synchronized (mLock) { 101 final var entry = mHistory.getEntry(binder); 102 if (entry == null) return; 103 104 entry.mPhase = phase; 105 } 106 } 107 108 @Override onFailed(@onNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase)109 public void onFailed(@NonNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase) { 110 synchronized (mLock) { 111 mHistory.setFinished(statsToken, ImeTracker.STATUS_FAIL, phase); 112 } 113 } 114 115 @Override onCancelled(@onNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase)116 public void onCancelled(@NonNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase) { 117 synchronized (mLock) { 118 mHistory.setFinished(statsToken, ImeTracker.STATUS_CANCEL, phase); 119 } 120 } 121 122 @Override onShown(@onNull ImeTracker.Token statsToken)123 public void onShown(@NonNull ImeTracker.Token statsToken) { 124 synchronized (mLock) { 125 mHistory.setFinished(statsToken, ImeTracker.STATUS_SUCCESS, ImeTracker.PHASE_NOT_SET); 126 } 127 } 128 129 @Override onHidden(@onNull ImeTracker.Token statsToken)130 public void onHidden(@NonNull ImeTracker.Token statsToken) { 131 synchronized (mLock) { 132 mHistory.setFinished(statsToken, ImeTracker.STATUS_SUCCESS, ImeTracker.PHASE_NOT_SET); 133 } 134 } 135 136 @Override onDispatched(@onNull ImeTracker.Token statsToken)137 public void onDispatched(@NonNull ImeTracker.Token statsToken) { 138 synchronized (mLock) { 139 mHistory.setFinished(statsToken, ImeTracker.STATUS_SUCCESS, ImeTracker.PHASE_NOT_SET); 140 } 141 } 142 143 /** 144 * Updates the IME request tracking token with new information available in IMMS. 145 * 146 * @param statsToken the token tracking the current IME request. 147 * @param requestWindowName the name of the window that created the IME request. 148 */ onImmsUpdate(@onNull ImeTracker.Token statsToken, @NonNull String requestWindowName)149 public void onImmsUpdate(@NonNull ImeTracker.Token statsToken, 150 @NonNull String requestWindowName) { 151 synchronized (mLock) { 152 final var entry = mHistory.getEntry(statsToken.getBinder()); 153 if (entry == null) return; 154 155 entry.mRequestWindowName = requestWindowName; 156 } 157 } 158 159 /** Dumps the contents of the history. */ dump(@onNull PrintWriter pw, @NonNull String prefix)160 public void dump(@NonNull PrintWriter pw, @NonNull String prefix) { 161 synchronized (mLock) { 162 mHistory.dump(pw, prefix); 163 } 164 } 165 166 @EnforcePermission(Manifest.permission.TEST_INPUT_METHOD) 167 @Override hasPendingImeVisibilityRequests()168 public boolean hasPendingImeVisibilityRequests() { 169 super.hasPendingImeVisibilityRequests_enforcePermission(); 170 synchronized (mLock) { 171 return !mHistory.mLiveEntries.isEmpty(); 172 } 173 } 174 175 @EnforcePermission(Manifest.permission.TEST_INPUT_METHOD) 176 @Override finishTrackingPendingImeVisibilityRequests( @onNull AndroidFuture completionSignal )177 public void finishTrackingPendingImeVisibilityRequests( 178 @NonNull AndroidFuture completionSignal /* T=Void */) { 179 super.finishTrackingPendingImeVisibilityRequests_enforcePermission(); 180 @SuppressWarnings("unchecked") 181 final AndroidFuture<Void> typedCompletionSignal = completionSignal; 182 try { 183 synchronized (mLock) { 184 mHistory.mLiveEntries.clear(); 185 } 186 typedCompletionSignal.complete(null); 187 } catch (Throwable e) { 188 typedCompletionSignal.completeExceptionally(e); 189 } 190 } 191 192 /** 193 * A circular buffer storing the most recent few {@link ImeTracker.Token} entries information. 194 */ 195 private static final class History { 196 197 /** The circular buffer's capacity. */ 198 private static final int CAPACITY = 100; 199 200 /** Backing store for the circular buffer. */ 201 @GuardedBy("ImeTrackerService.this") 202 private final ArrayDeque<Entry> mEntries = new ArrayDeque<>(CAPACITY); 203 204 /** Backing store for the live entries (i.e. entries that are not finished yet). */ 205 @GuardedBy("ImeTrackerService.this") 206 private final WeakHashMap<IBinder, Entry> mLiveEntries = new WeakHashMap<>(); 207 208 /** Latest entry sequence number. */ 209 private static final AtomicInteger sSequenceNumber = new AtomicInteger(0); 210 211 /** Adds a live entry corresponding to the given IME tracking token's binder. */ 212 @GuardedBy("ImeTrackerService.this") addEntry(@onNull IBinder binder, @NonNull Entry entry)213 private void addEntry(@NonNull IBinder binder, @NonNull Entry entry) { 214 mLiveEntries.put(binder, entry); 215 } 216 217 /** Gets the entry corresponding to the given IME tracking token's binder, if it exists. */ 218 @Nullable 219 @GuardedBy("ImeTrackerService.this") getEntry(@onNull IBinder binder)220 private Entry getEntry(@NonNull IBinder binder) { 221 return mLiveEntries.get(binder); 222 } 223 224 /** 225 * Sets the live entry corresponding to the tracking token, if it exists, as finished, 226 * and uploads the data for metrics. 227 * 228 * @param statsToken the token tracking the current IME request. 229 * @param status the finish status of the IME request. 230 * @param phase the phase the IME request finished at, if it exists 231 * (or {@link ImeTracker#PHASE_NOT_SET} otherwise). 232 */ 233 @GuardedBy("ImeTrackerService.this") setFinished(@onNull ImeTracker.Token statsToken, @ImeTracker.Status int status, @ImeTracker.Phase int phase)234 private void setFinished(@NonNull ImeTracker.Token statsToken, 235 @ImeTracker.Status int status, @ImeTracker.Phase int phase) { 236 final var entry = mLiveEntries.remove(statsToken.getBinder()); 237 if (entry == null) { 238 // This will be unconditionally called through the postDelayed above to handle 239 // potential timeouts, and is thus intentionally dropped to avoid having to manually 240 // save and remove the registered callback. Only timeout calls are expected. 241 if (status != ImeTracker.STATUS_TIMEOUT) { 242 Log.i(TAG, statsToken.getTag() 243 + ": setFinished on previously finished token at " 244 + ImeTracker.Debug.phaseToString(phase) + " with " 245 + ImeTracker.Debug.statusToString(status)); 246 } 247 return; 248 } 249 250 entry.mDuration = System.currentTimeMillis() - entry.mStartTime; 251 entry.mStatus = status; 252 253 if (phase != ImeTracker.PHASE_NOT_SET) { 254 entry.mPhase = phase; 255 } 256 257 if (status == ImeTracker.STATUS_TIMEOUT) { 258 // All events other than timeouts are already logged in the client-side ImeTracker. 259 Log.i(TAG, statsToken.getTag() + ": setFinished at " 260 + ImeTracker.Debug.phaseToString(entry.mPhase) + " with " 261 + ImeTracker.Debug.statusToString(status)); 262 } 263 264 // Remove excess entries overflowing capacity (plus one for the new entry). 265 while (mEntries.size() >= CAPACITY) { 266 mEntries.remove(); 267 } 268 269 mEntries.offer(entry); 270 271 // Log newly finished entry. 272 FrameworkStatsLog.write(FrameworkStatsLog.IME_REQUEST_FINISHED, entry.mUid, 273 entry.mDuration, entry.mType, entry.mStatus, entry.mReason, 274 entry.mOrigin, entry.mPhase, entry.mFromUser); 275 } 276 277 /** Dumps the contents of the circular buffer. */ 278 @GuardedBy("ImeTrackerService.this") dump(@onNull PrintWriter pw, @NonNull String prefix)279 private void dump(@NonNull PrintWriter pw, @NonNull String prefix) { 280 final var formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS", Locale.US) 281 .withZone(ZoneId.systemDefault()); 282 283 pw.print(prefix); 284 pw.println("mLiveEntries: " + mLiveEntries.size() + " elements"); 285 286 for (final var entry: mLiveEntries.values()) { 287 dumpEntry(entry, pw, prefix + " ", formatter); 288 } 289 pw.print(prefix); 290 pw.println("mEntries: " + mEntries.size() + " elements"); 291 292 for (final var entry: mEntries) { 293 dumpEntry(entry, pw, prefix + " ", formatter); 294 } 295 } 296 297 @GuardedBy("ImeTrackerService.this") dumpEntry(@onNull Entry entry, @NonNull PrintWriter pw, @NonNull String prefix, @NonNull DateTimeFormatter formatter)298 private void dumpEntry(@NonNull Entry entry, @NonNull PrintWriter pw, 299 @NonNull String prefix, @NonNull DateTimeFormatter formatter) { 300 pw.print(prefix); 301 pw.print("#" + entry.mSequenceNumber); 302 pw.print(" " + ImeTracker.Debug.typeToString(entry.mType)); 303 pw.print(" - " + ImeTracker.Debug.statusToString(entry.mStatus)); 304 pw.print(" - " + entry.mTag); 305 pw.println(" (" + entry.mDuration + "ms):"); 306 307 pw.print(prefix); 308 pw.print(" startTime=" + formatter.format(Instant.ofEpochMilli(entry.mStartTime))); 309 pw.println(" " + ImeTracker.Debug.originToString(entry.mOrigin)); 310 311 pw.print(prefix); 312 pw.print(" reason=" + InputMethodDebug.softInputDisplayReasonToString(entry.mReason)); 313 pw.println(" " + ImeTracker.Debug.phaseToString(entry.mPhase)); 314 315 pw.print(prefix); 316 pw.println(" requestWindowName=" + entry.mRequestWindowName); 317 } 318 319 /** A history entry. */ 320 private static final class Entry { 321 322 /** The entry's sequence number in the history. */ 323 private final int mSequenceNumber = sSequenceNumber.getAndIncrement(); 324 325 /** Logging tag, of the shape "component:random_hexadecimal". */ 326 @NonNull 327 private final String mTag; 328 329 /** Uid of the client that requested the IME. */ 330 private final int mUid; 331 332 /** Clock time in milliseconds when the IME request was created. */ 333 private final long mStartTime = System.currentTimeMillis(); 334 335 /** Duration in milliseconds of the IME request from start to end. */ 336 private long mDuration = 0; 337 338 /** Type of the IME request. */ 339 @ImeTracker.Type 340 private final int mType; 341 342 /** Status of the IME request. */ 343 @ImeTracker.Status 344 private int mStatus; 345 346 /** Origin of the IME request. */ 347 @ImeTracker.Origin 348 private final int mOrigin; 349 350 /** Reason for creating the IME request. */ 351 @SoftInputShowHideReason 352 private final int mReason; 353 354 /** Latest phase of the IME request. */ 355 @ImeTracker.Phase 356 private int mPhase = ImeTracker.PHASE_NOT_SET; 357 358 /** Whether this request was created directly from a user interaction. */ 359 private final boolean mFromUser; 360 361 /** 362 * Name of the window that created the IME request. 363 * 364 * Note: This is later set through {@link #onImmsUpdate}. 365 */ 366 @NonNull 367 private String mRequestWindowName = "not set"; 368 Entry(@onNull String tag, int uid, @ImeTracker.Type int type, @ImeTracker.Status int status, @ImeTracker.Origin int origin, @SoftInputShowHideReason int reason, boolean fromUser)369 private Entry(@NonNull String tag, int uid, @ImeTracker.Type int type, 370 @ImeTracker.Status int status, @ImeTracker.Origin int origin, 371 @SoftInputShowHideReason int reason, boolean fromUser) { 372 mTag = tag; 373 mUid = uid; 374 mType = type; 375 mStatus = status; 376 mOrigin = origin; 377 mReason = reason; 378 mFromUser = fromUser; 379 } 380 } 381 } 382 } 383