Bug #118622

【AF】【EVT3】【实车】系统卡顿

Added by CD TEST-方永红 about 2 years ago. Updated almost 2 years ago.

Status:CLOSEDStart date:2023-06-07
Priority:HighDue date:
Assignee:CD FW 曹覃刚% Done:

100%

Category:卡顿
Target version:-
Need_Info:-- Found Version:0106
Resolution:-- Degrated:--
Severity:Critical Verified Version:
Reproducibility:Rarely Fixed Version:
Test Type:ST Root cause:

Description

【现象】
副屏所有的应用包括预置应用点击进入都很卡顿 响应时间长甚至无效

log(1).txt Magnifier (7.18 MB) CD TEST-方永红, 2023-06-07 17:35

20230616-093305.jpg (489 KB) CD SYSTEM-夏旭, 2023-06-16 09:33

20230616-093305

Subtasks

Bug #118631: 【AF】【EVT3】【实车】系统卡顿， tlogdshc不断重启和被杀RESOLVEDCD TPM-王祥林

Related issues

Duplicated by Figure - Bug #118604: IOVDEV-33153【内部】【VC1】【0106】【台架】【EE环境】【副屏】【设置】副屏严重卡顿 CLOSED 2023-06-07
Duplicated by Figure - Bug #118600: IOVDEV-33078【内部】【VC1】【0106】【台架】【EE环境】【副屏】【设置】副屏系统严重卡顿，应用打不开 CLOSED 2023-06-07
Duplicates Figure - Bug #118646: 【IOVDEV-33447】【内部】【VC1】【0072】【台架】【EE环境】【副屏】【第三方应用】王者荣耀、火影... CLOSED 2023-06-08

History

#1 Updated by CD TEST-方永红 about 2 years ago

  • Subject changed from 【AF】【EVT3】【实车】系统卡断 to 【AF】【EVT3】【实车】系统卡顿

#2 Updated by CD FW 曹覃刚 about 2 years ago

  • Status changed from New to ASSIGNED

■ 我的分析
---------------------------
log(1).txt:1067: 06-07 15:23:28.779 0 0 I [ 126.157248] init: processing action (sys.tlog.tlogdshc.active=1) from (/system/etc/init/tlogd.rc:195)
log(1).txt:1068: 06-07 15:23:28.780 0 0 I [ 126.158216] init: starting service 'tlogdshc'...
log(1).txt:1069: 06-07 15:23:28.891 0 0 I [ 126.271878] init: Service 'tlogdshc' (pid 7291) exited with status 0 oneshot service took 0.107000 seconds in background
log(1).txt:1070: 06-07 15:23:28.891 0 0 I [ 126.271910] init: Sending signal 9 to service 'tlogdshc' (pid 7291) process group...
log(1).txt:1071: 06-07 15:23:28.891 0 0 I [ 126.272160] libprocessgroup: Successfully killed process cgroup uid 0 pid 7291 in 0ms
log(1).txt:1155: 06-07 15:23:58.784 0 0 I [ 156.158010] init: processing action (sys.tlog.tlogdshc.active=1) from (/system/etc/init/tlogd.rc:195)
log(1).txt:1156: 06-07 15:23:58.784 0 0 I [ 156.158559] init: starting service 'tlogdshc'...
log(1).txt:1157: 06-07 15:23:58.887 0 0 I [ 156.265766] init: Service 'tlogdshc' (pid 7644) exited with status 0 oneshot service took 0.103000 seconds in background
log(1).txt:1158: 06-07 15:23:58.887 0 0 I [ 156.265798] init: Sending signal 9 to service 'tlogdshc' (pid 7644) process group...
log(1).txt:1159: 06-07 15:23:58.887 0 0 I [ 156.266012] libprocessgroup: Successfully killed process cgroup uid 0 pid 7644 in 0ms
log(1).txt:1264: 06-07 15:24:28.793 0 0 I [ 186.171156] init: processing action (sys.tlog.tlogdshc.active=1) from (/system/etc/init/tlogd.rc:195)
log(1).txt:1265: 06-07 15:24:28.793 0 0 I [ 186.172268] init: starting service 'tlogdshc'...
log(1).txt:1266: 06-07 15:24:28.915 0 0 I [ 186.293851] init: Service 'tlogdshc' (pid 7963) exited with status 0 oneshot service took 0.115000 seconds in background
log(1).txt:1267: 06-07 15:24:28.915 0 0 I [ 186.293877] init: Sending signal 9 to service 'tlogdshc' (pid 7963) process group...
log(1).txt:1268: 06-07 15:24:28.915 0 0 I [ 186.294029] libprocessgroup: Successfully killed process cgroup uid 0 pid 7963 in 0ms
log(1).txt:1507: 06-07 15:24:58.805 0 0 I [ 216.172089] init: processing action (sys.tlog.tlogdshc.active=1) from (/system/etc/init/tlogd.rc:195)
log(1).txt:1508: 06-07 15:24:58.805 0 0 I [ 216.172842] init: starting service 'tlogdshc'...
log(1).txt:1509: 06-07 15:24:58.913 0 0 I [ 216.280374] init: Service 'tlogdshc' (pid 8253) exited with status 0 oneshot service took 0.103000 seconds in background
log(1).txt:1510: 06-07 15:24:58.913 0 0 I [ 216.280400] init: Sending signal 9 to service 'tlogdshc' (pid 8253) process group...
log(1).txt:1511: 06-07 15:24:58.913 0 0 I [ 216.280561] libprocessgroup: Successfully killed process cgroup uid 0 pid 8253 in 0ms
log(1).txt:1625: 06-07 15:25:28.811 0 0 I [ 246.178136] init: processing action (sys.tlog.tlogdshc.active=1) from (/system/etc/init/tlogd.rc:195)
log(1).txt:1626: 06-07 15:25:28.811 0 0 I [ 246.178588] init: starting service 'tlogdshc'...
log(1).txt:1627: 06-07 15:25:28.925 0 0 I [ 246.293379] init: Service 'tlogdshc' (pid 8457) exited with status 0 oneshot service took 0.112000 seconds in background
log(1).txt:1628: 06-07 15:25:28.925 0 0 I [ 246.293411] init: Sending signal 9 to service 'tlogdshc' (pid 8457) process group...
log(1).txt:1629: 06-07 15:25:28.925 0 0 I [ 246.293621] libprocessgroup: Successfully killed process cgroup uid 0 pid 8457 in 0ms
①15:23开始到日志结束, tlogdshc不断重启和被杀
---------------------------

