Android iow占用高问题排查

哈哈linux
1,953 阅读14分钟

每个疑难杂症，都是一次成长的机会。机会需要把握，机会也需要分享。

1. iow占用高问题现象

top命令是Linux下常用的性能分析工具，能够实时显示系统中各个进程的资源占用状况。在一个项目开发过程中，通过top -n 5查看系统资源使用情况时，发现一些可疑点。

top命令的使用

  • 32%iow：有进程在等待操作磁盘IO，有异常
  • android.hardware.audio.service-droidlogic占用CPU高：属于已知问题，无异常
  • init进程占用25.8%，有异常
Tasks: 275 total,   1 running, 274 sleeping,   0 stopped,   0 zombie
  Mem: 16777216T total, 16777216T used,   519964K free,   141768K buffers
 Swap:   524284K total,         0 used,   524284K free,  1120908K cached
400%cpu  26%user   0%nice  65%sys 265%idle  32%iow  10%irq   3%sirq   0%host
   PID USER         PR  NI VIRT  RES  SHR S[%CPU] %MEM     TIME+ ARGS
   334 audioserver  20   0  80M  32M  11M S 35.4   0.9  14:28.30 android.hardware.audio.service-droidlogic
     1 root         20   0  46M 8.2M 5.2M S 25.8   0.2   9:09.93 init second_stage
  3049 root         20   0  11M 3.4M 2.7M R 19.3   0.0   0:00.06 top -n 5
   403 root         20   0  72M  29M  24M S 16.1   0.8   6:24.27 tvserver
   288 root         20   0    0    0    0 S  6.4   0.0   2:19.04 [jbd2/dm-6-8]
  3007 root          0 -20    0    0    0 I  3.2   0.0   0:01.68 [kworker/0:2H-mmc_complete]

什么叫iow，iow占不占用CPU资源？

iow也叫做iowait，其实是一种cpu idle状态。当linux内核在统计CPU资源使用时间的时候，如果此时CPU处于idle空闲状态，同时有进程task在等待io，则记录为iowait时间。故iow不占用CPU资源，但是数值高表示有进程一直在等待io，是可能存在问题的。

同时对比了同一SOC的其他项目正常机器，表现如下：

Tasks: 245 total,   1 running, 244 sleeping,   0 stopped,   0 zombie
  Mem:  1007648K total,   990680K used,  17375232 free,   4153344 buffers
 Swap:   358396K total,   156928K used,   201468K free,   126420K cached
400%cpu  34%user   0%nice  31%sys 322%idle   0%iow  13%irq   0%sirq   0%host
   PID USER         PR  NI VIRT  RES  SHR S[%CPU] %MEM     TIME+ ARGS
   330 audioserver  20   0  78M  13M 2.2M S 28.1   1.3   2:52.29 android.hardware.audio.service-droidlogic
   375 root         20   0  68M 3.8M 2.5M S 21.8   0.3   2:23.56 tvserver
  3107 root         20   0  11M 3.3M 2.6M R 15.6   0.3   0:00.07 top -n 5
  1530 root         RT   0    0    0    0 S  3.1   0.0   0:02.71 [ppmgr]
  1247 root         RT   0    0    0    0 S  3.1   0.0   0:23.27 [sugov:0]
   263 root         20   0    0    0    0 S  3.1   0.0   0:09.76 [kworker/u8:4+algo-workqueue]
   178 root         20   0    0    0    0 I  3.1   0.0   0:03.79 [kworker/2:5-cec_work]
   150 root         RT   0    0    0    0 S  3.1   0.0   0:01.88 [aml-ditest-0]
     7 root         20   0    0    0    0 I  3.1   0.0   0:13.08 [kworker/u8:0-events_unbound]

故可以确定，很有可能是存在问题的。

2. iow占用高问题排查过程

2.1 vmstat

vmstat是Virtual Meomory Statistics（虚拟内存统计）的缩写，可实时动态监视操作系统的虚拟内存、进程、CPU活动。

vmstat命令的使用

使用vmstat 5 5每5s打印一次，总共5次，可以发现bo与wa异常。

  • bo表示每秒写入的块数，例如CPU写入文件到磁盘，bo就要大于0。正常bi和bo一般都要接近0，不然就是IO过于频繁，需要调整。
  • wa表示等待IO时间，正常情况下也为0。
