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 android.inputmethod; 18 19 import static android.perftests.utils.ManualBenchmarkState.StatsReport; 20 import static android.perftests.utils.PerfTestActivity.ID_EDITOR; 21 import static android.perftests.utils.TestUtils.getOnMainSync; 22 import static android.view.ViewGroup.LayoutParams.MATCH_PARENT; 23 import static android.view.WindowInsetsAnimation.Callback.DISPATCH_MODE_STOP; 24 25 import static androidx.test.platform.app.InstrumentationRegistry.getInstrumentation; 26 27 import android.annotation.UiThread; 28 import android.app.Activity; 29 import android.content.ComponentName; 30 import android.content.Context; 31 import android.inputmethodservice.InputMethodService; 32 import android.os.Process; 33 import android.os.SystemClock; 34 import android.perftests.utils.ManualBenchmarkState; 35 import android.perftests.utils.ManualBenchmarkState.ManualBenchmarkTest; 36 import android.perftests.utils.PerfManualStatusReporter; 37 import android.perftests.utils.TraceMarkParser; 38 import android.perftests.utils.TraceMarkParser.TraceMarkSlice; 39 import android.provider.Settings; 40 import android.text.TextUtils; 41 import android.util.Log; 42 import android.view.View; 43 import android.view.ViewGroup; 44 import android.view.WindowInsets; 45 import android.view.WindowInsetsAnimation; 46 import android.view.WindowInsetsController; 47 import android.view.inputmethod.InputMethodManager; 48 import android.widget.FrameLayout; 49 50 import androidx.annotation.NonNull; 51 import androidx.annotation.Nullable; 52 import androidx.test.filters.LargeTest; 53 54 import com.android.compatibility.common.util.PollingCheck; 55 import com.android.compatibility.common.util.SystemUtil; 56 57 import junit.framework.Assert; 58 59 import org.junit.Rule; 60 import org.junit.Test; 61 62 import java.io.BufferedReader; 63 import java.io.IOException; 64 import java.io.InputStream; 65 import java.io.InputStreamReader; 66 import java.util.List; 67 import java.util.concurrent.CountDownLatch; 68 import java.util.concurrent.TimeUnit; 69 import java.util.concurrent.atomic.AtomicBoolean; 70 import java.util.concurrent.atomic.AtomicLong; 71 import java.util.concurrent.atomic.AtomicReference; 72 73 /** Measure the performance of internal methods in Input Method framework by trace tag. */ 74 @LargeTest 75 public class ImePerfTest extends ImePerfTestBase 76 implements ManualBenchmarkState.CustomizedIterationListener { 77 private static final String TAG = ImePerfTest.class.getSimpleName(); 78 private static final long ANIMATION_NOT_STARTED = -1; 79 private static final int WAIT_PROCESS_KILL_TIMEOUT_MS = 2000; 80 81 @Rule 82 public final PerfManualStatusReporter mPerfStatusReporter = new PerfManualStatusReporter(); 83 84 @Rule 85 public final PerfTestActivityRule mActivityRule = new PerfTestActivityRule(); 86 87 /** 88 * IMF common methods to log for show/hide in trace. 89 */ 90 private String[] mCommonMethods = { 91 "IC.pendingAnim", 92 "IMMS.applyImeVisibility", 93 "applyPostLayoutPolicy", 94 "applyWindowSurfaceChanges", 95 "ISC.onPostLayout" 96 }; 97 98 /** IMF show methods to log in trace. */ 99 private String[] mShowMethods = { 100 "IC.showRequestFromIme", 101 "IC.showRequestFromApi", 102 "IC.showRequestFromApiToImeReady", 103 "IC.pendingAnim", 104 "IMMS.applyImeVisibility", 105 "IMMS.showMySoftInput", 106 "IMMS.showSoftInput", 107 "IMS.showSoftInput", 108 "IMS.startInput", 109 "WMS.showImePostLayout", 110 "IMS.updateFullscreenMode", 111 "IMS.onComputeInsets", 112 "IMS.showWindow" 113 }; 114 115 /** IMF show methods to log in trace. */ 116 private String[] mShowMethodsCold = { 117 "IMS.bindInput", 118 "IMS.initializeInternal", 119 "IMS.restartInput", 120 "IMS.onCreate", 121 "IMS.initSoftInputWindow", 122 "IMS.resetStateForNewConfiguration", 123 "IMMS.onServiceConnected", 124 "IMMS.sessionCreated", 125 "IMMS.startInputOrWindowGainedFocus" 126 }; 127 128 /** IMF hide lifecycle methods to log in trace. */ 129 private String[] mHideMethods = { 130 "IC.hideRequestFromIme", 131 "IC.hideRequestFromApi", 132 "IMMS.hideMySoftInput", 133 "IMMS.hideSoftInput", 134 "IMS.hideSoftInput", 135 "WMS.hideIme" 136 }; 137 138 /** 139 * IMF methods to log in trace. 140 */ 141 private TraceMarkParser mTraceMethods; 142 143 private boolean mIsTraceStarted; 144 145 /** 146 * Ime Session for {@link BaselineIme}. 147 */ 148 private static class ImeSession implements AutoCloseable { 149 150 private static final long TIMEOUT = 2000; 151 private final ComponentName mImeName; 152 private Context mContext = getInstrumentation().getContext(); 153 ImeSession(ComponentName ime)154 ImeSession(ComponentName ime) throws Exception { 155 mImeName = ime; 156 // using adb, enable and set Baseline IME. 157 executeShellCommand("ime reset"); 158 executeShellCommand("ime enable " + ime.flattenToShortString()); 159 executeShellCommand("ime set " + ime.flattenToShortString()); 160 PollingCheck.check("Make sure that BaselineIme becomes available " 161 + getCurrentInputMethodId(), TIMEOUT, 162 () -> ime.equals(getCurrentInputMethodId())); 163 } 164 165 @Override close()166 public void close() throws Exception { 167 executeShellCommand("ime reset"); 168 PollingCheck.check("Make sure that Baseline IME becomes unavailable", TIMEOUT, () -> 169 mContext.getSystemService(InputMethodManager.class) 170 .getEnabledInputMethodList() 171 .stream() 172 .noneMatch(info -> mImeName.equals(info.getComponent()))); 173 } 174 175 @Nullable getCurrentInputMethodId()176 private ComponentName getCurrentInputMethodId() { 177 return ComponentName.unflattenFromString( 178 Settings.Secure.getString(mContext.getContentResolver(), 179 Settings.Secure.DEFAULT_INPUT_METHOD)); 180 } 181 } 182 183 /** 184 * A minimal baseline IME (that has a single static view) used to measure IMF latency. 185 */ 186 public static class BaselineIme extends InputMethodService { 187 188 public static final int HEIGHT_DP = 100; 189 190 @Override onCreateInputView()191 public View onCreateInputView() { 192 final ViewGroup view = new FrameLayout(this); 193 final View inner = new View(this); 194 final float density = getResources().getDisplayMetrics().density; 195 final int height = (int) (HEIGHT_DP * density); 196 view.setPadding(0, 0, 0, 0); 197 view.addView(inner, new FrameLayout.LayoutParams(MATCH_PARENT, height)); 198 inner.setBackgroundColor(0xff01fe10); // green 199 Log.v(TAG, "onCreateInputView"); 200 return view; 201 } 202 getName(Context context)203 static ComponentName getName(Context context) { 204 return new ComponentName(context, BaselineIme.class); 205 } 206 } 207 208 @Test 209 @ManualBenchmarkTest( 210 targetTestDurationNs = 10 * TIME_1_S_IN_NS, 211 statsReport = @StatsReport( 212 flags = StatsReport.FLAG_ITERATION | StatsReport.FLAG_MEAN 213 | StatsReport.FLAG_MIN | StatsReport.FLAG_MAX 214 | StatsReport.FLAG_COEFFICIENT_VAR)) testShowImeWarm()215 public void testShowImeWarm() throws Throwable { 216 testShowOrHideImeWarm(true /* show */); 217 } 218 219 @Test 220 @ManualBenchmarkTest( 221 targetTestDurationNs = 10 * TIME_1_S_IN_NS, 222 statsReport = @StatsReport( 223 flags = StatsReport.FLAG_ITERATION | StatsReport.FLAG_MEAN 224 | StatsReport.FLAG_MIN | StatsReport.FLAG_MAX 225 | StatsReport.FLAG_COEFFICIENT_VAR)) testHideIme()226 public void testHideIme() throws Throwable { 227 testShowOrHideImeWarm(false /* show */); 228 } 229 230 @Test 231 @ManualBenchmarkTest( 232 targetTestDurationNs = 10 * TIME_1_S_IN_NS, 233 statsReport = @StatsReport( 234 flags = StatsReport.FLAG_ITERATION | StatsReport.FLAG_MEAN 235 | StatsReport.FLAG_MIN | StatsReport.FLAG_MAX 236 | StatsReport.FLAG_COEFFICIENT_VAR)) testShowImeCold()237 public void testShowImeCold() throws Throwable { 238 mTraceMethods = new TraceMarkParser( 239 buildArray(mCommonMethods, mShowMethods, mShowMethodsCold)); 240 241 final ManualBenchmarkState state = mPerfStatusReporter.getBenchmarkState(); 242 state.setCustomizedIterations(getProfilingIterations(), this); 243 if (state.isWarmingUp()) { 244 // we don't need to warmup for cold start. 245 return; 246 } 247 248 long measuredTimeNs = 0; 249 boolean shouldRetry = false; 250 while (shouldRetry || state.keepRunning(measuredTimeNs)) { 251 shouldRetry = false; 252 killBaselineImeSync(); 253 try (ImeSession imeSession = new ImeSession(BaselineIme.getName( 254 getInstrumentation().getContext()))) { 255 if (!mIsTraceStarted) { 256 startAsyncAtrace(); 257 } 258 final AtomicReference<CountDownLatch> latchStart = new AtomicReference<>(); 259 final Activity activity = getActivityWithFocus(); 260 261 setImeListener(activity, latchStart, null /* latchEnd */); 262 latchStart.set(new CountDownLatch(1)); 263 264 final WindowInsetsController controller = 265 activity.getWindow().getDecorView().getWindowInsetsController(); 266 AtomicLong startTime = new AtomicLong(); 267 activity.runOnUiThread(() -> { 268 startTime.set(SystemClock.elapsedRealtimeNanos()); 269 controller.show(WindowInsets.Type.ime()); 270 }); 271 272 measuredTimeNs = waitForAnimationStart(latchStart, startTime); 273 stopAsyncAtraceAndDumpTraces(); 274 275 if (measuredTimeNs == ANIMATION_NOT_STARTED) { 276 // Animation didn't start within timeout, 277 // retry for more samples. 278 // TODO(b/264722663): Investigate the animation start failure reason. 279 shouldRetry = true; 280 Log.w(TAG, "Insets animation didn't start within timeout."); 281 } 282 mActivityRule.finishActivity(); 283 } 284 } 285 stopAsyncAtrace(); 286 addResultToState(state); 287 } 288 killBaselineImeSync()289 private void killBaselineImeSync() { 290 // pidof returns a space separated list of numeric PIDs. 291 String result = SystemUtil.runShellCommand( 292 "pidof com.android.perftests.inputmethod:BaselineIME"); 293 for (String pid : result.trim().split(" ")) { 294 // The output may be empty if there is no process with the name. 295 if (TextUtils.isEmpty(pid)) { 296 continue; 297 } 298 final int pidToKill = Integer.parseInt(pid); 299 Process.killProcess(pidToKill); 300 try { 301 // Wait kill IME process being settled down. 302 Process.waitForProcessDeath(pidToKill, WAIT_PROCESS_KILL_TIMEOUT_MS); 303 } catch (Exception e) { 304 } 305 } 306 } 307 testShowOrHideImeWarm(final boolean show)308 private void testShowOrHideImeWarm(final boolean show) throws Throwable { 309 mTraceMethods = new TraceMarkParser(buildArray( 310 mCommonMethods, show ? mShowMethods : mHideMethods)); 311 final ManualBenchmarkState state = mPerfStatusReporter.getBenchmarkState(); 312 state.setCustomizedIterations(getProfilingIterations(), this); 313 long measuredTimeNs = 0; 314 try (ImeSession imeSession = new ImeSession(BaselineIme.getName( 315 getInstrumentation().getContext()))) { 316 final AtomicReference<CountDownLatch> latchStart = new AtomicReference<>(); 317 final AtomicReference<CountDownLatch> latchEnd = new AtomicReference<>(); 318 final Activity activity = getActivityWithFocus(); 319 320 // call IME show/hide 321 final WindowInsetsController controller = 322 activity.getWindow().getDecorView().getWindowInsetsController(); 323 324 while (state.keepRunning(measuredTimeNs)) { 325 setImeListener(activity, latchStart, latchEnd); 326 // For measuring hide, lets show IME first. 327 if (!show) { 328 initLatch(latchStart, latchEnd); 329 AtomicBoolean showCalled = new AtomicBoolean(); 330 getInstrumentation().runOnMainSync(() -> { 331 if (!isImeVisible(activity)) { 332 controller.show(WindowInsets.Type.ime()); 333 showCalled.set(true); 334 } 335 }); 336 if (showCalled.get()) { 337 PollingCheck.check("IME show animation should finish ", 338 TIMEOUT_1_S_IN_MS * 3, 339 () -> latchStart.get().getCount() == 0 340 && latchEnd.get().getCount() == 0); 341 } 342 } 343 if (!mIsTraceStarted && !state.isWarmingUp()) { 344 startAsyncAtrace(); 345 mIsTraceStarted = true; 346 } 347 348 AtomicLong startTime = new AtomicLong(); 349 AtomicBoolean unexpectedVisibility = new AtomicBoolean(); 350 initLatch(latchStart, latchEnd); 351 getInstrumentation().runOnMainSync(() -> { 352 boolean isVisible = isImeVisible(activity); 353 startTime.set(SystemClock.elapsedRealtimeNanos()); 354 355 if (show && !isVisible) { 356 controller.show(WindowInsets.Type.ime()); 357 } else if (!show && isVisible) { 358 controller.hide(WindowInsets.Type.ime()); 359 } else { 360 // ignore this iteration as unexpected IME visibility was encountered. 361 unexpectedVisibility.set(true); 362 } 363 }); 364 365 if (!unexpectedVisibility.get()) { 366 long timeElapsed = waitForAnimationStart(latchStart, startTime); 367 if (timeElapsed != ANIMATION_NOT_STARTED) { 368 measuredTimeNs = timeElapsed; 369 // wait for animation to end or we may start two animations and timing 370 // will not be measured accurately. 371 waitForAnimationEnd(latchEnd); 372 } 373 } 374 375 // hide IME before next iteration. 376 if (show) { 377 initLatch(latchStart, latchEnd); 378 activity.runOnUiThread(() -> controller.hide(WindowInsets.Type.ime())); 379 try { 380 latchEnd.get().await(TIMEOUT_1_S_IN_MS * 5, TimeUnit.MILLISECONDS); 381 if (latchEnd.get().getCount() != 0 382 && getOnMainSync(() -> isImeVisible(activity))) { 383 Assert.fail("IME hide animation should finish."); 384 } 385 } catch (InterruptedException e) { 386 } 387 } 388 } 389 } finally { 390 if (mIsTraceStarted) { 391 stopAsyncAtraceAndDumpTraces(); 392 } 393 } 394 mActivityRule.finishActivity(); 395 396 addResultToState(state); 397 } 398 initLatch(AtomicReference<CountDownLatch> latchStart, AtomicReference<CountDownLatch> latchEnd)399 private void initLatch(AtomicReference<CountDownLatch> latchStart, 400 AtomicReference<CountDownLatch> latchEnd) { 401 latchStart.set(new CountDownLatch(1)); 402 latchEnd.set(new CountDownLatch(1)); 403 } 404 405 @UiThread isImeVisible(@onNull final Activity activity)406 private boolean isImeVisible(@NonNull final Activity activity) { 407 return activity.getWindow().getDecorView().getRootWindowInsets().isVisible( 408 WindowInsets.Type.ime()); 409 } 410 waitForAnimationStart( AtomicReference<CountDownLatch> latchStart, AtomicLong startTime)411 private long waitForAnimationStart( 412 AtomicReference<CountDownLatch> latchStart, AtomicLong startTime) { 413 try { 414 latchStart.get().await(5, TimeUnit.SECONDS); 415 if (latchStart.get().getCount() != 0) { 416 return ANIMATION_NOT_STARTED; 417 } 418 } catch (InterruptedException e) { } 419 420 return SystemClock.elapsedRealtimeNanos() - startTime.get(); 421 } 422 waitForAnimationEnd(AtomicReference<CountDownLatch> latchEnd)423 private void waitForAnimationEnd(AtomicReference<CountDownLatch> latchEnd) { 424 try { 425 latchEnd.get().await(3, TimeUnit.SECONDS); 426 } catch (InterruptedException e) { } 427 } 428 addResultToState(ManualBenchmarkState state)429 private void addResultToState(ManualBenchmarkState state) { 430 mTraceMethods.forAllSlices((key, slices) -> { 431 if (slices.size() < 2) { 432 Log.w(TAG, "No enough samples for: " + key); 433 return; 434 } 435 for (TraceMarkSlice slice : slices) { 436 state.addExtraResult(key, (long) (slice.getDurationInSeconds() * NANOS_PER_S)); 437 } 438 }); 439 Log.i(TAG, String.valueOf(mTraceMethods)); 440 } 441 getActivityWithFocus()442 private Activity getActivityWithFocus() throws Exception { 443 final Activity activity = mActivityRule.launchActivity(); 444 PollingCheck.check("Activity onResume()", TIMEOUT_1_S_IN_MS, 445 () -> activity.isResumed()); 446 447 View editor = activity.findViewById(ID_EDITOR); 448 editor.requestFocus(); 449 450 // wait till editor is focused so we don't count activity/view latency. 451 PollingCheck.check("Editor is focused", TIMEOUT_1_S_IN_MS, 452 () -> editor.isFocused()); 453 getInstrumentation().waitForIdleSync(); 454 455 return activity; 456 } 457 setImeListener(Activity activity, @NonNull AtomicReference<CountDownLatch> latchStart, @Nullable AtomicReference<CountDownLatch> latchEnd)458 private void setImeListener(Activity activity, 459 @NonNull AtomicReference<CountDownLatch> latchStart, 460 @Nullable AtomicReference<CountDownLatch> latchEnd) { 461 // set IME animation listener 462 activity.getWindow().getDecorView().setWindowInsetsAnimationCallback( 463 new WindowInsetsAnimation.Callback(DISPATCH_MODE_STOP) { 464 @NonNull 465 @Override 466 public WindowInsetsAnimation.Bounds onStart( 467 @NonNull WindowInsetsAnimation animation, 468 @NonNull WindowInsetsAnimation.Bounds bounds) { 469 latchStart.get().countDown(); 470 return super.onStart(animation, bounds); 471 } 472 473 @NonNull 474 @Override 475 public WindowInsets onProgress(@NonNull WindowInsets insets, 476 @NonNull List<WindowInsetsAnimation> runningAnimations) { 477 return insets; 478 } 479 480 @Override 481 public void onEnd(@NonNull WindowInsetsAnimation animation) { 482 super.onEnd(animation); 483 if (latchEnd != null) { 484 latchEnd.get().countDown(); 485 } 486 } 487 }); 488 } 489 startAsyncAtrace()490 private void startAsyncAtrace() { 491 mIsTraceStarted = true; 492 // IMF uses 'wm' component for trace in InputMethodService, InputMethodManagerService, 493 // WindowManagerService and 'view' for client window (InsetsController). 494 // TODO(b/167947940): Consider a separate input_method atrace 495 startAsyncAtrace("wm view"); 496 } 497 stopAsyncAtraceAndDumpTraces()498 private void stopAsyncAtraceAndDumpTraces() { 499 if (!mIsTraceStarted) { 500 return; 501 } 502 mIsTraceStarted = false; 503 final InputStream inputStream = stopAsyncAtraceWithStream(); 504 try (BufferedReader reader = new BufferedReader(new InputStreamReader(inputStream))) { 505 String line; 506 while ((line = reader.readLine()) != null) { 507 mTraceMethods.visit(line); 508 } 509 } catch (IOException e) { 510 Log.w(TAG, "Failed to read the result of stopped atrace", e); 511 } 512 } 513 stopAsyncAtrace()514 private void stopAsyncAtrace() { 515 if (!mIsTraceStarted) { 516 return; 517 } 518 mIsTraceStarted = false; 519 getUiAutomation().executeShellCommand("atrace --async_stop"); 520 } 521 522 @Override onStart(int iteration)523 public void onStart(int iteration) { 524 // Do not capture trace when profiling because the result will be much slower. 525 stopAsyncAtrace(); 526 } 527 528 @Override onFinished(int iteration)529 public void onFinished(int iteration) { 530 // do nothing. 531 } 532 } 533