From ad3c422f6cf41388ce1221f961d519e3010ba0a8 Mon Sep 17 00:00:00 2001 From: Jordan Silva Date: Wed, 28 Aug 2024 17:06:25 +0100 Subject: [PATCH] Adds a timeout for OverviewCommandHelper commands (3/3) We had several bugs in the past months related to recents button not displaying Overview when using 3 button navigation. For some of the bug reports, we noticed the OverviewCommandHelper pending commands list got stuck and stopped processing the next commands in the list. Sometimes, the pending commands list was cleared while some command was being processed, allowing newer commands to be executed while another command is already running. This resulted in the second callback never returning and inconsistent states for OverviewCommandHelper and RecentsView. Our logs showed OverviewCommandHelper often got stuck and didn't finish the commands correctly. To mitigate these issues we updated the following behaviors: - Implemented a timeout to process the commands in the queue. If the callback doesn't return in a given time, it will drop that execution and process the next one in the queue. - Fix clearPendingCommands to clear only the pending commands from the queue, and not the running command. Bug: 352046797 Fix: 351122926 Fix: 361768912 Flag: EXEMPT bugfix. Test: OverviewCommandHelperTest Change-Id: I47adf0c54dcbaef63d9b72055e000c26114e96e1 --- aconfig/launcher_overview.aconfig | 9 + .../quickstep/OverviewCommandHelper.kt | 146 ++++++++++---- .../quickstep/OverviewCommandHelperTest.kt | 179 ++++++++++++++++++ 3 files changed, 300 insertions(+), 34 deletions(-) create mode 100644 quickstep/tests/multivalentTests/src/com/android/quickstep/OverviewCommandHelperTest.kt diff --git a/aconfig/launcher_overview.aconfig b/aconfig/launcher_overview.aconfig index e11b00c675..23733a4ff3 100644 --- a/aconfig/launcher_overview.aconfig +++ b/aconfig/launcher_overview.aconfig @@ -39,3 +39,12 @@ flag { bug: "353947137" } +flag { + name: "enable_overview_command_helper_timeout" + namespace: "launcher_overview" + description: "Enables OverviewCommandHelper new version with a timeout to prevent the queue to be unresponsive." + bug: "351122926" + metadata { + purpose: PURPOSE_BUGFIX + } +} \ No newline at end of file diff --git a/quickstep/src/com/android/quickstep/OverviewCommandHelper.kt b/quickstep/src/com/android/quickstep/OverviewCommandHelper.kt index 8873275a30..acf54e8ec1 100644 --- a/quickstep/src/com/android/quickstep/OverviewCommandHelper.kt +++ b/quickstep/src/com/android/quickstep/OverviewCommandHelper.kt @@ -25,16 +25,26 @@ import android.util.Log import android.view.View import androidx.annotation.BinderThread import androidx.annotation.UiThread +import androidx.annotation.VisibleForTesting import com.android.internal.jank.Cuj +import com.android.launcher3.Flags.enableOverviewCommandHelperTimeout import com.android.launcher3.PagedView import com.android.launcher3.config.FeatureFlags import com.android.launcher3.logger.LauncherAtom import com.android.launcher3.logging.StatsLogManager -import com.android.launcher3.logging.StatsLogManager.LauncherEvent.* +import com.android.launcher3.logging.StatsLogManager.LauncherEvent.LAUNCHER_OVERVIEW_SHOW_OVERVIEW_FROM_3_BUTTON +import com.android.launcher3.logging.StatsLogManager.LauncherEvent.LAUNCHER_OVERVIEW_SHOW_OVERVIEW_FROM_KEYBOARD_QUICK_SWITCH +import com.android.launcher3.logging.StatsLogManager.LauncherEvent.LAUNCHER_OVERVIEW_SHOW_OVERVIEW_FROM_KEYBOARD_SHORTCUT import com.android.launcher3.util.Executors import com.android.launcher3.util.RunnableList +import com.android.launcher3.util.coroutines.DispatcherProvider +import com.android.launcher3.util.coroutines.ProductionDispatchers import com.android.quickstep.OverviewCommandHelper.CommandInfo.CommandStatus -import com.android.quickstep.OverviewCommandHelper.CommandType.* +import com.android.quickstep.OverviewCommandHelper.CommandType.HIDE +import com.android.quickstep.OverviewCommandHelper.CommandType.HOME +import com.android.quickstep.OverviewCommandHelper.CommandType.KEYBOARD_INPUT +import com.android.quickstep.OverviewCommandHelper.CommandType.SHOW +import com.android.quickstep.OverviewCommandHelper.CommandType.TOGGLE import com.android.quickstep.util.ActiveGestureLog import com.android.quickstep.views.RecentsView import com.android.quickstep.views.RecentsViewContainer @@ -43,13 +53,25 @@ import com.android.systemui.shared.recents.model.ThumbnailData import com.android.systemui.shared.system.InteractionJankMonitorWrapper import java.io.PrintWriter import java.util.concurrent.ConcurrentLinkedDeque +import kotlin.coroutines.resume +import kotlinx.coroutines.CoroutineScope +import kotlinx.coroutines.SupervisorJob +import kotlinx.coroutines.ensureActive +import kotlinx.coroutines.launch +import kotlinx.coroutines.suspendCancellableCoroutine +import kotlinx.coroutines.withTimeout /** Helper class to handle various atomic commands for switching between Overview. */ -class OverviewCommandHelper( +class OverviewCommandHelper +@JvmOverloads +constructor( private val touchInteractionService: TouchInteractionService, private val overviewComponentObserver: OverviewComponentObserver, - private val taskAnimationManager: TaskAnimationManager + private val taskAnimationManager: TaskAnimationManager, + private val dispatcherProvider: DispatcherProvider = ProductionDispatchers, ) { + private val coroutineScope = CoroutineScope(SupervisorJob() + dispatcherProvider.default) + private val commandQueue = ConcurrentLinkedDeque() /** @@ -79,10 +101,10 @@ class OverviewCommandHelper( * dropped. */ @BinderThread - fun addCommand(type: CommandType) { + fun addCommand(type: CommandType): CommandInfo? { if (commandQueue.size >= MAX_QUEUE_SIZE) { - Log.d(TAG, "commands queue is full ($commandQueue). command not added: $type") - return + Log.d(TAG, "command not added: $type - queue is full ($commandQueue).") + return null } val command = CommandInfo(type) @@ -90,8 +112,17 @@ class OverviewCommandHelper( Log.d(TAG, "command added: $command") if (commandQueue.size == 1) { - Executors.MAIN_EXECUTOR.execute { executeNext() } + Log.d(TAG, "execute: $command - queue size: ${commandQueue.size}") + if (enableOverviewCommandHelperTimeout()) { + coroutineScope.launch(dispatcherProvider.main) { processNextCommand() } + } else { + Executors.MAIN_EXECUTOR.execute { processNextCommand() } + } + } else { + Log.d(TAG, "not executed: $command - queue size: ${commandQueue.size}") } + + return command } fun canStartHomeSafely(): Boolean = commandQueue.isEmpty() || commandQueue.first().type == HOME @@ -108,7 +139,7 @@ class OverviewCommandHelper( * completion (returns false). */ @UiThread - private fun executeNext() { + private fun processNextCommand() { val command: CommandInfo = commandQueue.firstOrNull() ?: run { @@ -119,12 +150,22 @@ class OverviewCommandHelper( command.status = CommandStatus.PROCESSING Log.d(TAG, "executing command: $command") - val result = executeCommand(command) - Log.d(TAG, "command executed: $command with result: $result") - if (result) { - onCommandFinished(command) + if (enableOverviewCommandHelperTimeout()) { + coroutineScope.launch(dispatcherProvider.main) { + withTimeout(QUEUE_WAIT_DURATION_IN_MS) { + executeCommandSuspended(command) + ensureActive() + onCommandFinished(command) + } + } } else { - Log.d(TAG, "waiting for command callback: $command") + val result = executeCommand(command, onCallbackResult = { onCommandFinished(command) }) + Log.d(TAG, "command executed: $command with result: $result") + if (result) { + onCommandFinished(command) + } else { + Log.d(TAG, "waiting for command callback: $command") + } } } @@ -132,7 +173,9 @@ class OverviewCommandHelper( * Executes the task and returns true if next task can be executed. If false, then the next task * is deferred until [.scheduleNextTask] is called */ - private fun executeCommand(command: CommandInfo): Boolean { + @VisibleForTesting + fun executeCommand(command: CommandInfo, onCallbackResult: () -> Unit): Boolean { + // This shouldn't happen if we execute 1 command per time. if (waitForToggleCommandComplete && command.type == TOGGLE) { Log.d(TAG, "executeCommand: $command - waiting for toggle command complete") return true @@ -141,15 +184,37 @@ class OverviewCommandHelper( val recentsView = visibleRecentsView Log.d(TAG, "executeCommand: $command - visibleRecentsView: $recentsView") return if (recentsView != null) { - executeWhenRecentsIsVisible(command, recentsView) + executeWhenRecentsIsVisible(command, recentsView, onCallbackResult) } else { - executeWhenRecentsIsNotVisible(command) + executeWhenRecentsIsNotVisible(command, onCallbackResult) } } + /** + * Executes the task and returns true if next task can be executed. If false, then the next task + * is deferred until [.scheduleNextTask] is called + */ + private suspend fun executeCommandSuspended(command: CommandInfo) = + suspendCancellableCoroutine { continuation -> + fun processResult(isCompleted: Boolean) { + Log.d(TAG, "command executed: $command with result: $isCompleted") + if (isCompleted) { + continuation.resume(Unit) + } else { + Log.d(TAG, "waiting for command callback: $command") + } + } + + val result = executeCommand(command, onCallbackResult = { processResult(true) }) + processResult(result) + + continuation.invokeOnCancellation { cancelCommand(command, it) } + } + private fun executeWhenRecentsIsVisible( command: CommandInfo, recentsView: RecentsView<*, *>, + onCallbackResult: () -> Unit, ): Boolean = when (command.type) { SHOW -> true // already visible @@ -161,7 +226,7 @@ class OverviewCommandHelper( keyboardTaskFocusIndex = PagedView.INVALID_PAGE val currentPage = recentsView.nextPage val taskView = recentsView.getTaskViewAt(currentPage) - launchTask(recentsView, taskView, command) + launchTask(recentsView, taskView, command, onCallbackResult) } } TOGGLE -> { @@ -171,7 +236,7 @@ class OverviewCommandHelper( } else { recentsView.nextTaskView ?: recentsView.runningTaskView } - launchTask(recentsView, taskView, command) + launchTask(recentsView, taskView, command, onCallbackResult) } HOME -> { recentsView.startHome() @@ -182,7 +247,8 @@ class OverviewCommandHelper( private fun launchTask( recents: RecentsView<*, *>, taskView: TaskView?, - command: CommandInfo + command: CommandInfo, + onCallbackResult: () -> Unit ): Boolean { var callbackList: RunnableList? = null if (taskView != null) { @@ -194,7 +260,7 @@ class OverviewCommandHelper( if (callbackList != null) { callbackList.add { Log.d(TAG, "launching task callback: $command") - onCommandFinished(command) + onCallbackResult() waitForToggleCommandComplete = false } Log.d(TAG, "launching task - waiting for callback: $command") @@ -206,7 +272,10 @@ class OverviewCommandHelper( } } - private fun executeWhenRecentsIsNotVisible(command: CommandInfo): Boolean { + private fun executeWhenRecentsIsNotVisible( + command: CommandInfo, + onCallbackResult: () -> Unit + ): Boolean { val recentsViewContainer = activityInterface.getCreatedContainer() as? RecentsViewContainer val recentsView: RecentsView<*, *>? = recentsViewContainer?.getOverviewPanel() val deviceProfile = recentsViewContainer?.getDeviceProfile() @@ -263,7 +332,7 @@ class OverviewCommandHelper( Log.d(TAG, "switching to Overview state - onAnimationEnd: $command") super.onAnimationEnd(animation) onRecentsViewFocusUpdated(command) - onCommandFinished(command) + onCallbackResult() } } if (activityInterface.switchToRecentsIfVisible(animatorListener)) { @@ -289,7 +358,7 @@ class OverviewCommandHelper( command.createTime ) interactionHandler.setGestureEndCallback { - onTransitionComplete(command, interactionHandler) + onTransitionComplete(command, interactionHandler, onCallbackResult) } interactionHandler.initWhenReady("OverviewCommandHelper: command.type=${command.type}") @@ -321,11 +390,6 @@ class OverviewCommandHelper( } } - // TODO(b/361768912): Dead code. Remove or update after this bug is fixed. - // if (visibleRecentsView != null) { - // visibleRecentsView.moveRunningTaskToFront(); - // } - if (taskAnimationManager.isRecentsAnimationRunning) { command.setAnimationCallbacks( taskAnimationManager.continueRecentsAnimation(gestureState) @@ -351,12 +415,16 @@ class OverviewCommandHelper( return false } - private fun onTransitionComplete(command: CommandInfo, handler: AbsSwipeUpHandler<*, *, *>) { + private fun onTransitionComplete( + command: CommandInfo, + handler: AbsSwipeUpHandler<*, *, *>, + onCommandResult: () -> Unit + ) { Log.d(TAG, "switching via recents animation - onTransitionComplete: $command") command.removeListener(handler) Trace.endAsyncSection(TRANSITION_NAME, 0) onRecentsViewFocusUpdated(command) - onCommandFinished(command) + onCommandResult() } /** Called when the command finishes execution. */ @@ -373,7 +441,14 @@ class OverviewCommandHelper( Log.d(TAG, "command executed successfully! $command") commandQueue.remove(command) - executeNext() + processNextCommand() + } + + private fun cancelCommand(command: CommandInfo, throwable: Throwable?) { + command.status = CommandStatus.CANCELED + Log.e(TAG, "command cancelled: $command - $throwable") + commandQueue.remove(command) + processNextCommand() } private fun updateRecentsViewFocus(command: CommandInfo) { @@ -447,7 +522,8 @@ class OverviewCommandHelper( pw.println(" waitForToggleCommandComplete=$waitForToggleCommandComplete") } - private data class CommandInfo( + @VisibleForTesting + data class CommandInfo( val type: CommandType, var status: CommandStatus = CommandStatus.IDLE, val createTime: Long = SystemClock.elapsedRealtime(), @@ -468,7 +544,8 @@ class OverviewCommandHelper( enum class CommandStatus { IDLE, PROCESSING, - COMPLETED + COMPLETED, + CANCELED } } @@ -489,5 +566,6 @@ class OverviewCommandHelper( * should be enough. We'll toss in one more because we're kind hearted. */ private const val MAX_QUEUE_SIZE = 3 + private const val QUEUE_WAIT_DURATION_IN_MS = 5000L } } diff --git a/quickstep/tests/multivalentTests/src/com/android/quickstep/OverviewCommandHelperTest.kt b/quickstep/tests/multivalentTests/src/com/android/quickstep/OverviewCommandHelperTest.kt new file mode 100644 index 0000000000..0ae710f866 --- /dev/null +++ b/quickstep/tests/multivalentTests/src/com/android/quickstep/OverviewCommandHelperTest.kt @@ -0,0 +1,179 @@ +/* + * Copyright (C) 2024 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.quickstep + +import android.platform.test.flag.junit.SetFlagsRule +import androidx.test.filters.SmallTest +import com.android.launcher3.Flags +import com.android.launcher3.util.LauncherMultivalentJUnit +import com.android.launcher3.util.TestDispatcherProvider +import com.android.launcher3.util.rule.setFlags +import com.android.quickstep.OverviewCommandHelper.CommandInfo +import com.android.quickstep.OverviewCommandHelper.CommandInfo.CommandStatus +import com.android.quickstep.OverviewCommandHelper.CommandType +import com.google.common.truth.Truth.assertThat +import kotlinx.coroutines.ExperimentalCoroutinesApi +import kotlinx.coroutines.delay +import kotlinx.coroutines.launch +import kotlinx.coroutines.runBlocking +import kotlinx.coroutines.test.StandardTestDispatcher +import kotlinx.coroutines.test.TestScope +import kotlinx.coroutines.test.advanceTimeBy +import kotlinx.coroutines.test.runCurrent +import kotlinx.coroutines.test.runTest +import org.junit.Before +import org.junit.Rule +import org.junit.Test +import org.junit.runner.RunWith +import org.mockito.Mockito.doAnswer +import org.mockito.Mockito.spy +import org.mockito.Mockito.`when` +import org.mockito.kotlin.any +import org.mockito.kotlin.mock + +@SmallTest +@RunWith(LauncherMultivalentJUnit::class) +@OptIn(ExperimentalCoroutinesApi::class) +class OverviewCommandHelperTest { + @get:Rule val setFlagsRule: SetFlagsRule = SetFlagsRule() + + private lateinit var sut: OverviewCommandHelper + private val dispatcher = StandardTestDispatcher() + private val testScope = TestScope(dispatcher) + + private var pendingCallbacksWithDelays = mutableListOf() + + @Suppress("UNCHECKED_CAST") + @Before + fun setup() { + setFlagsRule.setFlags(true, Flags.FLAG_ENABLE_OVERVIEW_COMMAND_HELPER_TIMEOUT) + + sut = + spy( + OverviewCommandHelper( + touchInteractionService = mock(), + overviewComponentObserver = mock(), + taskAnimationManager = mock(), + dispatcherProvider = TestDispatcherProvider(dispatcher) + ) + ) + + doAnswer { invocation -> + val pendingCallback = invocation.arguments[1] as () -> Unit + + val delayInMillis = pendingCallbacksWithDelays.removeFirstOrNull() + if (delayInMillis != null) { + runBlocking { + testScope.backgroundScope.launch { + delay(delayInMillis) + pendingCallback.invoke() + } + } + } + delayInMillis == null // if no callback to execute, returns success + } + .`when`(sut) + .executeCommand(any(), any()) + } + + private fun addCallbackDelay(delayInMillis: Long = 0) { + pendingCallbacksWithDelays.add(delayInMillis) + } + + @Test + fun whenFirstCommandIsAdded_executeCommandImmediately() = + testScope.runTest { + // Add command to queue + val commandInfo: CommandInfo = sut.addCommand(CommandType.HOME)!! + assertThat(commandInfo.status).isEqualTo(CommandStatus.IDLE) + runCurrent() + assertThat(commandInfo.status).isEqualTo(CommandStatus.COMPLETED) + } + + @Test + fun whenFirstCommandIsAdded_executeCommandImmediately_WithCallbackDelay() = + testScope.runTest { + addCallbackDelay(100) + + // Add command to queue + val commandType = CommandType.HOME + val commandInfo: CommandInfo = sut.addCommand(commandType)!! + assertThat(commandInfo.status).isEqualTo(CommandStatus.IDLE) + + runCurrent() + assertThat(commandInfo.status).isEqualTo(CommandStatus.PROCESSING) + + advanceTimeBy(200L) + assertThat(commandInfo.status).isEqualTo(CommandStatus.COMPLETED) + } + + @Test + fun whenFirstCommandIsPendingCallback_NextCommandWillWait() = + testScope.runTest { + // Add command to queue + addCallbackDelay(100) + val commandType1 = CommandType.HOME + val commandInfo1: CommandInfo = sut.addCommand(commandType1)!! + assertThat(commandInfo1.status).isEqualTo(CommandStatus.IDLE) + + addCallbackDelay(100) + val commandType2 = CommandType.SHOW + val commandInfo2: CommandInfo = sut.addCommand(commandType2)!! + assertThat(commandInfo2.status).isEqualTo(CommandStatus.IDLE) + + runCurrent() + assertThat(commandInfo1.status).isEqualTo(CommandStatus.PROCESSING) + assertThat(commandInfo2.status).isEqualTo(CommandStatus.IDLE) + + advanceTimeBy(101L) + assertThat(commandInfo1.status).isEqualTo(CommandStatus.COMPLETED) + assertThat(commandInfo2.status).isEqualTo(CommandStatus.PROCESSING) + + advanceTimeBy(101L) + assertThat(commandInfo2.status).isEqualTo(CommandStatus.COMPLETED) + } + + @Test + fun whenCommandTakesTooLong_TriggerTimeout_AndExecuteNextCommand() = + testScope.runTest { + // Add command to queue + addCallbackDelay(QUEUE_TIMEOUT) + val commandType1 = CommandType.HOME + val commandInfo1: CommandInfo = sut.addCommand(commandType1)!! + assertThat(commandInfo1.status).isEqualTo(CommandStatus.IDLE) + + addCallbackDelay(100) + val commandType2 = CommandType.SHOW + val commandInfo2: CommandInfo = sut.addCommand(commandType2)!! + assertThat(commandInfo2.status).isEqualTo(CommandStatus.IDLE) + + runCurrent() + assertThat(commandInfo1.status).isEqualTo(CommandStatus.PROCESSING) + assertThat(commandInfo2.status).isEqualTo(CommandStatus.IDLE) + + advanceTimeBy(QUEUE_TIMEOUT) + assertThat(commandInfo1.status).isEqualTo(CommandStatus.CANCELED) + assertThat(commandInfo2.status).isEqualTo(CommandStatus.PROCESSING) + + advanceTimeBy(101) + assertThat(commandInfo2.status).isEqualTo(CommandStatus.COMPLETED) + } + + private companion object { + const val QUEUE_TIMEOUT = 5001L + } +}