Figure

Hi 诗雨

0602-副屏静态老化-V01.00.0100-【VIN】HRYTTESTVINMGM403-提示system没有响应.7z

客户提供的是实时日志，需要历史日志和ANR的trace，请帮忙获取
已飞书同步

覃刚 看看这份日志是否仍然没有历史日志

Hi 周婷

0602-副屏静态老化-V01.00.0100-【VIN】HRYTTESTVINMGM403-提示system没有响应.7z

新提供的日志是实时日志，不是历史日志，需要提供历史日志
请同步，谢谢

■ 我的分析
根据最新提供的日志，20230602 08:40，并没有ANR发生
但是在20230601 21:38有一样的错误 system anr产生
----------------------
06-01 21:16:05.625 1537 1777 I InputDispatcher: PointerEventDispatcher0 (server) spent 2073ms processing MotionEvent
....
06-01 21:38:56.789 1537 1777 I InputDispatcher: PointerEventDispatcher0 (server) spent 3232ms processing MotionEvent
06-01 21:38:56.789 1537 1777 I InputDispatcher: PointerEventDispatcher0 (server) spent 3215ms processing MotionEvent
06-01 21:38:56.789 1537 1777 I InputDispatcher: PointerEventDispatcher0 (server) spent 3198ms processing MotionEvent
06-01 21:38:56.789 1537 1777 I InputDispatcher: PointerEventDispatcher0 (server) spent 3182ms processing MotionEvent
//从21:16:05开始，PointerEventDispatcher0处理事件就开始变慢了，这个滑动事件在这个时间段内在疯狂输出，说明持续有滑动事件(这个日志是处理事件超过2秒时打印, 表示现在处理事件已经很缓慢了)

06-01 21:16:05.630 2545 2545 D ViewTouchDebug: mView : DecorView@569001c[QuickstepLauncher]Receive event : MotionEvent { action=ACTION_MOVE, actionButton=0, id⁰=0, x⁰=1144.0, y⁰=883.0, toolType⁰=TOOL_TYPE_FINGER, buttonState=0, classification=NONE, metaState=0, flags=0x0, edgeFlags=0x0, pointerCount=1, historySize=1, eventTime=7722874, downTime=5693309, deviceId=-1, source=0x1002, displayId=0, eventId=-236403310 }
....
06-01 21:38:56.702 2545 2545 D ViewTouchDebug: mView : DecorView@569001c[QuickstepLauncher]Receive event : MotionEvent { action=ACTION_MOVE, actionButton=0, id⁰=0, x⁰=1144.0, y⁰=883.0, toolType⁰=TOOL_TYPE_FINGER, buttonState=0, classification=NONE, metaState=0, flags=0x0, edgeFlags=0x0, pointerCount=1, historySize=1, eventTime=9093085, downTime=5693309, deviceId=-1, source=0x1002, displayId=0, eventId=-885178006 }
06-01 21:38:56.719 2545 2545 D ViewTouchDebug: mView : DecorView@569001c[QuickstepLauncher]Receive event : MotionEvent { action=ACTION_MOVE, actionButton=0, id⁰=0, x⁰=1144.0, y⁰=883.0, toolType⁰=TOOL_TYPE_FINGER, buttonState=0, classification=NONE, metaState=0, flags=0x0, edgeFlags=0x0, pointerCount=1, historySize=1, eventTime=9093101, downTime=5693309, deviceId=-1, source=0x1002, displayId=0, eventId=-392382550 }
06-01 21:38:56.735 2545 2545 D ViewTouchDebug: mView : DecorView@569001c[QuickstepLauncher]Receive event : MotionEvent { action=ACTION_MOVE, actionButton=0, id⁰=0, x⁰=1144.0, y⁰=883.0, toolType⁰=TOOL_TYPE_FINGER, buttonState=0, classification=NONE, metaState=0, flags=0x0, edgeFlags=0x0, pointerCount=1, historySize=1, eventTime=9093118, downTime=5693309, deviceId=-1, source=0x1002, displayId=0, eventId=-790698933 }
//从21:16:05开始，事件的接受方是桌面，在时间段内，桌面进程除了上述事件的日志打印，并没有其他日志打印也没有启动任何应用，说明当前的动作只是不停的在桌面滑动
//滑动持续了20来分钟，产生了ANR

