系统优化-IO-写log引起的问题IO问题

Posted on | Edited on | In ,

以下场景是一个典型的由于写log导致IO问题的场景。

注：我的测试环境是1c2g内存的虚拟机，所以无法模拟案例，案例的需求是2c8g，所以这里只罗列除了排查思路。

准备工作

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

启动后发现系统响应变慢

1
2
3
4
5
6
7
8
9
10
11
12
# 按1切换到每个CPU的使用情况
$ top
top - 14:43:43 up 1 day,  1:39,  2 users,  load average: 2.48, 1.09, 0.63
Tasks: 130 total,   2 running,  74 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.7 us,  6.0 sy,  0.0 ni,  0.7 id, 92.7 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  0.0 us,  0.3 sy,  0.0 ni, 92.3 id,  7.3 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  8169308 total,   747684 free,   741336 used,  6680288 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  7113124 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
18940 root      20   0  656108 355740   5236 R   6.3  4.4   0:12.56 python
1312 root      20   0  236532  24116   9648 S   0.3  0.3   9:29.80 python3
  1. cpu0 的wa已经到了92.7
  2. pyhton占了6.3的是你用率

  3. 内存的buff/cache占了6个g

    综上觉得是io的问题，pyhton这个进程导致的，内存的占用有可能是因为大量的io读写文件导致的

    用iostat查看下io的情况

1
2
3
4
5
6
# -d表示显示I/O性能指标，-x表示显示扩展统计（即所有I/O指标）
$ iostat -x -d 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
loop0            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   0.00   0.00
sdb              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   0.00   0.00
sda              0.00   64.00      0.00  32768.00     0.00     0.00   0.00   0.00    0.00 7270.44 1102.18     0.00   512.00  15.50  99.20

系统sda的写到了32mb每秒，w_waite到了7s，私用率几乎100%，进一步印证了才想

下面我们该用pidstat查看具体时间那个进程导致的了，这里看到是18904-python导致的

1
2
3
4
5
6
7
8
9
$ pidstat -d 1

15:08:35      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
15:08:36        0     18940      0.00  45816.00      0.00      96  python

15:08:36      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
15:08:37        0       354      0.00      0.00      0.00     350  jbd2/sda1-8
15:08:37        0     18940      0.00  46000.00      0.00      96  python
15:08:37        0     20065      0.00      0.00      0.00    1503  kworker/u4:2

strace -p pid来查看源码，发现程序会给句柄为3的文件写入300mb的数据，stat(“/tmp/logtest.txt.1”，找到了文件所在

1
2
3
4
5
6
7
8
9
10
11
12
$ strace -p 18940
strace: Process 18940 attached
...
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0f7aee9000
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0f682e8000
write(3, "2018-12-05 15:23:01,709 - __main"..., 314572844
) = 314572844
munmap(0x7f0f682e8000, 314576896)       = 0
write(3, "\n", 1)                       = 1
munmap(0x7f0f7aee9000, 314576896)       = 0
close(3)                                = 0
stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0

我们可以用lsof -p进一步印证是哪些文件

1
2
3
4
5
6
7
8

$ lsof -p 18940
COMMAND   PID USER   FD   TYPE DEVICE  SIZE/OFF    NODE NAME
python  18940 root  cwd    DIR   0,50      4096 1549389 /
python  18940 root  rtd    DIR   0,50      4096 1549389 /
…
python  18940 root    2u   CHR  136,0       0t0       3 /dev/pts/0
python  18940 root    3w   REG    8,1 117944320     303 /tmp/logtest.txt