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