Android-io统计

Android Comments

年前遇到客户的板子 emmc 被写坏的问题，当时还没时间去研究分析，现在疫情在家就把之前遇到的问题慢慢研究一下。
emmc 是有一定使用寿命的，它的寿命跟擦写次数相关的。正常来说应该在５，６年以上。但这个客户才使用了半年多就坏了。怀疑是某个进程在疯狂的写入磁盘数据，导致擦写次数达到寿命期限。
下面介绍一些查看 emmc io　状态的工具方法。我们可以用这些工具方法来查看 emmc 是不是擦写寿命到了，找出到底是哪个应用把 emmc 写坏了。

1. emmc 擦写次数和判断 emmc 使用寿命是否到期方法

1.1 适用于大部分机芯：

在系统启动之后查看 emmc 擦写次数，串口打印信息输入命令如下：

1
cat /sys/kernel/debug/mmc0/mmc0:0001/ext_csd

执行命令后会出现一长串的数字，将这些数字拷贝到文本文档中，用文本编辑工具打开，然后查看第537-538位数字/字母（即268byte)。

对于这个数字的解释如下:

  • 如果此值是00，则表示这个机芯不支持这种方法来查询EMMC擦写次数。
  • 01-0A为正常的范围，其他数值都不正常。 这个数值只是百分比，不是明确次数。例如 0x01 表示使用了 0% - 10% 寿命，依次类推。
  • 如果此值是0B，则便是这颗EMMC的擦写次数已经超过最大擦写次数。这种情况EMMC的状态不稳定，可能就会出现开不了机的情况了。

1.2 适合Mstar机芯：

开机后一直按住电脑上的Enter键，进入 mboot，然后输入命令 mmc ecsd ，然后查看ecsd[268]的数值，例如ecsd[268]:0x1，表示擦写次数在10%以内。
方法2看到的数值和方法1是一致的。只是对于开机启动不了的机芯板来说，更加实用。

1.3 emmc 理论寿命与实际寿命验证

emmc 理论寿命可以从 emmc 厂家提供的规则书上获取。
我们在实际生产要使用某款 emmc 芯片的之前，都需要对 emmc 的寿命进行验证。一般板子的芯片方案商都会提供验证工具，验证方法。
本质上就是暴力写 emmc，看在暴力写入情况下，能写多久。这类实验，测试一次都要进行一两个月左右。

2. 查看系统整体的 io 状态

2.1 iostat

用法如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
KKHi3751V810:/ # busybox iostat --help                                         
BusyBox v1.26.2 (2020-02-10 02:26:18 UTC) multi-call binary.

Usage: iostat [-c] [-d] [-t] [-z] [-k|-m] [ALL|BLOCKDEV...] [INTERVAL [COUNT]]

Report CPU and I/O statistics

        -c      Show CPU utilization
        -d      Show device utilization
        -t      Print current time
        -z      Omit devices with no activity
        -k      Use kb/s
        -m      Use Mb/s
KKHi3751V810:/ #

比如说我们想查看当前系统的 io 状态，以 kb/s　作为单位:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
KKHi3751V810:/ # busybox iostat -d -k                                          
Linux 4.9.44_s5 (localhost)     02/11/20        _aarch64_       (4 CPU)

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
zram0             0.01         0.02         0.00        176          4
mmcblk0           5.21        35.64        47.65     299644     400596
mmcblk0p1         0.66         0.00         0.00          0          0
mmcblk0p7         0.00         0.00         0.01          0         48
mmcblk0p10        0.00         0.00         0.00         32          0
mmcblk0p16        0.01         0.05         0.01        402         60
mmcblk0p18        0.01         0.10         0.01        806         68
mmcblk0p20        0.24        15.19         0.11     127717        928
mmcblk0p21        0.02         1.00         0.00       8421          0
mmcblk0p22        0.00         0.02         0.00        130         12
mmcblk0p23        0.00         0.04         0.01        362         44
mmcblk0p25        4.28        19.24        47.51     161774     399436
sda               0.03         1.37         0.00      11546          0

