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

# ps -ef | grep /app.py // 确认案例应用正常启动
root     23054 23036 45 08:30 pts/0    00:00:02 python /app.py
root     23089 20643  0 08:30 pts/0    00:00:00 grep --color=auto /app.py

# top
top - 08:32:22 up 56 days, 22:49,  1 user,  load average: 3.57, 1.70, 0.89
Tasks: 196 total,   2 running, 194 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.7 us,  1.3 sy,  0.0 ni,  0.0 id, 97.7 wa,  0.0 hi,  0.3 si,  0.0 st
%Cpu1  : 17.9 us, 78.8 sy,  0.0 ni,  3.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu2  :  1.0 us,  0.3 sy,  0.0 ni, 97.0 id,  1.7 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu3  :  2.0 us,  0.3 sy,  0.0 ni, 97.3 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
MiB Mem : 11854.82+total, 1368.898 free, 1653.500 used, 8832.430 buff/cache
MiB Swap:    0.000 total,    0.000 free,    0.000 used. 9793.617 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
23054 root      20   0 1040092 644228   3304 R  96.7  5.3   1:25.50 python /app.py
 7294 apache    20   0  369372  30468   4136 S   2.0  0.3 102:08.77 php-fpm: pool www
...

// %Cpu1 的使用率非常高，sy 78.8；%Cpu0 wa 97.7 => 此时可能正在进行 I/O 密集的进程
// Buffer/Cache 占用内存高达 8GB 之多，通过 /proc/meminfo 可以看到系统的 buffer 和 cache 各占多少
// 从进程中，我们可以看到 PID 23054 python /app.py %CPU 96.7

# iostat -x -d 1 // -d 表示显示I/O性能指标，-x 表示显示扩展统计（即所有I/O指标）
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00   82.00     0.00 41984.00  1024.00   143.55  642.94    0.00  642.94  12.20 100.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

// 磁盘 sda 的 I/O 使用率已经高达 100%，很可能已经接近 I/O 饱和。
// 每秒写磁盘请求数是 82.00 ，写大小是 41 MB，写请求的响应时间为 6 秒，而请求队列长度则达到了 143。

// 超慢的响应时间和特长的请求队列长度，进一步验证了 I/O 已经饱和的猜想

# pidstat -d 1

// 从 pidstat 的输出，可以发现只有 python 进程的写比较大

// 往下看 iodelay 项。虽然只有 python 在大量写数据，但有两个进程 （kworker 和 jbd2 ）的延迟，居然比 python 进程还大很多。
// kworker 是一个内核线程，而 jbd2 是 ext4 文件系统中用来保证数据完整性的内核线程。
// 他们都是保证文件系统基本功能的内核线程，所以具体细节暂时就不用管了，我们只需要明白，它们延迟的根源还是大量 I/O。

# strace -p 23054
...
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f40204b1000
write(3, "2020-08-11 01:28:41,353 - __main"..., 314572844) = 314572844
munmap(0x7f40204b1000, 314576896)       = 0
...
lseek(3, 0, SEEK_CUR)                   = 943718535
munmap(0x7f401b9b1000, 314576896)       = 0
close(3)                                = 0
stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0
...

// 进程向文件描述符编号为 3，写入 300MB 的数据
// 再观察后面的 stat() 调用，你可以看到，它正在获取 /tmp/logtest.txt.1 的状态，
// 类似与日志论转格式的文件名，那么日志文件可能是 /tmp/logtest.txt

# lsof -p 23054
COMMAND   PID USER   FD   TYPE DEVICE  SIZE/OFF      NODE NAME
python  28500 root  cwd    DIR   0,36        17  65749020 /
...
python  28500 root    2u   CHR  136,0       0t0         3 /dev/pts/0
python  28500 root    3w   REG  253,0 943718535   4341230 /tmp/logtest.txt

// FD 表示文件描述符号，TYPE 表示文件类型，NAME 表示文件路径
// 最后一行说明这个进程打开了文件 /tmp/logtest.txt，并且它的文件描述符是 3 号，而 3 后面的 w ，表示以写的方式打开。