MTK 平台I/O 太高导致卡主例子

卡住位置

 

两次卡住位置不一样

 

 

SYS_BLOCKIO

wt:speed,size,time      写I/O信息       wl 写I/O负载比

wt:1743,14209024,7958.wl:90%

 

rt:speed,size,time       读I/O速度

 

mmc.q:0 => eMMC， mmc.q:1 => T-Card，ufs.q:0 => UFS

 

pid:296,{08477:00000:00000000:00020:00081920}  => wcnt wlen rcnt rlen

 

这个卡IO问题是由于pid 5922(cp--与obb数据迁移相关)大量写4K写引起的（每0.5s有2000-4000次）

 

Android Log:

64% TOTAL: 13% user + 7.2% kernel + 43% iowait + 0% softirq

Kernel Log:

sync、delay、iowait

 

 

[  490.657973] (6)[1508:watchdog]cp              D    0  5922   5914 0x00000000

[  490.657977] (6)[1508:watchdog]Call trace:

[  490.657980] (6)[1508:watchdog][<ffffff8a46086610>] __switch_to+0x128/0x144

[  490.657984] (6)[1508:watchdog][<ffffff8a46f5b3c8>] __schedule+0xde8/0x10b4

[  490.657987] (6)[1508:watchdog][<ffffff8a46f5bcd0>] io_schedule+0x90/0xc0

[  490.657993] (6)[1508:watchdog][<ffffff8a461f96b4>] wait_on_page_bit_killable+0x17c/0x21c

[  490.657996] (6)[1508:watchdog][<ffffff8a461fb054>] generic_file_read_iter+0x1a8/0x8d4

[  490.657999] (6)[1508:watchdog][<ffffff8a4631cc08>] ext4_file_read_iter+0x2c/0x44

[  490.658002] (6)[1508:watchdog][<ffffff8a46269e00>] __vfs_read+0xe4/0x12c

[  490.658005] (6)[1508:watchdog][<ffffff8a46269f90>] vfs_read+0xa0/0x138

[  490.658007] (6)[1508:watchdog][<ffffff8a4626a534>] SyS_read+0x6c/0xcc

[  490.658009] (6)[1508:watchdog][<ffffff8a4609fd18>] oppo_root_check+0x20/0xf0

 

 

u:r:installd:s0                root           813   813     1  156908   6940 binder_ioctl_write_read 0    efg  S 19 0     -   0  fg   6 installd                    Binder:813_2

u:r:installd:s0                root           813   842     1  156908   6940 binder_ioctl_write_read 0    efg  S 19 0     -   0  fg   6 installd                    Binder:813_1

u:r:installd:s0                root           813  1572     1  156908   6940 binder_ioctl_write_read 0    efg  S 19 0     -   0  fg   5 installd                    Binder:813_3

u:r:installd:s0                root           813  1574     1  156908   6940 binder_ioctl_write_read 0    efg  S 19 0     -   0  fg   5 installd                    Binder:813_4

u:r:installd:s0                root           813  1575     1  156908   6940 binder_ioctl_write_read 0    efg  S 19 0     -   0  fg   6 installd                    Binder:813_5

u:r:installd:s0                root           813  1628     1  156908   6940 binder_ioctl_write_read 0    efg  S 19 0     -   0  fg   5 installd                    Binder:813_6

u:r:installd:s0                root           813  5850     1  156908   6940 binder_ioctl_write_read 0    efg  S 19 0     -   0  fg   4 installd                    Binder:813_7

u:r:installd:s0                root           813  5851     1  156908   6940 do_wait             0    efg  S  19   0      -   0  fg   5 installd  

 

 

 

 

SYS_PROCESSES_AND_THREADS

LABEL                          USER           PID   TID  PPID     VSZ    RSS WCHAN            ADDR FRZ  S PRI  NI RTPRIO SCH PCY CPU NAME   

u:r:migrate_legacy_obb_data:s0 root          5922  5922  5914   29964   3196 wait_on_page_bit_killable 0 efg  D 19 0   -   0  fg   1 cp                          cp

 

 

 

[312994.710097]ufs.q:0.
rt:124000,253952,2.  //rspeed   
wt:15651,2211840,138.//wspeed 15651 kb/s,wsize 2211840b=2160kb,time
wl:3%,36906462,1135295310,210. //负载率 3% = duty/时间,duty 36906462 ,时间1135295310 ， 请求次数 210
vm:2308044,1148,458841756,0,1231105496,88256953. //"FilePages(fp)"    "FileDirty(fd)"    "NumDirtied(nd)"    "WriteBack(wb)"    "NumWritten(nw)"    "FileMapFault(fmflt)"

cpu:67488409,7887795,34797224,16628534,189012,3432828,1599029. //user    nice    system    idle    iowait    irq    softirq

pid:0,{00549:00261:01069056:00000:00000000} // ppid 0,pid 00549 ,wcnt 261,wsize 01069056b=1044K,rcnt 0,rsize 0b   ;这里可以根据wsize 跟 wspeed 算出花的时间，跟据wsize 和wcnt 算出每次写数据大小
{04268:00007:00028672:00000:00000000}// ppid 0,pid 04268
{14986:00003:00012288:00000:00000000}{04088:00000:00000000:00060:00245760}{22422:00038:00155648:00000:00000000}{10162:00000:00000000:00001:00004096}{02680:00001:00004096:00001:00004096}{07556:00008:00032768:00000:00000000}{14339:00001:00004096:00000:00000000}{30375:00066:00270336:00000:00000000}{27586:00003:00012288:00000:00000000}{14208:00002:00008192:00000:00000000}{26722:00002:00008192:00000:00000000}{26724:00001:00004096:00000:00000000}{01879:00002:00008192:00000:00000000}{01554:00004:00016384:00000:00000000}{04255:00001:00004096:00000:00000000}{04257:00001:00004096:00000:00000000}{12378:00058:00237568:00000:00000000}{11514:00006:00024576:00000:00000000}{11495:00039:00159744:00000:00000000}{04259:00001:00004096:00000:00000000}{31169:00002:00008192:00000:00000000}{09028:00001:00004096:00000:00000000}{09030:00002:00008192:00000:00000000}{03457:00001:00004096:00000:00000000}{16955:00002:00008192:00000:00000000}{25721:00002:00008192:00000:00000000}{13174:00005:00020480:00000:00000000}.