---------------------------
log(1).txt:16409: 06-07 15:53:21.319 1539 1675 I ActivityManager: Killing 14680:com.tencent.qqmusic/u0a97 (adj 10000): start timeout
log(1).txt:16410: 06-07 15:53:21.319 1539 1675 I am_kill : [0,14680,com.tencent.qqmusic,-10000,start timeout]
log(1).txt:16611: 06-07 15:53:31.313 1539 1675 I ActivityManager: Killing 14737:com.qti.diagservices/1000 (adj -10000): start timeout
log(1).txt:16612: 06-07 15:53:31.313 1539 1675 I am_kill : [0,14737,com.qti.diagservices,-10000,start timeout]
log(1).txt:16618: 06-07 15:53:31.423 1539 1675 I ActivityManager: Killing 14738:com.thundercomm.gamemode.provider/u0a62 (adj -10000): start timeout
log(1).txt:16619: 06-07 15:53:31.424 1539 1675 I am_kill : [0,14738,com.thundercomm.gamemode.provider,-10000,start timeout]
log(1).txt:16634: 06-07 15:53:32.071 1539 1675 I ActivityManager: Killing 14748:com.tencent.qqmusic/u0a97 (adj -10000): start timeout
log(1).txt:16635: 06-07 15:53:32.071 1539 1675 I am_kill : [0,14748,com.tencent.qqmusic,-10000,start timeout]
log(1).txt:16811: 06-07 15:53:42.197 1539 1675 I ActivityManager: Killing 14803:com.tencent.qqmusic/u0a97 (adj -10000): start timeout
log(1).txt:16812: 06-07 15:53:42.198 1539 1675 I am_kill : [0,14803,com.tencent.qqmusic,-10000,start timeout]
log(1).txt:16818: 06-07 15:53:42.302 1539 1675 I ActivityManager: Killing 14805:com.thundercomm.gamemode.provider/u0a62 (adj -10000): start timeout
log(1).txt:16819: 06-07 15:53:42.302 1539 1675 I am_kill : [0,14805,com.thundercomm.gamemode.provider,-10000,start timeout]
log(1).txt:16873: 06-07 15:53:45.799 1539 1675 I ActivityManager: Killing 14815:com.tencent.tmgp.sgame/u0a96 (adj -10000): start timeout
log(1).txt:16874: 06-07 15:53:45.799 1539 1675 I am_kill : [0,14815,com.tencent.tmgp.sgame,-10000,start timeout]
log(1).txt:17155: 06-07 15:54:01.042 1539 1675 I ActivityManager: Killing 14864:com.qualcomm.timeservice/u0a57 (adj -10000): start timeout
log(1).txt:17156: 06-07 15:54:01.042 1539 1675 I am_kill : [0,14864,com.qualcomm.timeservice,-10000,start timeout]
log(1).txt:17165: 06-07 15:54:01.054 1539 1675 I ActivityManager: Killing 14865:com.android.providers.calendar/u0a28 (adj -10000): start timeout
log(1).txt:17166: 06-07 15:54:01.054 1539 1675 I am_kill : [0,14865,com.android.providers.calendar,-10000,start timeout]
log(1).txt:17176: 06-07 15:54:01.144 1539 1675 I ActivityManager: Killing 14867:com.tencent.qqmusic/u0a97 (adj -10000): start timeout
log(1).txt:17177: 06-07 15:54:01.144 1539 1675 I am_kill : [0,14867,com.tencent.qqmusic,-10000,start timeout]
log(1).txt:17192: 06-07 15:54:02.037 1539 1675 I ActivityManager: Killing 14879:com.thundercomm.gamemode.provider/u0a62 (adj -10000): start timeout
log(1).txt:17193: 06-07 15:54:02.038 1539 1675 I am_kill : [0,14879,com.thundercomm.gamemode.provider,-10000,start timeout]
log(1).txt:17207: 06-07 15:54:03.210 1539 1675 I ActivityManager: Killing 14889:com.kugou.android/u0a100 (adj -10000): start timeout
log(1).txt:17208: 06-07 15:54:03.210 1539 1675 I am_kill : [0,14889,com.kugou.android,-10000,start timeout]
log(1).txt:17295: 06-07 15:54:11.060 1539 1675 I ActivityManager: Killing 14916:com.qualcomm.timeservice/u0a57 (adj -10000): start timeout
log(1).txt:17296: 06-07 15:54:11.060 1539 1675 I am_kill : [0,14916,com.qualcomm.timeservice,-10000,start timeout]
log(1).txt:17305: 06-07 15:54:11.068 1539 1675 I ActivityManager: Killing 14917:com.android.providers.calendar/u0a28 (adj -10000): start timeout
log(1).txt:17306: 06-07 15:54:11.068 1539 1675 I am_kill : [0,14917,com.android.providers.calendar,-10000,start timeout]
log(1).txt:17412: 06-07 15:54:21.090 1539 1675 I ActivityManager: Killing 14942:com.qualcomm.timeservice/u0a57 (adj -10000): start timeout
log(1).txt:17413: 06-07 15:54:21.090 1539 1675 I am_kill : [0,14942,com.qualcomm.timeservice,-10000,start timeout]
log(1).txt:17518: 06-07 15:54:31.117 1539 1675 I ActivityManager: Killing 14972:com.qualcomm.timeservice/u0a57 (adj -10000): start timeout
log(1).txt:17519: 06-07 15:54:31.117 1539 1675 I am_kill : [0,14972,com.qualcomm.timeservice,-10000,start timeout]
②15:53开始，出现各种应用启动超时被杀的情况
--------------------------

