Figure

1、5月29日最新进展

1）monkey停止的原因
从日志中我们可以获取到如下信息：

11-11 07:30:13.869     0     0 W [27012.522260] Mem-Info:  
11-11 07:30:13.869     0     0 W [27012.522330] active_anon: 1261745 inactive_anon:180117 isolated_anon:31
11-11 07:30:13.870     0     0 W [27012.522330]  active_file: 8387 inactive_file:8494 isolated_file:0
11-11 07:30:13.870     0     0 W [27012.522330]  unevictable: 27202 dirty:58 writeback:0 unstable:0
11-11 07:30:13.870     0     0 W [27012.522330]  slab_reclaimable: 16895 slab_unreclaimable:63890
11-11 07:30:13.870     0     0 W [27012.522330]  mapped: 65309 shmem:3159 pagetables:19934 bounce:0
11-11 07:30:13.870     0     0 W [27012.522330]  free: 18885 free_pcp:879 free_cma:0
11-11 07:30:13.870     0     0 W         : [27012.522336] Node 0 active_anon:5046980kB inactive_anon:720468kB active_file:33548kB inactive_file:33976kB unevictable:108808kB isolated(anon):124kB isolated(file):0kB mapped:261236kB dirty:232kB writeback:0kB shmem:12636kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
11-11 07:30:13.870     0     0 W         : [27012.522344] Normal free:73044kB min:7040kB low:41492kB high:43252kB active_anon:3544024kB inactive_anon:478540kB active_file:33456kB inactive_file:34468kB unevictable:108216kB writepending:232kB present:5960896kB managed:5799084kB mlocked:108216kB kernel_stack:43472kB pagetables:79736kB bounce:0kB free_pcp:3408kB local_pcp:252kB free_cma:0kB
11-11 07:30:13.870     0     0 W [27012.522345] lowmem_reserve[]: 0 16384
11-11 07:30:13.870     0     0 W         : [27012.522355] Movable free:2496kB min:2544kB low:15000kB high:15636kB active_anon:1503392kB inactive_anon:241672kB active_file:0kB inactive_file:0kB unevictable:592kB writepending:0kB present:2097152kB managed:2097152kB mlocked:592kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:248kB local_pcp:248kB free_cma:0kB
11-11 07:30:13.872     0     0 W [27012.522356] lowmem_reserve[]: 0 0
11-11 07:30:13.873     0     0 W [27012.522359] Normal: 22*4kB (U) 83*8kB (UE) 19*16kB (U) 11*32kB (UE) 1114*64kB (U) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 72704kB
11-11 07:30:13.873     0     0 W [27012.522463] Movable: 89*4kB (M) 0*8kB 4*16kB (M) 3*32kB (M) 1*64kB (M) 9*128kB (M) 2*256kB (M) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2244kB
11-11 07:30:13.873     0     0 W         : [27012.522493] 53950 total pagecache pages
11-11 07:30:13.873     0     0 W         : [27012.522503] 6931 pages in swap cache
11-11 07:30:13.873     0     0 W         : [27012.522506] Swap cache stats: add 6899218, delete 6895885, find 2920473/7607719
11-11 07:30:13.873     0     0 W         : [27012.522507] Free swap  = 0kB
11-11 07:30:13.873     0     0 W         : [27012.522509] Total swap = 4194300kB
11-11 07:30:13.873     0     0 W         : [27012.522510] 2014512 pages RAM
11-11 07:30:13.873     0     0 W         : [27012.522512] 0 pages HighMem/MovableOnly
11-11 07:30:13.873     0     0 W         : [27012.522513] 40453 pages reserved
11-11 07:30:13.873     0     0 W         : [27012.522514] 89088 pages cma reserved
11-11 07:30:14.251     0     0 E         : [27012.902312] Out of memory: Kill process 1209 (tlog) score 0 or sacrifice child
11-11 07:30:14.251     0     0 E         : [27012.910121] Killed process 1209 (tlog) total-vm:17772012kB, anon-rss:5345780kB, file-rss:2240kB, shmem-rss:248kB oom_score_adj=-900
11-11 07:30:14.327     0     0 I [27012.986358] binder: 13372:13372 ioctl 40046210 7fc9627184 returned -22
11-11 15:09:14.816     0     0 W [54554.308411] Mem-Info:  
11-11 15:09:14.819     0     0 W [54554.308423] active_anon: 1345599 inactive_anon:192226 isolated_anon:64
11-11 15:09:14.819     0     0 W [54554.308423]  active_file: 6405 inactive_file:6187 isolated_file:0
11-11 15:09:14.819     0     0 W [54554.308423]  unevictable: 27203 dirty:23 writeback:0 unstable:0
11-11 15:09:14.819     0     0 W [54554.308423]  slab_reclaimable: 17448 slab_unreclaimable:56616
11-11 15:09:14.819     0     0 W [54554.308423]  mapped: 39207 shmem:3338 pagetables:19584 bounce:0
11-11 15:09:14.819     0     0 W [54554.308423]  free: 18368 free_pcp:555 free_cma:99
11-11 15:09:14.819     0     0 W         : [54554.308429] Node 0 active_anon:5382164kB inactive_anon:768904kB active_file:25620kB inactive_file:24748kB unevictable:108812kB isolated(anon):256kB isolated(file):0kB mapped:156828kB dirty:92kB writeback:0kB shmem:13352kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
11-11 15:09:14.819     0     0 W         : [54554.308437] Normal free:73508kB min:7040kB low:41492kB high:43252kB active_anon:3705980kB inactive_anon:659008kB active_file:25716kB inactive_file:24328kB unevictable:108216kB writepending:88kB present:5960896kB managed:5799084kB mlocked:108216kB kernel_stack:38288kB pagetables:78336kB bounce:0kB free_pcp:2216kB local_pcp:252kB free_cma:396kB
11-11 15:09:14.819     0     0 W [54554.308438] lowmem_reserve[]: 0 16384
11-11 15:09:14.819     0     0 W         : [54554.308447] Movable free:0kB min:2544kB low:15000kB high:15636kB active_anon:1676184kB inactive_anon:109940kB active_file:0kB inactive_file:0kB unevictable:596kB writepending:0kB present:2097152kB managed:2097152kB mlocked:596kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
11-11 15:09:14.819     0     0 W [54554.308448] lowmem_reserve[]: 0 0
11-11 15:09:14.819     0     0 W [54554.308451] Normal: 194*4kB (UM) 18*8kB (M) 21*16kB (M) 39*32kB (UE) 1033*64kB (UE) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB (H) = 72712kB
11-11 15:09:14.819     0     0 W [54554.308466] Movable: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 0kB
11-11 15:09:14.819     0     0 W         : [54554.308477] 44484 total pagecache pages
11-11 15:09:14.819     0     0 W         : [54554.308483] 1732 pages in swap cache
11-11 15:09:14.819     0     0 W         : [54554.308485] Swap cache stats: add 14203046, delete 14205542, find 6730748/16605858
11-11 15:09:14.819     0     0 W         : [54554.308486] Free swap  = 434592kB
11-11 15:09:14.819     0     0 W         : [54554.308487] Total swap = 4194300kB
11-11 15:09:14.819     0     0 W         : [54554.308489] 2014512 pages RAM
11-11 15:09:14.819     0     0 W         : [54554.308490] 0 pages HighMem/MovableOnly
11-11 15:09:14.819     0     0 W         : [54554.308492] 40453 pages reserved
11-11 15:09:14.819     0     0 W         : [54554.308493] 89088 pages cma reserved
11-11 15:09:15.834     0     0 I [54555.328494] oom_reaper: reaped process 26181 (re-initialized>), now anon-rss:0kB, file-rss:0kB, shmem-rss:16kB
11-11 15:09:15.865     0     0 I [54555.358510] oom_reaper: reaped process 26168 (.microsoft.emmx), now anon-rss:0kB, file-rss:0kB, shmem-rss:332kB
11-11 15:09:15.951     0     0 E         : [54555.422451] Out of memory: Kill process 1280 (system_server) score 0 or sacrifice child
11-11 15:09:15.951     0     0 E         : [54555.431048] Killed process 1280 (system_server) total-vm:20959012kB, anon-rss:0kB, file-rss:0kB, shmem-rss:7548kB oom_score_adj=-900
11-11 15:09:16.013     0     0 I [54555.506058] oom_reaper: reaped process 1280 (system_server), now anon-rss:0kB, file-rss:150620kB, shmem-rss:7348kB
11-11 15:09:16.781     0     0 I [54556.274834] binder: 26259:26259 ioctl 40046210 ff8a75b0 returned -22
11-11 15:09:16.925     0     0 I [54556.419105] binder: 26248:26295 ioctl 40046210 6fd43b8144 returned -22
11-11 15:09:17.226     0     0 E         : [54556.709719] Out of memory: Kill process 13450 (tlog) score 0 or sacrifice child
11-11 15:09:17.227     0     0 E         : [54556.717320] Killed process 13450 (tlog) total-vm:17837548kB, anon-rss:6373432kB, file-rss:4836kB, shmem-rss:248kB 
oom_score_adj=-900