console:/ # vmstat 5 5
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 1  0      0 574552 130100 1156344   0    0  4990  9331    1 13510 27 22 42 9
 0  1      0 567580 131376 1156360   0    0     4 11325    1 24604 17 17 57 9
 1  1      0 566132 132292 1156356   0    0     0 11442    1 24738 16 17 58 9
 1  1      0 563392 133560 1156532   0    0     0 11501    1 24502 13 23 55 9
 3  0      0 562636 134264 1156572   0    0     0 11420    1 24617 5 28 58  9

同样对比同SOC的其他项目正常机器：

 vmstat 5 5
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 0  0 156672  19508   3976 128460   18   97   528    28    1 7653 10 14 75  1
 1  0 156672  16656   3984 129968    7    0   291    27    1 24063 8 13 79  0
 1  0 156672  16248   3992 129868    1    0   118    21    0 23891 8 12 80  0
 0  0 156928  16268   3980 127008    4   76   185    37    1 23529 9 12 79  0
 1  0 156928  16264   3988 126484    0    3     5    35    1 23632 8 13 79  0

2.2 iotop

iotop命令的使用

使用iotop -d 5 | head -n 10查看磁盘IO占用，从如下log可以看出：

  • jbd2/mmcblk0p29：I/占用很高
  • init进程：影响可能比较大，但是PID为205而不是1，所以可推测与init下的某个线程有关系。
                         --- IO (KiB/s) --- --- faults ---  ----------- delayed on ----------
   PID Command            read  write  total  major  minor  IO     swap   sched  mem    total
   205 init                  0    477    477      0      0  5.56%  0.00%  2.41%  0.00%  7.97%
  2542 logcat                0     24     24      0      0  0.33%  0.00%  0.36%  0.00%  0.69%
   293 jbd2/mmcblk0p29       0     10     10      0      0 56.38%  0.00%  2.65%  0.00% 59.02%
  2181 Profile Saver         0      2      2      0     67  0.04%  0.00%  0.17%  0.00%  0.21%
  2180 Thread-3              0      0      0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
     1 init                  0      0      0      0      0  0.00%  0.00%  0.36%  0.00%  0.36%
     2 kthreadd              0      0      0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
     3 rcu_gp                0      0      0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%

2.3 使用atrace跟踪线程jbd2/mmcblk0p29信息

Android atrace/systrace的使用

1642133766.png

1642133775.png

jbd2/mmcblk0p29是文件系统的 日志进程，如果有进程对data分区写数据的话，文件系统就会通过这个进程来记录，属于被影响者。所以是有进程对data分区频繁的写了数据。

2.4 继续查看205的线程

使用ps -efT，找不到对应的205线程，只能从init入手。

ps -efT：找不到对应的205线程
root            200   200      2    1 22:15:01 ?     00:00:00 [kworker/1:3-events]
root            201   201      2    1 22:15:01 ?     00:00:00 [kworker/2:3H-kblockd]
root            202   202      2    1 22:15:01 ?     00:00:00 [kworker/0:5H-mmc_complete]
root            203   203      2    1 22:15:02 ?     00:00:00 [kworker/3:2H-kblockd]
root            204   204      2    1 22:15:02 ?     00:00:00 [kworker/1:1H-kblockd]
root            206   206      1    1 22:15:02 ?     00:00:00 init subcontext u:r:vendor_init:s0 15
root            208   208      1    1 22:15:02 ?     00:00:08 ueventd

2.5 strace打印异常机器init进程的系统调用情况

strace命令的使用

strace -c -f -p 1
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 57.02   11.199842        1066     10503           epoll_pwait
  5.55    1.089301         235      4628           renameat
  5.46    1.073230          77     13884           openat
  4.02    0.788652          79      9880           write
  3.97    0.779451          84      9255           fsync
  3.34    0.656198         124      5251           waitid
  3.09    0.607560          31     19136           close
  2.91    0.570653          11     51272           clock_gettime
  2.67    0.524042          14     36140           ppoll
  2.14    0.420936          16     25636           recvfrom
  2.14    0.420456          26     15756           getsockopt
  2.02    0.396111          20     19135           read
  1.71    0.336436          64      5252           sendto
  1.36    0.266383          57      4628      4628 faccessat
  1.19    0.234080          44      5252           accept4
  0.77    0.151465          14     10504           futex
  0.65    0.127401          13      9256           fstat64
