Linux I/O 性能分析思路

如何找出疯狂打日志的进程

启动案例应用

docker run -v /tmp:/tmp --name=app -itd feisky/logapp

用 top 命令观察cpu，内存等使用情况

top - 07:37:52 up 7 min,  1 user,  load average: 2.74, 1.27, 0.52
Tasks: 116 total,   2 running,  56 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3.6 us,  7.7 sy,  0.0 ni, 10.1 id, 78.6 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  3760660 total,   147584 free,  1160440 used,  2452636 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  2333960 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
11747 root      20   0  963312 934344   5320 D  24.9 24.8   0:36.05 python
   76 root      20   0       0      0      0 D   0.9  0.0   0:01.93 kworker/u4:2+fl
   67 root       0 -20       0      0      0 I   0.4  0.0   0:00.28 kworker/0:1H-kb

发现系统 iowait 快速比较高。并且内存大部分被buff/cache占用。

继续用 iostat 观察磁盘 io 情况

# -d表示显示I/O性能指标，-x表示显示扩展统计（即所有I/O指标）
iostat -x -d 1
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
vda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
vdb               0.00     0.00    0.00  260.00     0.00 116856.00   898.89   107.16  412.65    0.00  412.65   3.84  99.90

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
vda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
vdb               0.00     0.00    0.00  236.00     0.00 118256.00  1002.17   128.66  545.65    0.00  545.65   4.24 100.00

发现磁盘 sdb 使用率已经达到接近100%。

继续用 pidstat 观察进程的 io 占用情况

# pidstat 加上 -d 参数，就可以显示每个进程的 I/O 情况
pidstat -d 1
07:40:11 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
07:40:12 AM     0     11747      0.00  72672.00      0.00  python

07:40:13 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
07:40:14 AM     0     11166      0.00     28.00      0.00  jbd2/vdb-8
07:40:14 AM     0     11747      0.00 176160.00      0.00  python
07:40:14 AM     0     13266      0.00      4.00      0.00  sap1002

可以发现，我们找到了占用内存比较高的进程，应该是这里的 python 程序。

用 strace 追踪具体的进程。