■ 下一步计划
1.需要system的同学看一下，tlogdshc不断重启和被杀的原因，子任务 #118631
2.我们检查应用启动超时被杀的的原因

注:已飞书联系测试同学获取完整的tlog

#4 Updated by CD FW 曹覃刚 about 2 years ago

■ 我的分析

2.我们检查应用启动超时被杀的的原因

-----------------
①起进程超时，被杀
log(1).txt:21785: 06-07 15:58:44.524 1539 1676 I am_proc_start: [0,15818,10099,com.qiyi.video,NULL,]
log(1).txt:21787: 06-07 15:58:44.524 1539 1676 I ActivityManager: Start proc 15818:com.qiyi.video/u0a99 for null
log(1).txt:21987: 06-07 15:58:54.524 1539 1675 W ActivityManager: Process ProcessRecord{913b14 15818:com.qiyi.video/u0a99} failed to attach
log(1).txt:21988: 06-07 15:58:54.524 1539 1675 I am_process_start_timeout: [0,15818,10099,com.qiyi.video]
log(1).txt:21990: 06-07 15:58:54.525 1539 1675 I ActivityManager: Killing 15818:com.qiyi.video/u0a99 (adj -10000): start timeout
log(1).txt:21991: 06-07 15:58:54.525 1539 1675 I am_kill : [0,15818,com.qiyi.video,-10000,start timeout]