------ ----------- ----------- --------- --------- ----------------
100.00   19.642197                255368      4628 total

抓取异常与正常机器init进程及其线程的系统调用，截取1s的时间：

strace -T -tt -e trace=all -f -p 1 -o /mnt/media_rw/sda1/982_haiwai_output_init_thread.txt strace -T -tt -e trace=all -f -p 1 -o /mnt/media_rw/sda1/982_vi_output_init_thread.txt

对比文件982_haiwai_output_init_thread.txt与982_vi_output_init_thread.txt可得出205的线程一直在操作文件描述符19与20。

1642134147.png

1642134158.png

ls -l /proc/1/fd 查看init进程打开的fd，文件描述符19是socket，文件描述符20是/data/property/persistent_properties.tmp。

ls -l /proc/1/fd
total 0
lrwx------ 1 root root 64 2021-12-30 00:13 0 -> /dev/null
lrwx------ 1 root root 64 2021-12-30 00:13 1 -> /dev/null
lrwx------ 1 root root 64 2021-12-30 00:13 10 -> socket:[18587]
lr-x------ 1 root root 64 2021-12-30 00:13 11 -> /proc/1/mounts
lrwx------ 1 root root 64 2021-12-30 00:13 12 -> anon_inode:[eventpoll]
lr-x------ 1 root root 64 2021-12-30 00:13 13 -> mnt:[4026531840]
lr-x------ 1 root root 64 2021-12-30 00:13 14 -> mnt:[4026531840]
lrwx------ 1 root root 64 2021-12-30 00:13 15 -> socket:[18623]
lrwx------ 1 root root 64 2021-12-30 00:13 16 -> /dev/device-mapper
l-wx------ 1 root root 64 2021-12-30 00:13 17 -> /dev/kmsg
lrwx------ 1 root root 64 2021-12-30 00:13 18 -> socket:[22340]
lrwx------ 1 root root 64 2021-12-30 00:13 19 -> socket:[2207269]
lrwx------ 1 root root 64 2021-12-30 00:13 2 -> /dev/null
l-wx------ 1 root root 64 2021-12-30 00:17 20 -> /data/property/persistent_properties.tmp
l-wx------ 1 root root 64 2021-12-30 00:13 3 -> /dev/kmsg
lrwx------ 1 root root 64 2021-12-30 00:13 4 -> socket:[18582]
lrwx------ 1 root root 64 2021-12-30 00:13 5 -> anon_inode:[eventpoll]
lrwx------ 1 root root 64 2021-12-30 00:13 6 -> anon_inode:[signalfd]
lrwx------ 1 root root 64 2021-12-30 00:13 7 -> anon_inode:[eventfd]
lrwx------ 1 root root 64 2021-12-30 00:13 8 -> socket:[18585]
lrwx------ 1 root root 64 2021-12-30 00:13 9 -> socket:[18586]

lsof -p 1：列出指定进程号所打开的文件

COMMAND     PID       USER   FD      TYPE             DEVICE  SIZE/OFF       NODE NAME
init        205       root  cwd       DIR              253,0      4096          2 /
init        205       root  rtd       DIR              253,0      4096          2 /
init        205       root  txt       REG              253,0    754128       1076 /system/bin/init
init        205       root  mem       REG              253,0    754128       1076 /system/bin/init
......
init        205       root   16u      CHR             10,236       0t0       2574 /dev/device-mapper
init        205       root   17w      CHR               1,11       0t0       2105 /dev/kmsg
init        205       root   18u     unix                          0t0      22340 socket
init        205       root   19u     unix                          0t0    2158313 /dev/socket/property_service
init        205       root   20r      DIR             179,29      4096     498249 /data/property

推断与property有关，研究property的源码。

2.6 在Android property源码中添加log打印

在property_service.cpp中函数handle_property_set_fd()添加打印，handle_property_set_fd()：设置property时触发的回调函数。