KKHi3751V810:/ #

其中 mmcblk0 代码整个 emmc，　mmcblk0pxx　代表某个分区，　可以通过以下方法来查找对应的分区：

1
2
3
4
5
6
7
8
9
ls -l /dev/block/platform/soc/f9830000.emmc/by-name/                           <
...
lrwxrwxrwx 1 root root 21 1970-01-01 08:00 system -> /dev/block/mmcblk0p20
lrwxrwxrwx 1 root root 20 1970-01-01 08:00 tconparam -> /dev/block/mmcblk0p8
lrwxrwxrwx 1 root root 20 1970-01-01 08:00 trustedcore -> /dev/block/mmcblk0p9
lrwxrwxrwx 1 root root 21 1970-01-01 08:00 userdata -> /dev/block/mmcblk0p25
lrwxrwxrwx 1 root root 21 1970-01-01 08:00 vendor -> /dev/block/mmcblk0p21
lrwxrwxrwx 1 root root 21 1970-01-01 08:00 versioninfo -> /dev/block/mmcblk0p11
KKHi3751V810:/ #

我们看到　mmcblk0p25　对应的是 userdata 分区。
综合以上知道当前系统只有 userdata　有写入，　写入速度为 47 KB/s。

2.2 iotop

iostat　只能查看系统的整体 io　状态，当 io 状态异常高时，　不能定位是哪个进程引起的问题，　这时我们可以使用 iotop 这个工具来查看每个进程的 io 占用比例。
使用方法如下：

1
2
3
4
5
6
7
8
9
10
11
KKHi3751V810:/ # iotop --help
Usage: iotop [-h] [-P] [-d <delay>] [-n <cycles>] [-s <column>]
   -a  Show byte count instead of rate
   -d  Set the delay between refreshes in seconds.
   -h  Display this help screen.
   -m  Set the number of processes or threads to show
   -n  Set the number of refreshes before exiting.
   -P  Show processes instead of the default threads.
   -s  Set the column to sort by:
       pid, read, write, total, io, swap, sched, mem or delay.
KKHi3751V810:/ #

比如我们查看前10个io占用最大的进程，就可以使用以下方法：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
130|KKHi3751V810:/ # iotop -m 10 -P -s write                                   
                          --- IO (KiB/s) ---  ----------- delayed on ----------
   PID Command            read  write  total  IO     swap   sched  mem    total
 25227 :filedownloader       0   7208   7208  0.00%  0.00%  0.00%  0.00%  0.00%
 24323 logcat                0     12     12  0.00%  0.00%  0.00%  0.00%  0.00%
     1 init                  0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
     2 kthreadd              0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
     3 ksoftirqd/0           0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
     5 kworker/0:0H          0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
     7 rcu_preempt           0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
     8 rcu_sched             0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
     9 rcu_bh                0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
    10 migration/0           0      0      0  0.00%  0.00%  0.00%  0.00%  0.00%
       TOTAL                 0   7220   7220                0     12     12

从结果可以看到　25227 :filedownloader　这个进程 io 占用最高，写入速度为 7208KB/s。因为这时我正在下载文件。

3. 查看某个进程的 io 总量

iotop　只可以查看某个时间点的 io 速率，　我们需要统计某个进程总共的 io 总量时就得使用　cat /proc/$pid/io 这个方法了。

1
2
3
4
5
6
7
8
9
KKHi3751V810:/proc/25227 # cat io
rchar: 170665
wchar: 81578559
syscr: 555
syscw: 13095
read_bytes: 36864
write_bytes: 82153472
cancelled_write_bytes: 0
KKHi3751V810:/proc/25227 #

