Bug #117479
【AF】【EVT3】【压测】【偶现】在OTA压测过程中，设备升级后重启时，桌面出现”Quickstep没有响应“的提示
| Status: | CLOSED | Start date: | 2023-04-14 | |
|---|---|---|---|---|
| Priority: | High | Due date: | 2023-05-10 | |
| Assignee: | 移动测试一组_CDTS 刘强 | % Done: | 100% | |
| Category: | CD-APP | |||
| Target version: | - | |||
| Need_Info: | -- | Found Version: | 0086-0090 | |
| Resolution: | FIXED | Degrated: | No | |
| Severity: | Major | Verified Version: | ||
| Reproducibility: | Occasionally | Fixed Version: | 2023-05-23 | |
| Test Type: | ST | Root cause: | 编码问题 |
Description
【测试步骤】
1、使用脚本进行OTA压测：0086-0090
2、升级成功后设备自动重启
3、重启后查看设备基本功能
【预期结果】
3、设备基本功能正常
【实际结果】
3、桌面出现”Quickstep停止运行“的提示
History
#1 Updated by 移动测试一组_CDTS 刘强 about 2 years ago
- Subject changed from 【AF】【EVT3】【压测】【偶现】在OTA压测过程中，设备升级后重启时，桌面出现”Quickstep停止运行“的提示 to 【AF】【EVT3】【压测】【偶现】在OTA压测过程中，设备升级后重启时，桌面出现”Quickstep没有响应“的提示
#2 Updated by CD FW 曹覃刚 about 2 years ago
- File anr_2023-04-11-05-10-13-729 added
- Category changed from CD-FW to CD-APP
- Status changed from New to ASSIGNED
- Assignee changed from CD FW 曹覃刚 to CD APP-王宏
Hi 王宏
桌面发生anr
suspend all histogram: Sum: 280us 99% C.I. 0.090us-193.040us Avg: 16.470us Max: 197us
DALVIK THREADS (27):
"main" prio=5 tid=1 Runnable
| group="main" sCount=0 ucsCount=0 flags=0 obj=0x7192b3f8 self=0xb40000711f883be0
| sysTid=2718 nice=-10 cgrp=default sched=0/0 handle=0x72e93824f8
| state=R schedstat=( 294153651 88911975 460 ) utm=23 stm=6 core=6 HZ=100
| stack=0x7fd383f000-0x7fd3841000 stackSize=8188KB
| held mutexes= "mutator lock"(shared held)
at com.android.launcher3.WorkspaceLayoutManager.addInScreen(WorkspaceLayoutManager.java:93)
at com.android.launcher3.Workspace.addInScreen(Workspace.java:3473)
at com.android.launcher3.WorkspaceLayoutManager.addInScreenFromBind(WorkspaceLayoutManager.java:49)
at com.android.launcher3.Launcher.bindItems(Launcher.java:2454)
at com.android.launcher3.Launcher.bindItems(Launcher.java:2376)
at com.android.launcher3.model.BaseLoaderResults$WorkspaceBinder.lambda$bindWorkspaceItems$7(BaseLoaderResults.java:245)
at com.android.launcher3.model.BaseLoaderResults$WorkspaceBinder$$ExternalSyntheticLambda5.execute(unavailable:-1)
at com.android.launcher3.model.BaseLoaderResults$WorkspaceBinder.lambda$executeCallbacksTask$9$BaseLoaderResults$WorkspaceBinder(BaseLoaderResults.java:266)
at com.android.launcher3.model.BaseLoaderResults$WorkspaceBinder$$ExternalSyntheticLambda8.run(unavailable:-1)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loopOnce(Looper.java:201)
at android.os.Looper.loop(Looper.java:288)
at android.app.ActivityThread.main(ActivityThread.java:7880)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1009)
#3 Updated by CD APP-王营 about 2 years ago
- Due date set to 2023-04-18
#4 Updated by CD APP-王宏 about 2 years ago
- Assignee changed from CD APP-王宏 to CD APP-王营
#5 Updated by CD APP-王营 about 2 years ago
- Due date changed from 2023-04-18 to 2023-04-21
■ Current conclusion
分析中
Launcher桌面发生anr的原因如下：
04-11 05:10:25.328 1553 4032 E ActivityManager: Reason: Input dispatching timed out (595168f com.android.launcher3/com.android.launcher3.uioverrides.QuickstepLauncher (server) is not responding. Waited 5005ms for FocusEvent(hasFocus=true))
分析trace文件中，Launcher加载数据过程中有锁未释放，Log如下：
"launcher-loader" prio=5 tid=19 TimedWaiting
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x133c1588 self=0xb40000711f8b9a10
| sysTid=2785 nice=10 cgrp=default sched=0/0 handle=0x6f318dfcb0
| state=S schedstat=( 29957232 32796666 178 ) utm=1 stm=1 core=2 HZ=100
| stack=0x6f317dc000-0x6f317de000 stackSize=1039KB
| held mutexes=
at java.lang.Object.wait(Native method)
- waiting on <0x0d86c4fa> (a com.android.launcher3.model.LoaderTask)
at java.lang.Object.wait(Object.java:442)
at com.android.launcher3.util.LooperIdleLock.awaitLocked(LooperIdleLock.java:57)
at com.android.launcher3.model.LoaderTask.waitForIdle(LoaderTask.java:166)
- locked <0x0d86c4fa> (a com.android.launcher3.model.LoaderTask)
at com.android.launcher3.model.LoaderTask.run(LoaderTask.java:221)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loopOnce(Looper.java:201)
at android.os.Looper.loop(Looper.java:288)
at android.os.HandlerThread.run(HandlerThread.java:67)
Launcher桌面的数据是异步加载，从UI层产生的错误的log来看，WorkspaceLayoutManager 在 addInScreen() 方法中发生anr
■ Next action
继续分析Launcher从获取数据到绑定item到workspace流程中，在哪一个环节会造成anr问题。
#6 Updated by CD APP-王营 about 2 years ago
■ Current conclusion
分析中,暂时未能找到异常原因，正在根据log分析anr发生之前的系统行为。
■ Next action
1、继续分析log
2、尝试复现此问题
#7 Updated by CD APP-王营 about 2 years ago
■ Current conclusion
已有一种方案，可修改后验证
■ My analysis
Log中提示Launcher主线程任务太多，从此处着手进行优化，SharedPreference第一次读写数据的时候比较耗时，放在Application中进行初始化。
此问题会继续在以下文档下更新：
https://thundersoft.feishu.cn/docx/T5zldHBUMohQ1jxfgULc9tsKndc
■ Next action
优化后验证
#8 Updated by CD APP-王营 about 2 years ago
■ Current conclusion
对比了异常情况和正常启动的log发现如下差异：
ota升级后正常启动的log会调用LauncherModel的startLoader()方法并抛出异常：
04-26 03:16:15.733 2700 2700 D Launcher.Model: startLoader
04-26 03:16:15.733 2700 2700 D Launcher.Model: java.lang.Exception
04-26 03:16:15.733 2700 2700 D Launcher.Model: at com.android.launcher3.LauncherModel.startLoader(LauncherModel.java:360)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at com.android.launcher3.LauncherModel.addCallbacksAndLoad(LauncherModel.java:340)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at com.android.launcher3.Launcher.onCreate(Launcher.java:530)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at com.android.launcher3.BaseQuickstepLauncher.onCreate(BaseQuickstepLauncher.java:147)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.Activity.performCreate(Activity.java:8094)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.Activity.performCreate(Activity.java:8074)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1330)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:3609)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:3793)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.servertransaction.LaunchActivityItem.execute(LaunchActivityItem.java:103)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.servertransaction.TransactionExecutor.executeCallbacks(TransactionExecutor.java:135)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:95)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2211)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.os.Handler.dispatchMessage(Handler.java:106)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.os.Looper.loopOnce(Looper.java:201)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.os.Looper.loop(Looper.java:288)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at android.app.ActivityThread.main(ActivityThread.java:7880)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at java.lang.reflect.Method.invoke(Native Method)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
04-26 03:16:15.733 2700 2700 D Launcher.Model: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1009)
启动log已经上床normalStart_new
异常情况下的log中没有此log，说明异常情况下Launcher数据的加载流程出现问题或者block.
■ Next action
现有log中未能分析出异常产生的原因，添加强化日志，复现此问题，再根据最新日志分析流程中可能出现的问题
■Submit URL
https://dev.thundercomm.com/gerrit/c/general/platform/packages/apps/Launcher3/+/196622
#9 Updated by CD APP-王营 about 2 years ago
■ Current conclusion
分析中
■ My analysis
从目前logcat和trace分析，还是怀疑Laucher的主线程被block了，需要增加日志看下被block在了哪里
1. 在Launcher增加日志，从86-》增加了日志的刷机版本，ota压测，获取更多的log信息
2. 直接在90版本上进行开关机压测，看下ANR是否跟ota有关系
3. 在86版本上push 新的Launcher app，进行开关机的压测，如果没有一样的ANR发生，说明ANR可能跟Launcher没关系 。
4. 差分一下86和90之间有哪些更新，找下有没有怀疑点
■ Next action
根据当前方向继续分析。
#10 Updated by 移动测试一组_CDTS 刘强 about 2 years ago
1. Qile烧写0086版本后开机到操作界面
2. adb push updata.zip /sdcard/Download/ push升级包到设备
3. 设置搜索框输入*#149#
4. 点击升级
5. 升级完成后系统自动重启
6. 重复step1-5
#11 Updated by CD APP-王营 about 2 years ago
- Due date changed from 2023-04-21 to 2023-05-10
#12 Updated by CD APP-王营 about 2 years ago
■ Current conclusion
OTA压测201次在第201次发生anr，已抓取Logcat 和trace
■ My analysis
根据Trace文件定位在Launcher启动后注册了一个广播接收器，此Receiver在在注册后马上收到了广播，通过SharedPreference进行数据保存，怀疑在保存之前会进行SharedPreference的初始化，此过程可能导致主线程耗时太久。
■ Next action
继续分析主线程在启动后的工作流程。
#13 Updated by CD APP-王营 about 2 years ago
- % Done changed from 0 to 100
- Resolution changed from -- to FIXED
- Degrated changed from -- to No
- Fixed Version set to 2023-05-23
- Root cause set to 编码问题
【当前进展】
问题已处理，待验证
【分析】
从复现log中分析可知主线程任务太多被block，导致Launcher的LoaderTask回调延迟，View渲染滞后，无法响应focusEvent。
trace文件中问题定位log如下
at com.android.launcher3.util.MCUUtil.saveLastActivity(MCUUtil.java:46)
at com.android.launcher3.util.ActivityChangeReceiver.onReceive(ActivityChangeReceiver.java:15)
at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$getRunnable$0$LoadedApk$ReceiverDispatcher$Args(LoadedApk.java:1679)
at android.app.LoadedApk$ReceiverDispatcher$Args$$ExternalSyntheticLambda0.run(unavailable:-1)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loopOnce(Looper.java:201)
at android.os.Looper.loop(Looper.java:288)
at android.app.ActivityThread.main(ActivityThread.java:7880)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1009)
广播接收器的onReceive方法在主线程执行，此阶段出现block会影响Launcher View的渲染
MCUUtil在获取topActivity时会获取AMS服务，拿到Activity信息，在广播接收器的intent中已经包含了Activity的数据，基于以上两点做出以下优化：
1、防止广播接收器onReceive方法中耗时block主线程，在onReceive方法中任务通过子线程来执行
2、topActivity中的数据直接从Intent中取得。
【提交】
https://dev.thundercomm.com/gerrit/c/general/platform/packages/apps/Launcher3/+/201606
#14 Updated by IoT scm about 2 years ago
| ID | Project | Branch | Uploader |
| 201606 | general/platform/packages/apps/Launcher3 | Pre_figure_turbox-c2130c-la1.1-qssi12-dev | ying.wang@thundersoft.com |
| AF: Launcher: Optimize receiver logic 1.Optimize activity change receiver log when save top activity info. TC-RID: 0301-0205301 IssueID: TS-R-BUG-117479 Change-Id: I63e2f0be80a0b1a5c02e033b9fbb46b77b4a777d |
|||
#15 Updated by CD APP-王营 about 2 years ago
- Status changed from ASSIGNED to RESOLVED
- Assignee changed from CD APP-王营 to 移动测试一组_CDTS 刘强
#16 Updated by 移动测试一组_CDTS 刘强 about 2 years ago
压测：64次未复现
继续跟踪
#17 Updated by 移动测试一组_CDTS 刘强 about 2 years ago
- Status changed from RESOLVED to VERIFIED
验证版本：0106版本
累积压测：190次 未出现问题
但其他测试场景出现这个error，由另一个问题跟踪：https://share.thundersoft.com/redmine/issues/118625
#18 Updated by 移动测试一组_CDTS 刘强 about 2 years ago
- Status changed from VERIFIED to CLOSED