可以发现发生了tlog和system_server 发生了oom的问题，
导致system_server被杀了，可能引起了monkey的杀除。
关于OOM的问题有票https://share.thundersoft.com/redmine/issues/118126 在跟进。

2）anr问题

在FSEM_000055_0002_1111150936文件下有大量的anr日志文件
从分析来看，大多都是几个游戏应用的：com.tencent.tmgp.pubgmhd、 com.yymoon.dxc

分析trace文件：
Anr 日志文件：anr_2022-11-11-03-14-28-377
Subject: Input dispatching timed out (Application does not have a focused window)
----- Waiting Channels: pid 32406 at 2022-11-11 03:14:28.378950729+0800 -----
Cmd line: com.tencent.tmgp.pubgmhd
crash_dump failed to dump process 32406: failed to attach to thread 32406, already traced by 1122 (debuggerd)
可以看出针对 com.tencent.tmgp.pubgmhd的trace文件的抓取是失败的，没有太多的有用信息。
从内存来看
CPU usage from 0ms to 20937ms later (2022-11-11 03:14:27.999 to 2022-11-11 03:14:48.907):
20% 1280/system_server: 13% user + 7.5% kernel / faults: 106999 minor 5 major
14% 914/surfaceflinger: 9.9% user + 4.1% kernel / faults: 2278 minor
13% 32406/com.tencent.tmgp.pubgmhd: 10% user + 3.4% kernel / faults: 29769 minor
13% 852/vendor.qti.hardware.display.composer-service: 8.4% user + 4.6% kernel / faults: 672 minor
11% 1914/com.android.systemui: 9.5% user + 1.9% kernel / faults: 6080 minor
24% TOTAL: 14% user + 8.5% kernel + 0.4% iowait + 1% irq + 0.3% softirq
这个时候的内存使用是正常的未发生明显的异常。
从提供日志中未能找到发生anr时和anr之前时间的logcat信息（应该是日志缺失了未抓到anr当时的日志）
又分析了其他几个anr文件，发现情况都不差不多，暴露问题的进程是com.tencent.tmgp.pubgmhd，但是并未抓取到
正确的trace信息。

综述：发生anr的对象都是几个游戏应用：com.tencent.tmgp.pubgmhd、 com.yymoon.dxc，问题都是monkey发送给
它们的keyevent、motionevent没有及时响应，从事件的角度来看这些event游戏应用也许并不能响应。anr的文件又未抓取到正确的
trace信息，anr发生时的logcat信息不正确，从研发的角度并不能从当前的日志和trace中获取有用的信息进行分析。
建议可以尝试继续monkey测试，复现问题时，争取抓取到有用的信息（另外进行测试时最好将系统时间调为当时测试的正确时间）。

2、下一步
1）monkey停止的问题，根据 https://share.thundersoft.com/redmine/issues/118126 的情况验证OOM的问题，是否还会引起monkey的停止。
2）anr问题，从目前的日志信息不能分析出具体的原因，需要测试尝试复现或者继续进行测试，补充复现问题并抓取到正确和用的日志信息。