static void handle_property_set_fd() {
    switch (cmd) {
        case PROP_MSG_SETPROP: {
            if (!socket.RecvChars(prop_name, PROP_NAME_MAX, &timeout_ms) ||
                !socket.RecvChars(prop_value, PROP_VALUE_MAX, &timeout_ms))
            LOG(ERROR) << "[prop] prop_name: '" << prop_name << "', prop_value: " << prop_value;
            uint32_t result = HandlePropertySet(prop_name, prop_value, source_context, cr, nullptr, &error);
            break;
          }
    
        case PROP_MSG_SETPROP2: {
            if (!socket.RecvString(&name, &timeout_ms) ||
                !socket.RecvString(&value, &timeout_ms)) 
            LOG(ERROR) << "[prop] prop_name: '" << name << "', prop_value: " << value;
            uint32_t result = HandlePropertySet(name, value, source_context, cr, &socket, &error);
            break;
          }
    }
}

从log看persist.ctm.devicelist.slot与persist.ctm.devicelist频繁在设置。而persist属性设置时是需要保存到/data/property文件中的。

[  277.826256@3]  init: [prop] prop_name: 'persist.ctm.devicelist', prop_value: 2148270338
[  277.834984@3]  init: [prop] prop_name: 'persist.ctm.devicelist.slot', prop_value: 0
[  282.770415@1]  init: [prop] prop_name: 'persist.ctm.devicelist.slot', prop_value: 0
[  282.779763@2]  init: [prop] prop_name: 'persist.ctm.devicelist', prop_value: 2148270338
[  282.789187@2]  init: [prop] prop_name: 'persist.ctm.devicelist.slot', prop_value: 0
[  282.795443@0]  init: [prop] prop_name: 'persist.ctm.devicelist', prop_value: 2148270338
[  282.807507@1]  init: [prop] prop_name: 'persist.ctm.devicelist.slot', prop_value: 0
[  282.817137@2]  init: [prop] prop_name: 'persist.ctm.devicelist', prop_value: 2148270338
[  282.825768@2]  init: [prop] prop_name: 'persist.ctm.devicelist.slot', prop_value: 0
[  282.831808@2]  init: [prop] prop_name: 'mic.hw.test.req', prop_value: 
[  282.832710@2]  init: [prop] prop_name: 'persist.ctm.devicelist', prop_value: 2148270338
[  282.842315@1]  init: [prop] prop_name: 'persist.ctm.devicelist.slot', prop_value: 0
[  287.776701@2]  init: [prop] prop_name: 'persist.ctm.devicelist.slot', prop_value: 0
[  287.784725@2]  init: [prop] prop_name: 'persist.ctm.devicelist', prop_value: 2148270338

2.7 查找使用persist.ctm.devicelist.slot与persist.ctm.devicelist的地方

1642134580(1).jpg

2.8 找到源码排查

1642134609.png

1642134634(1).jpg

这下问题水落石出，就是这个属性导致的。

2.9 找到原作者确认原因

1、原本只需要初始化执行一次的任务，放到了线程里面循环执行---->原因是初始化执行一次的时候属性会设置失败，属性值会被修改，所以找了这个规避方法。 2、线程里面1ms进行循环---->考虑不周

2.10 讨论解决办法

1、临时解决方法：将1ms改为10ms执行，相同属性值，不设置，优先确保解决掉iow的问题。

2、永久措施：找到初始化执行的时候设置失败的原因，可能原因：

  • 1.初始化阶段设置有点早---->同一个地方，换其他属性设置是能设置成功的；此属性初始化延时50s，设置也不能成功。
  • 2.设置了然后被覆盖---->在property_set()中的__system_property_set()中添加打印，是否有多次设置 ----> 打印显示只设置了一次，即设置为1，但是最终getprop的结果确是0。
  • 3.调用了property_set但是没设置成功---->在__system_property_set()中加堆栈打印，但是__system_property_set()在libc库中，堆栈打印又依赖libc库，编译不通过。不过后续找到其他办法解决，当时这个时候是忽略了这个方法。 Android hal层堆栈打印方法

2.11 继续寻找属性初始化失败的原因

在init进程的property service中添加打印，因为属性设置最终的实现是在property service中的。

image.png

结果init property service中的打印很少，有遗漏，并且incount没有连续增加，故可得出结论，init property service中的打印不全。

image.png

2.12 查看在property_set()中的__system_property_set()中打印

有大量的如下属性"mic.hw.test.req"一直被设置，怀疑相互之间有影响，故寻找设置的源头。屏蔽掉所有能设置如下属性的地方，但是还是会频繁的进行设置，最后咨询相关模块的同事，均不清楚哪个地方还能设置，至此找不到这个的原因。

image.png

