blob: 27e1b9a303f2269352cf12b06a0787257a5c9ec8 [file] [log] [blame]
/*
* Copyright (C) 2022 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.server.inputmethod;
import android.Manifest;
import android.annotation.EnforcePermission;
import android.annotation.NonNull;
import android.annotation.Nullable;
import android.os.Binder;
import android.os.Handler;
import android.os.IBinder;
import android.os.Looper;
import android.util.Log;
import android.view.inputmethod.ImeTracker;
import com.android.internal.annotations.GuardedBy;
import com.android.internal.inputmethod.IImeTracker;
import com.android.internal.inputmethod.InputMethodDebug;
import com.android.internal.inputmethod.SoftInputShowHideReason;
import com.android.internal.util.FrameworkStatsLog;
import java.io.PrintWriter;
import java.time.Instant;
import java.time.ZoneId;
import java.time.format.DateTimeFormatter;
import java.util.ArrayDeque;
import java.util.Locale;
import java.util.WeakHashMap;
import java.util.concurrent.atomic.AtomicInteger;
/**
* Service for managing and logging {@link ImeTracker.Token} instances.
*
* @implNote Suppresses {@link GuardedBy} warnings, as linter reports that {@link #mHistory}
* interactions are guarded by {@code this} instead of {@code ImeTrackerService.this}, which should
* be identical.
*
* @hide
*/
@SuppressWarnings("GuardedBy")
public final class ImeTrackerService extends IImeTracker.Stub {
private static final String TAG = ImeTracker.TAG;
/** The threshold in milliseconds after which a history entry is considered timed out. */
private static final long TIMEOUT_MS = 10_000;
/** Handler for registering timeouts for live entries. */
@GuardedBy("mLock")
private final Handler mHandler;
/** Singleton instance of the History. */
@GuardedBy("mLock")
private final History mHistory = new History();
private final Object mLock = new Object();
ImeTrackerService(@NonNull Looper looper) {
mHandler = new Handler(looper, null /* callback */, true /* async */);
}
@NonNull
@Override
public ImeTracker.Token onRequestShow(@NonNull String tag, int uid,
@ImeTracker.Origin int origin, @SoftInputShowHideReason int reason) {
final var binder = new Binder();
final var token = new ImeTracker.Token(binder, tag);
final var entry = new History.Entry(tag, uid, ImeTracker.TYPE_SHOW, ImeTracker.STATUS_RUN,
origin, reason);
synchronized (mLock) {
mHistory.addEntry(binder, entry);
// Register a delayed task to handle the case where the new entry times out.
mHandler.postDelayed(() -> {
synchronized (mLock) {
mHistory.setFinished(token, ImeTracker.STATUS_TIMEOUT,
ImeTracker.PHASE_NOT_SET);
}
}, TIMEOUT_MS);
}
return token;
}
@NonNull
@Override
public ImeTracker.Token onRequestHide(@NonNull String tag, int uid,
@ImeTracker.Origin int origin, @SoftInputShowHideReason int reason) {
final var binder = new Binder();
final var token = new ImeTracker.Token(binder, tag);
final var entry = new History.Entry(tag, uid, ImeTracker.TYPE_HIDE, ImeTracker.STATUS_RUN,
origin, reason);
synchronized (mLock) {
mHistory.addEntry(binder, entry);
// Register a delayed task to handle the case where the new entry times out.
mHandler.postDelayed(() -> {
synchronized (mLock) {
mHistory.setFinished(token, ImeTracker.STATUS_TIMEOUT,
ImeTracker.PHASE_NOT_SET);
}
}, TIMEOUT_MS);
}
return token;
}
@Override
public void onProgress(@NonNull IBinder binder, @ImeTracker.Phase int phase) {
synchronized (mLock) {
final var entry = mHistory.getEntry(binder);
if (entry == null) return;
entry.mPhase = phase;
}
}
@Override
public void onFailed(@NonNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase) {
synchronized (mLock) {
mHistory.setFinished(statsToken, ImeTracker.STATUS_FAIL, phase);
}
}
@Override
public void onCancelled(@NonNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase) {
synchronized (mLock) {
mHistory.setFinished(statsToken, ImeTracker.STATUS_CANCEL, phase);
}
}
@Override
public void onShown(@NonNull ImeTracker.Token statsToken) {
synchronized (mLock) {
mHistory.setFinished(statsToken, ImeTracker.STATUS_SUCCESS, ImeTracker.PHASE_NOT_SET);
}
}
@Override
public void onHidden(@NonNull ImeTracker.Token statsToken) {
synchronized (mLock) {
mHistory.setFinished(statsToken, ImeTracker.STATUS_SUCCESS, ImeTracker.PHASE_NOT_SET);
}
}
/**
* Updates the IME request tracking token with new information available in IMMS.
*
* @param statsToken the token corresponding to the current IME request.
* @param requestWindowName the name of the window that created the IME request.
*/
public void onImmsUpdate(@NonNull ImeTracker.Token statsToken,
@NonNull String requestWindowName) {
synchronized (mLock) {
final var entry = mHistory.getEntry(statsToken.getBinder());
if (entry == null) return;
entry.mRequestWindowName = requestWindowName;
}
}
/** Dumps the contents of the history. */
public void dump(@NonNull PrintWriter pw, @NonNull String prefix) {
synchronized (mLock) {
mHistory.dump(pw, prefix);
}
}
@EnforcePermission(Manifest.permission.TEST_INPUT_METHOD)
@Override
public boolean hasPendingImeVisibilityRequests() {
super.hasPendingImeVisibilityRequests_enforcePermission();
synchronized (mLock) {
return !mHistory.mLiveEntries.isEmpty();
}
}
/**
* A circular buffer storing the most recent few {@link ImeTracker.Token} entries information.
*/
private static final class History {
/** The circular buffer's capacity. */
private static final int CAPACITY = 100;
/** Backing store for the circular buffer. */
@GuardedBy("ImeTrackerService.this")
private final ArrayDeque<Entry> mEntries = new ArrayDeque<>(CAPACITY);
/** Backing store for the live entries (i.e. entries that are not finished yet). */
@GuardedBy("ImeTrackerService.this")
private final WeakHashMap<IBinder, Entry> mLiveEntries = new WeakHashMap<>();
/** Latest entry sequence number. */
private static final AtomicInteger sSequenceNumber = new AtomicInteger(0);
/** Adds a live entry corresponding to the given IME tracking token's binder. */
@GuardedBy("ImeTrackerService.this")
private void addEntry(@NonNull IBinder binder, @NonNull Entry entry) {
mLiveEntries.put(binder, entry);
}
/** Gets the entry corresponding to the given IME tracking token's binder, if it exists. */
@Nullable
@GuardedBy("ImeTrackerService.this")
private Entry getEntry(@NonNull IBinder binder) {
return mLiveEntries.get(binder);
}
/**
* Sets the live entry corresponding to the tracking token, if it exists, as finished,
* and uploads the data for metrics.
*
* @param statsToken the token corresponding to the current IME request.
* @param status the finish status of the IME request.
* @param phase the phase the IME request finished at, if it exists
* (or {@link ImeTracker#PHASE_NOT_SET} otherwise).
*/
@GuardedBy("ImeTrackerService.this")
private void setFinished(@NonNull ImeTracker.Token statsToken,
@ImeTracker.Status int status, @ImeTracker.Phase int phase) {
final var entry = mLiveEntries.remove(statsToken.getBinder());
if (entry == null) {
// This will be unconditionally called through the postDelayed above to handle
// potential timeouts, and is thus intentionally dropped to avoid having to manually
// save and remove the registered callback. Only timeout calls are expected.
if (status != ImeTracker.STATUS_TIMEOUT) {
Log.i(TAG, statsToken.getTag()
+ ": setFinished on previously finished token at "
+ ImeTracker.Debug.phaseToString(phase) + " with "
+ ImeTracker.Debug.statusToString(status));
}
return;
}
entry.mDuration = System.currentTimeMillis() - entry.mStartTime;
entry.mStatus = status;
if (phase != ImeTracker.PHASE_NOT_SET) {
entry.mPhase = phase;
}
if (status == ImeTracker.STATUS_TIMEOUT) {
// All events other than timeouts are already logged in the client-side ImeTracker.
Log.i(TAG, statsToken.getTag() + ": setFinished at "
+ ImeTracker.Debug.phaseToString(entry.mPhase) + " with "
+ ImeTracker.Debug.statusToString(status));
}
// Remove excess entries overflowing capacity (plus one for the new entry).
while (mEntries.size() >= CAPACITY) {
mEntries.remove();
}
mEntries.offer(entry);
// Log newly finished entry.
FrameworkStatsLog.write(FrameworkStatsLog.IME_REQUEST_FINISHED, entry.mUid,
entry.mDuration, entry.mType, entry.mStatus, entry.mReason,
entry.mOrigin, entry.mPhase);
}
/** Dumps the contents of the circular buffer. */
@GuardedBy("ImeTrackerService.this")
private void dump(@NonNull PrintWriter pw, @NonNull String prefix) {
final var formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS", Locale.US)
.withZone(ZoneId.systemDefault());
pw.print(prefix);
pw.println("mLiveEntries: " + mLiveEntries.size() + " elements");
for (final var entry: mLiveEntries.values()) {
dumpEntry(entry, pw, prefix + " ", formatter);
}
pw.print(prefix);
pw.println("mEntries: " + mEntries.size() + " elements");
for (final var entry: mEntries) {
dumpEntry(entry, pw, prefix + " ", formatter);
}
}
@GuardedBy("ImeTrackerService.this")
private void dumpEntry(@NonNull Entry entry, @NonNull PrintWriter pw,
@NonNull String prefix, @NonNull DateTimeFormatter formatter) {
pw.print(prefix);
pw.print("#" + entry.mSequenceNumber);
pw.print(" " + ImeTracker.Debug.typeToString(entry.mType));
pw.print(" - " + ImeTracker.Debug.statusToString(entry.mStatus));
pw.print(" - " + entry.mTag);
pw.println(" (" + entry.mDuration + "ms):");
pw.print(prefix);
pw.print(" startTime=" + formatter.format(Instant.ofEpochMilli(entry.mStartTime)));
pw.println(" " + ImeTracker.Debug.originToString(entry.mOrigin));
pw.print(prefix);
pw.print(" reason=" + InputMethodDebug.softInputDisplayReasonToString(entry.mReason));
pw.println(" " + ImeTracker.Debug.phaseToString(entry.mPhase));
pw.print(prefix);
pw.println(" requestWindowName=" + entry.mRequestWindowName);
}
/** A history entry. */
private static final class Entry {
/** The entry's sequence number in the history. */
private final int mSequenceNumber = sSequenceNumber.getAndIncrement();
/** Logging tag, of the shape "component:random_hexadecimal". */
@NonNull
private final String mTag;
/** Uid of the client that requested the IME. */
private final int mUid;
/** Clock time in milliseconds when the IME request was created. */
private final long mStartTime = System.currentTimeMillis();
/** Duration in milliseconds of the IME request from start to end. */
private long mDuration = 0;
/** Type of the IME request. */
@ImeTracker.Type
private final int mType;
/** Status of the IME request. */
@ImeTracker.Status
private int mStatus;
/** Origin of the IME request. */
@ImeTracker.Origin
private final int mOrigin;
/** Reason for creating the IME request. */
@SoftInputShowHideReason
private final int mReason;
/** Latest phase of the IME request. */
@ImeTracker.Phase
private int mPhase = ImeTracker.PHASE_NOT_SET;
/**
* Name of the window that created the IME request.
*
* Note: This is later set through {@link #onImmsUpdate}.
*/
@NonNull
private String mRequestWindowName = "not set";
private Entry(@NonNull String tag, int uid, @ImeTracker.Type int type,
@ImeTracker.Status int status, @ImeTracker.Origin int origin,
@SoftInputShowHideReason int reason) {
mTag = tag;
mUid = uid;
mType = type;
mStatus = status;
mOrigin = origin;
mReason = reason;
}
}
}
}