strace -p 11747
strace: Process 11747 attached
munmap(0x7fcfcbbde000, 314576896)       = 0
write(3, "\n", 1)                       = 1
munmap(0x7fcfde7df000, 314576896)       = 0
select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=100000}) = 0 (Timeout)
getpid()                                = 1
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfde7df000
mmap(NULL, 393220096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfc70de000
mremap(0x7fcfc70de000, 393220096, 314576896, MREMAP_MAYMOVE) = 0x7fcfc70de000
munmap(0x7fcfde7df000, 314576896)       = 0
lseek(3, 0, SEEK_END)                   = 629145690
lseek(3, 0, SEEK_CUR)                   = 629145690
munmap(0x7fcfc70de000, 314576896)       = 0
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfde7df000
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfcbbde000
write(3, "2024-01-29 23:42:44,016 - __main"..., 314572844) = 314572844
munmap(0x7fcfcbbde000, 314576896)       = 0
write(3, "\n", 1)                       = 1
munmap(0x7fcfde7df000, 314576896)       = 0
select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=100000}) = 0 (Timeout)
getpid()                                = 1
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfde7df000
mmap(NULL, 393220096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfc70de000
mremap(0x7fcfc70de000, 393220096, 314576896, MREMAP_MAYMOVE) = 0x7fcfc70de000
munmap(0x7fcfde7df000, 314576896)       = 0
lseek(3, 0, SEEK_END)                   = 943718535
lseek(3, 0, SEEK_CUR)                   = 943718535
munmap(0x7fcfc70de000, 314576896)       = 0
close(3)                                = 0
stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0
unlink("/tmp/logtest.txt.1")            = 0
stat("/tmp/logtest.txt", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0
rename("/tmp/logtest.txt", "/tmp/logtest.txt.1") = 0
open("/tmp/logtest.txt", O_WRONLY|O_CREAT|O_APPEND|O_CLOEXEC, 0666) = 3
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
lseek(3, 0, SEEK_END)                   = 0

从 write() 系统调用上，我们可以看到，进程向文件描述符编号为 3 的文件中，写入了 300MB 的数据。看到一个日志文件路径/tmp/logtest.txt.1，可以猜测，这是一个日志回滚文件，而正在写的日志文件路径，则是 /tmp/logtest.txt。

可以继续用 lsof 查看这个进程打开了哪些文件。

lsof -p 11747
COMMAND   PID USER   FD   TYPE DEVICE  SIZE/OFF   NODE NAME
python  11747 root  cwd    DIR   0,47      4096 661078 /
python  11747 root  rtd    DIR   0,47      4096 661078 /
python  11747 root    2u   CHR  136,0       0t0      3 /dev/pts/0
python  11747 root    3w   REG 253,16 244989952     14 /tmp/logtest.txt

至此，我们已经确认进程 11747 以每次 300MB 的速度，在“疯狂”写日志，而日志文件的路径是 /tmp/logtest.txt。

SQL查询磁盘性能分析

使用 top 命令查看服务器的负载

top
top - 12:02:15 up 6 days,  8:05,  1 user,  load average: 0.66, 0.72, 0.59
Tasks: 137 total,   1 running,  81 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.7 us,  1.3 sy,  0.0 ni, 35.9 id, 62.1 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  0.3 us,  0.7 sy,  0.0 ni, 84.7 id, 14.3 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  8169300 total,  7238472 free,   546132 used,   384696 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  7316952 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
27458 999       20   0  833852  57968  13176 S   1.7  0.7   0:12.40 mysqld

可以看到 cpu0 的 iowait 比较高

查看磁盘使用情况

$ iostat -d -x 1
Device            r/s     w/s     rkB/s     wkB/s   rrqm/s   wrqm/s  %rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz  svctm  %util
...
sda            273.00    0.00  32568.00      0.00     0.00     0.00   0.00   0.00    7.90    0.00   1.16   119.30     0.00   3.56  97.20

可以看到，磁盘 sda 有大量的读操作，并且使用率也几乎打满。

使用 pidstat 查看具体进程的 io 使用情况

pidstat -d 1
12:04:11      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
12:04:12      999     27458  32640.00      0.00      0.00       0  mysqld
12:04:12        0     27617      4.00      4.00      0.00       3  python
12:04:12        0     27864      0.00      4.00      0.00       0  systemd-journal

定位到了 mysqld 进程。

使用 strace 命令定位 mysql 进程的数据读取情况，加上-f 参数

strace -f -p 27458
[pid 28014] read(38, "934EiwT363aak7VtqF1mHGa4LL4Dhbks"..., 131072) = 131072
[pid 28014] read(38, "hSs7KBDepBqA6m4ce6i6iUfFTeG9Ot9z"..., 20480) = 20480
[pid 28014] read(38, "NRhRjCSsLLBjTfdqiBRLvN9K6FRfqqLm"..., 131072) = 131072
[pid 28014] read(38, "AKgsik4BilLb7y6OkwQUjjqGeCTQTaRl"..., 24576) = 24576
[pid 28014] read(38, "hFMHx7FzUSqfFI22fQxWCpSnDmRjamaW"..., 131072) = 131072
[pid 28014] read(38, "ajUzLmKqivcDJSkiw7QWf2ETLgvQIpfC"..., 20480) = 20480

可以看到，mysql 进程有大量线程在大量读取。

使用 lsof 查看具体是打开了哪些文件

 lsof -p 27458
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
...
mysqld  27458      999   38u   REG    8,1 512440000 2601895 /var/lib/mysql/test/products.MYD

可以看到正在读的是 mysql 数据文件。

mysql> show full processlist;
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| Id | User | Host            | db   | Command | Time | State        | Info                                                |
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| 27 | root | localhost       | test | Query   |    0 | init         | show full processlist                               |
| 28 | root | 127.0.0.1:42262 | test | Query   |    1 | Sending data | select * from products where productName='geektime' |
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
2 rows in set (0.00 sec)

使用 explain 语句分析有问题的 sql

# 切换到test库
mysql> use test;
# 执行explain命令
mysql> explain select * from products where productName='geektime';
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
| id | select_type | table    | type | possible_keys | key  | key_len | ref  | rows  | Extra       |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
|  1 | SIMPLE      | products | ALL  | NULL          | NULL | NULL    | NULL | 10000 | Using where |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
1 row in set (0.00 sec)

其中，有几个比较重要的字段需要注意

select_type 表示查询类型，而这里的 SIMPLE 表示此查询不包括 UNION 查询或者子查询；
table 表示数据表的名字，这里是 products；
type 表示查询类型，这里的 ALL 表示全表查询，但索引查询应该是 index 类型才对；
possible_keys 表示可能选用的索引，这里是 NULL；
key 表示确切会使用的索引，这里也是 NULL；
rows 表示查询扫描的行数，这里是 10000。
根据结果，我们可以确定，这条查询语句压根儿没有使用索引，所以查询时，会扫描全表，并且扫描行数高达 10000 行。响应速度肯定会很慢。

优化方法：给productName字段添加 index 即可。

mysql> CREATE INDEX products_index ON products (productName(64));
Query OK, 10000 rows affected (14.45 sec)
Records: 10000  Duplicates: 0  Warnings: 0

最后编辑于：2024.02.02 08:43:06

©著作权归作者所有,转载或内容合作请联系作者
【社区内容提示】社区部分内容疑似由AI辅助生成，浏览时请结合常识与多方信息审慎甄别。
平台声明：文章内容（如有图片或视频亦包括在内）由作者上传并发布，文章内容仅代表作者本人观点，简书系信息发布平台，仅提供信息存储服务。

Linux I/O 性能分析思路

Linux I/O 性能分析思路

如何找出疯狂打日志的进程

SQL查询磁盘性能分析

相关阅读更多精彩内容

友情链接更多精彩内容