log(1).txt:21788: 06-07 15:58:44.528 1539 1676 I am_proc_start: [0,15823,10095,com.ss.android.ugc.aweme,NULL,]
log(1).txt:21789: 06-07 15:58:44.528 1539 1676 I ActivityManager: Start proc 15823:com.ss.android.ugc.aweme/u0a95 for null
log(1).txt:21992: 06-07 15:58:54.529 1539 1675 W ActivityManager: Process ProcessRecord{34e6fbd 15823:com.ss.android.ugc.aweme/u0a95} failed to attach
log(1).txt:21993: 06-07 15:58:54.530 1539 1675 I am_process_start_timeout: [0,15823,10095,com.ss.android.ugc.aweme]
log(1).txt:21995: 06-07 15:58:54.530 1539 1675 I ActivityManager: Killing 15823:com.ss.android.ugc.aweme/u0a95 (adj -10000): start timeout
log(1).txt:21996: 06-07 15:58:54.530 1539 1675 I am_kill : [0,15823,com.ss.android.ugc.aweme,-10000,start timeout]

②wake lock超时
log(1).txt:2953: 06-07 15:30:56.074 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:3335: 06-07 15:31:55.260 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:5123: 06-07 15:37:36.861 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:7391: 06-07 15:42:49.091 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:13482: 06-07 15:50:58.165 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:16807: 06-07 15:53:42.191 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:18601: 06-07 15:55:27.290 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:21268: 06-07 15:58:29.345 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:22030: 06-07 15:58:56.297 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:36877: 06-07 16:05:49.693 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:39377: 06-07 16:06:14.088 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:46775: 06-07 16:08:07.401 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:51314: 06-07 16:09:20.693 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:52661: 06-07 16:09:38.021 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
log(1).txt:58092: 06-07 16:10:27.912 1539 1658 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
-----------------
看问题与 #118602 有关联，与wake lock相关

■ 下一步计划
主要需要推进 #118602 的分析，下列问题可能都与之相关
#118646 #118622 #118604 #118600
目前来看，都是在起应用进程时超时，而超时似乎都与wake lock有关

#5 Updated by CD FW 曹覃刚 about 2 years ago

  • Status changed from ASSIGNED to RESOLVED

转jira跟踪

#6 Updated by CD SYSTEM-夏旭 about 2 years ago

【当前进展】
已抓取卡顿时systrace，由于卡顿严重时setting打不开 导致无法抓取问题现场trace，从trace中看见startActivity时间runnable了2s 同步提case给高通

ota跑到超大核上，对应用启动时间有一定影响，目前将ota限在0~3核上

#7 Updated by IoT scm about 2 years ago

Gerrit Merge Information：
ID Project Branch Uploader
207974 general/platform/vendor/thundercomm/apps/FOTA Pre_figure_turbox-c2130c-la1.1-qssi12-dev
SYSTEM:Performance system stuck
ota Bind the small nucleus
TC-RID: 1200-0800207
IssueID: TS-R-BUG-118622
Change-Id: I2be1ac0f7d2caeaf5edec50ea07c0bfe5df2112d

#8 Updated by IoT scm about 2 years ago

Gerrit Merge Information：
ID Project Branch Uploader
208867 general/platform/vendor/thundercomm/apps/FOTA Pre_figure_turbox-c2130c-la1.1-qssi12-release_sorp
SYSTEM:Performance system stuck
ota Bind the small nucleus
TC-RID: 1200-0800207
IssueID: TS-R-BUG-118622
Change-Id: I2be1ac0f7d2caeaf5edec50ea07c0bfe5df2112d
(cherry picked from commit 7151fac059c95e7b8241a3cca84ec0c87c40869b)

#9 Updated by CDTS_TEST 王成 almost 2 years ago

  • Status changed from RESOLVED to VERIFIED

关联BUG已全关闭

#10 Updated by CDTS_TEST 王成 almost 2 years ago

  • Status changed from VERIFIED to CLOSED

Also available in: Atom PDF