按如下设置进行屏蔽掉这个属性，排除这个属性设置的影响。结果之前的问题还是存在（"persist.ctm.devicelist.slot"还是会被覆盖）。

image.png

到目前为止，此问题就变得很奇怪，没有打印，却属性值不对。陷入迷茫中......

这个过程中，阅读了属性设置、socket相关的源码，问了周边同事有啥好建议，均没有收获。开始自闭......

2.13 没有放弃，继续找原因，偶然间，导出一份log

尝试等了很长时间，再去再导一次logcat，结果发现：

image.png

被另外的进程重新设置了！！！

喜出望外，查找对应的进程，找到对应负责的人，的确会有这个动作，是从其他平台移植过来的。

不要太相信logcat，可能打印不全！！！

至此问题完全解决，前前后后、断断续续花了一周多的时间，问题原因很简单，但是解决问题的过程，的确有些艰难。也许是基础不够好，没有找到合适的方法，回过头想想，有很多地方是不用走弯路的，特别是logcat打印丢失的问题，不过这也是一个成长。最后，遇到问题再奇怪，也不要放弃，说不定突然间就豁然开朗。

3. 回头看看一些疑惑的地方

3.1 针对logcat打印，后续注意

    1. 对logcat中频繁的打印进行缩减，避免被误删
    1. 关键性的打印，不要进行频繁打印，要有针对性打印。例如本例中针对所需要的属性进行打印，实测不会丢失，两次设置都被打印出来 image.png
    1. 增加logcat缓冲区

image.png

3.2 在__system_property_set()中加堆栈打印

Android hal层堆栈打印方法

3.3 属性"mic.hw.test.req"频繁设置的原因

在__system_property_set()中将属性"mic.hw.test.req"的调用栈打出来，可发现与/vendor/lib/hw/audio.primary.amlogic.so中mainThreadFunc()相关，在源码中找这个so，来源于一个libxxxxAudioProcess.a的文件，至此问题水落石出。

__BIONIC_WEAK_FOR_NATIVE_BRIDGE
int __system_property_set(const char* key, const char* value) {
  if (key == nullptr) return -1;
  if (value == nullptr) value = "";

  if(memcmp(key, "mic.hw.test.req", strlen("mic.hw.test.req")) == 0)
  {
    async_safe_format_log(ANDROID_LOG_WARN, "[prop]libc", "__system_property_set set property1 \"%s\" to \"%s\"", key, value);
    check_and_callcheck(key);
  }
}

01-14 00:21:43.565891   321   460 D dumpstack: #00 pc 00001401  /system/lib/libdumpstack.so (dumping_callstack+36)
01-14 00:21:43.565998   321   460 D dumpstack: #01 pc 000445ef  /apex/com.android.runtime/lib/bionic/libc.so (__system_property_set+146)
01-14 00:21:43.566026   321   460 D dumpstack: #02 pc 00093527  /vendor/lib/hw/audio.primary.amlogic.so (mainThreadFunc+5702)
01-14 00:21:43.566071   321   460 D dumpstack: #03 pc 000809f3  /apex/com.android.runtime/lib/bionic/libc.so (__pthread_start(void*)+40)
01-14 00:21:43.566095   321   460 D dumpstack: #04 pc 00039dc3  /apex/com.android.runtime/lib/bionic/libc.so (__start_thread+30)
avatar
文章
阅读
粉丝
相关推荐
一次 Rancher 内存占用过高问题排查
3.2k阅读
 · 
14点赞
console 内存占用的误解
1.6k阅读
 · 
11点赞
记录一次解决Android 高CPU占用率的问题
2.1k阅读
 · 
20点赞
一次Java内存占用高的排查案例，解释了我对内存问题的所有疑问
5.3k阅读
 · 
73点赞
electron资源cpu/memory占用过高的处理思路
3.1k阅读
 · 
12点赞
ps vs top：CPU占用率统计的两种不同方式
3.8k阅读
 · 
1点赞
2023年的现代安卓开发
34k阅读
 · 
462点赞
golang pprof 监控系列(5) —— cpu 占用率 统计原理
2.4k阅读
 · 
4点赞
SwiftUI + Core Data App 的内存占用优化之旅
5.4k阅读
 · 
24点赞
“堆内存持续占用高 且 ygc回收效果不佳” 排查处理实践
1.3k阅读
 · 
46点赞

友情链接：