06-01 21:38:58.636 1537 1777 W InputDispatcher: Monitor PointerEventDispatcher0 (server) is unresponsive: PointerEventDispatcher0 (server) is not responding. Waited 5001ms for MotionEvent
06-01 21:38:58.636 1537 1777 W InputDispatcher: Canceling events for PointerEventDispatcher0 (server) because it is unresponsive
06-01 21:38:58.636 1537 1777 I WindowManager: ANR in gesture monitor owned by pid:1537. Reason: PointerEventDispatcher0 (server) is not responding. Waited 5001ms for MotionEvent
//处理时间超过5秒，就会产生anr

06-01 21:39:17.331 1537 17016 E ActivityManager: ANR in system
06-01 21:39:17.331 1537 17016 E ActivityManager: PID: 1537
06-01 21:39:17.331 1537 17016 E ActivityManager: Reason: Input dispatching timed out (PointerEventDispatcher0 (server) is not responding. Waited 5001ms for MotionEvent)
----------------------

结合上述分析以及测试的动作
1.测试为副屏静态老化，通过adb指令，副屏桌面空白处按压12H
2.事件传输链路正常，只是处理在问题时间段内越来越慢，桌面进程并无其他操作，只是在打印接受事件的日志
问题的原因应该是:疯狂打印事件接受日志导致，导致事件处理变慢

■ 下一步计划
删除该事件打印的日志

ftp://cdiot@192.168.87.46/Pre_figure/Test_Log/118456/tlog_iov0201017500006162025411a2212290000000771_000195_0602163333.tar.gz

■ 我的分析

------------------------------
06-13 21:34:44.578 1574 24659 E ActivityManager: ANR in system
06-13 21:34:44.578 1574 24659 E ActivityManager: PID: 1574
06-13 21:34:44.578 1574 24659 E ActivityManager: Reason: Input dispatching timed out (PointerEventDispatcher0 (server) is not responding. Waited 5000ms for MotionEvent(deviceId=-1, eventTime=73173015000000, source=0x00001002, displayId=0, action=MOVE, actionButton=0x00000000, flags=0x00000000, metaState=0x00000000, buttonState=0x00000000, classification=NONE, edgeFlags=0x00000000, xPrecision=1.0, yPrecision=1.0, xCursorPosition=nan, yCursorPosition=nan, pointers=[0: (1780.0, 650.0)]), policyFlags=0x6b000000)
06-13 21:34:44.578 1574 24659 E ActivityManager: ErrorId: b8d5d575-26e8-4402-9529-35bf5aee528c
06-13 21:34:44.578 1574 24659 E ActivityManager: Frozen: false
06-13 21:34:44.578 1574 24659 E ActivityManager: Load: 4.51 / 1.97 / 1.67
06-13 21:34:44.578 1574 24659 E ActivityManager: ----- Output from /proc/pressure/memory -----
06-13 21:34:44.578 1574 24659 E ActivityManager: some avg10=1.09 avg60=0.27 avg300=0.06 total=8865783
06-13 21:34:44.578 1574 24659 E ActivityManager: full avg10=0.00 avg60=0.00 avg300=0.00 total=2639021
06-13 21:34:44.578 1574 24659 E ActivityManager: ----- End output from /proc/pressure/memory -----
06-13 21:34:44.578 1574 24659 E ActivityManager:
06-13 21:34:44.578 1574 24659 E ActivityManager: CPU usage from 0ms to 8881ms later (2023-06-13 21:34:35.633 to 2023-06-13 21:34:44.515):
06-13 21:34:44.578 1574 24659 E ActivityManager: 108% 1574/system_server: 73% user + 34% kernel / faults: 503001 minor 14 major
06-13 21:34:44.578 1574 24659 E ActivityManager: 31% 11579/com.tencent.qqmusic: 20% user + 10% kernel / faults: 2507 minor 4 major
06-13 21:34:44.578 1574 24659 E ActivityManager: 10% 1023/surfaceflinger: 6.2% user + 4.1% kernel / faults: 862 minor
06-13 21:34:44.579 1574 24659 E ActivityManager: 40% TOTAL: 21% user + 16% kernel + 0.6% iowait + 1.2% irq + 0.4% softirq
06-13 21:34:44.579 1574 24659 E ActivityManager: CPU usage from 202ms to 771ms later (2023-06-13 21:34:35.835 to 2023-06-13 21:34:36.405):
06-13 21:34:44.579 1574 24659 E ActivityManager: 270% 1574/system_server: 141% user + 129% kernel / faults: 107721 minor
06-13 21:34:44.579 1574 24659 E ActivityManager: 78% 1705/android.ui: 23% user + 55% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 78% 9096/RenderThread: 57% user + 21% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 40% 24659/AnrConsumer: 14% user + 26% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 11% 2112/Binder:1574_5: 7.1% user + 4.7% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 7.1% 1887/InputDispatcher: 4.7% user + 2.3% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 7.1% 16783/Binder:1574_1A: 4.7% user + 2.3% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 4.7% 1728/OomAdjuster: 0% user + 4.7% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 4.7% 3276/Binder:1574_D: 4.7% user + 0% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 4.7% 15264/Binder:1574_17: 2.3% user + 2.3% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 2.3% 1606/Binder:1574_2: 2.3% user + 0% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 2.3% 1708/android.display: 2.3% user + 0% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 2.3% 1722/ActivityManager: 2.3% user + 0% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 2.3% 1725/ActivityManager: 2.3% user + 0% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 2.3% 1897/EventHandlerThr: 2.3% user + 0% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 2.3% 14188/Binder:1574_16: 0% user + 2.3% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 2.3% 16553/Binder:1574_19: 0% user + 2.3% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 31% 90/oom_reaper: 0% user + 31% kernel
06-13 21:34:44.579 1574 24659 E ActivityManager: 96% TOTAL: 39% user + 53% kernel + 2.6% irq + 0.6% softirq
------------------------------