各字段的解析如下：
rchar: 170665 // 读出的总字节数，read()或者pread()中的长度参数总和(pagecache中统计而来，不代表实际磁盘的读入)
wchar: 81578559 // 写入的总字节数，write()或者pwrite()中的长度参数总和
syscr: 555 // read()或者pread()总的调用次数
syscw: 13095 // write()或者pwrite()总的调用次数
read_bytes: 36864 // 实际从磁盘中读取的字节总数
write_bytes: 82153472 // 实际写入到磁盘中的字节总数
cancelled_write_bytes: 0 // 由于截断pagecache导致应该发生而没有发生的写入字节数

实际写入磁盘的数据总量为　write_bytes: 82153472　字节。

4. 查看某个进程打开的文件

当我们发现某个进程的 io 异常时，想了解一下这个进程是在对哪个文件进行读写导致的，可以使用以下方法：

1
2
3
4
5
6
7
8
KKHi3751V810:/proc/24323/fd # ls -l
total 0
lrwx------ 1 root root 64 2020-02-11 12:50 0 -> /dev/pts/0
l-wx------ 1 root root 64 2020-02-11 12:50 1 -> /data/io.log
lrwx------ 1 root root 64 2020-02-11 12:50 12 -> socket:[9872]
lrwx------ 1 root root 64 2020-02-11 12:50 2 -> /dev/pts/0
lrwx------ 1 root root 64 2020-02-11 12:28 3 -> socket:[382495]
KKHi3751V810:/proc/24323/fd #

/proc/$pid/fd 目录下保存了这个进程打开的所有文件描述符。我们可以用 ls -l 来查看这些文件描述符指向的实际文件。这个例子中文件描述符 1 就表示文件　/data/io.log。
我们再通过 strace 来查看某个进程的系统调用，看看是不是一直在调用　write　接口写文件

1
2
3
4
5
6
7
8
9
10
11
12
13
KKHi3751V810:/proc/24323/fd # strace -p 24323                                  
strace: Process 24323 attached
recvfrom(3, "\204\0\34\0\302k\0\0\302k\0\0\3053B^\200\263}\34\0\0\0\0\0\0\0\0\4str"..., 5120, 0, NULL, NULL) = 160
write(1, "02-11 12:55:33.478 27586 27586 I"..., 167) = 167
recvfrom(3, "\264\0\34\0\302k\0\0\302k\0\0\3053B^@z\253\34\0\0\0\0\0\0\0\0\4str"..., 5120, 0, NULL, NULL) = 208
write(1, "02-11 12:55:33.481 27586 27586 I"..., 215) = 215
recvfrom(3, "\r\1\34\0\224\n\0\0\320\f\0\0\3063B^CS\303\22\3\0\0\0\350\3\0\0\5Con"..., 5120, 0, NULL, NULL) = 297
write(1, "02-11 12:55:34.314  2708  3280 W"..., 302) = 302
recvfrom(3, "r\0\34\0u\10\0\0\275\t\0\0\3063B^\354\253\327\22\3\0\0\0\350\3\0\0\3AMS"..., 5120, 0, NULL, NULL) = 142
write(1, "02-11 12:55:34.316  2165  2493 D"..., 152) = 152
recvfrom(3, "i\4\34\0u\10\0\0\275\t\0\0\3063B^\307`\350\22\0\0\0\0\350\3\0\0\5Pac"..., 5120, 0, NULL, NULL) = 1157
write(1, "02-11 12:55:34.317  2165  2493 W"..., 1749) = 1749
madvise(0x7a6ac2e000, 28672, MADV_DONTNEED) = 0

从以上 log 看，我们知道 24323 这个进程一直在往文件描述符 1 里面写内容，　而从 ls -l /proc/24323/fd 的结果中我们知道文件描述符 1 代表的是 /data/io.log　文件。
我们从 log 上还可以看出写入的部分内容和数据大小。

至此，所有的工具都介绍完啦，以后再遇到 io 的问题，我们就可以灵活运用这些工具来分析问题了。

秋少Android system developer