发生问题时，CPU拉到了96%，占用过高, 其中system_server异常拉伸到270%
cpu资源主要被下面线程在使用
①78% 1705/android.ui: 23% user + 55% kernel
通过下面的线程堆栈可知，在绘制当前触摸点的信息，这个是由于开启了触摸点信息显示
-----------
"android.ui" prio=5 tid=14 Runnable | group="main" sCount=0 ucsCount=0 flags=0 obj=0x15303178 self=0xb4000079a9666ad0 | sysTid=1705 nice=-2 cgrp=default sched=0/0 handle=0x77ac258cb0 | state=R schedstat=( 331418487198 15445073142 281510 ) utm=12768 stm=20373 core=4 HZ=100 | stack=0x77ac155000-0x77ac157000 stackSize=1039KB | held mutexes= "mutator lock"(shared held)
native: #00 pc 000000000056a948 /apex/com.android.art/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+144)
native: #01 pc 0000000000685f74 /apex/com.android.art/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, bool, BacktraceMap*, bool) const+364)
native: #02 pc 00000000006a468c /apex/com.android.art/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+924)
native: #03 pc 0000000000686f0c /apex/com.android.art/lib64/libart.so (art::Thread::RunCheckpointFunction()+180)
native: #04 pc 000000000074ce30 /apex/com.android.art/lib64/libart.so (art::JniMethodFastEnd(unsigned int, art::Thread*)+120)
at android.graphics.BaseRecordingCanvas.nDrawPoint(Native method)
at android.graphics.BaseRecordingCanvas.drawPoint(BaseRecordingCanvas.java:329)
at com.android.internal.widget.PointerLocationView.onDraw(PointerLocationView.java:375)
at android.view.View.draw(View.java:22649)
at android.view.View.updateDisplayListIfDirty(View.java:21524)
at android.view.ThreadedRenderer.updateViewTreeDisplayList(ThreadedRenderer.java:534)
-----------
②78% 9096/RenderThread: 57% user + 21% kernel
渲染图形的线程，协助UI框架实现一些图形相关的操作，根据当前设备状态，当前应该是在处理触摸点显示信息的View
③40% 24659/AnrConsumer: 14% user + 26% kernel
ANR线程，仅在出现anr时工作

■ 下一步计划
根据上述分析，由于adb命令按压2h，持续不断绘制触摸点信息，导致了cpu压力过大，发生anr
请测试同学关闭触摸点信息显示的View，再做adb命令按压2h的测试

adb 命令按压12H，验证通过