基础：如何找出狂打日志的“内鬼”.

系统管理员 2022-09-17 04:26 103阅读 0赞

## 准备 ##

*  机器配置：2 CPU，8GB 内存
 *  预先安装 docker、sysstat 等⼯具，如 apt install docker.io sysstat

## 操作 ##

⾸先，我们在终端中执⾏下⾯的命令，运⾏今天的⽬标应⽤：

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

然后，在终端中运⾏ ps 命令，确认案例应⽤正常启动。如果操作⽆误，你应该可以在 ps 的输出中，看到⼀个 app.py 的进程：

$ ps -ef | grep /app.py
    root 18940 18921 73 14:41 pts/0 00:00:02 python /app.py

接着，我们来看看系统有没有性能问题。要观察哪些性能指标呢？前⾯⽂章中，我们知道 CPU、内存和磁盘 I/O 等系统资源，很容易出现资源瓶颈，这就是我们观察的⽅向了。我们来观察⼀下这些资源的使⽤情况。

当然，动⼿之前你应该想清楚，要⽤哪些⼯具来做，以及⼯具的使⽤顺序⼜是怎样的

我们可以先⽤ top ，来观察 CPU 和内存的使⽤情况；然后再⽤ iostat ，来观察磁盘的 I/O 情况。

# 按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

*  观察top的输出，可以发现，CPU0的使用率非常高，它的系统CPU使用率(sys%)为6%，而iowait超过了90%，这说明CPU0上，可能正在运行着IO密集型的进程。不过，究竟是什么原因呢？这个疑问先保留着，我们先继续看完。
 *  接着我们来看，进程部分的CPU使用情况。你会发现，python进程的CPU使用率已经达到了6%，而其他进程的CPU使用率都比较低，不超过0.3%。看起来python是个可疑进程。记下 python 进程的 PID 号 18940，我们稍后分析。
 *  最后再来看内存的使用情况，总内存8G，剩余内存只有730MB，而Buffer/Cache占用内存高达6GB之多，这说明内存主要被缓存占用。虽然大部分缓存可以回收，但是我们还得了解下缓存的去处，确认缓存的使用都是合理的

到这一步，基本上可以判断出，CPU使用率中的iowait是一个潜在瓶颈，而内存部分的缓存占比较大，那磁盘IO又是什么样的情况呢？

我们在终端中按 Ctrl+C ，停⽌ top 命令，再运⾏ iostat 命令，观察 I/O 的使⽤情况：

# -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 5

*  观察 iostat 的最后⼀列，你会看到，磁盘 sda 的 I/O 使⽤率已经⾼达 99%，很可能已经接近 I/O 饱和。
 *  再看前⾯的各个指标，每秒写磁盘请求数是 64 ，写⼤⼩是 32 MB，写请求的响应时间为 7 秒，⽽请求队列⻓度则达到了1100。

超慢的响应时间和特⻓的请求队列⻓度，进⼀步验证了 I/O 已经饱和的猜想。此时，sda 磁盘已经遇到了严重的性能瓶颈。

到这⾥，也就可以理解，为什么前⾯看到的 iowait ⾼达 90% 了，这正是磁盘 sda 的 I/O 瓶颈导致的。接下来的重点就是分析I/O 性能瓶颈的根源了。那要怎么知道，这些 I/O请求相关的进程呢？

使⽤ pidstat 加上 -d 参数，就可以显示每个进程的 I/O 情况。所以，你可以在终端中运⾏如下命令来观察：  
![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_20_color_FFFFFF_t_70_g_se_x_16]

*  从pidstat的输出可以发现，只有python进程的写比较大，而且每秒写的数据超过了45MB，比上面iostat发现的32MB的结果还要打。很明显，正是python进程到来了IO瓶颈
 *  再往下看 iodelay 项。虽然只有 python 在⼤量写数据，但你应该注意到了，有两个进程 （kworker 和 jbd2 ）的延迟，居然⽐python 进程还⼤很多。
    
     *  其中，kworker 是⼀个内核线程，⽽ jbd2 是 ext4 ⽂件系统中，⽤来保证数据完整性的内核线程
     *  他们都是保证文件系统基本功能的内核线程，其延迟的根源还是大量IO

综合pidstat的输出来看，还是python进程的嫌疑最⼤。接下来，我们来分析 python 进程到底在写什么。

⾸先留意⼀下 python 进程的 PID 号， 18940。看到 18940 ，你有没有觉得熟悉？其实前⾯在使⽤top时，我们记录过的 CPU

使⽤率最⾼的进程，也正是它。不过，虽然在top中使⽤率最⾼，也不过是 6%，并不算⾼。所以，以I/O问题为分析⽅向还是正确的。

知道了进程的 PID 号，具体要怎么查看写的情况呢？

读写⽂件必须通过系统调⽤完成。观察系统调⽤情况，就可以知道进程正在写的⽂件。而 strace 正是我们分析系统调⽤时最常⽤的⼯具。  
![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_20_color_FFFFFF_t_70_g_se_x_16 1]

*  从write()系统调用上，我们可以看到，进程向文件描述符编号为3的文件中，写入了300MB的数据。看来，它应该是我们要找的文件。不过，write()调用中只能看到文件的描述符编号，文件名和路径还是未知的
 *  再观察后⾯的 stat() 调⽤，你可以看到，它正在获取 /tmp/logtest.txt.1 的状态。 这种“点+数字格式”的⽂件，在⽇志回滚中⾮常常⻅。我们可以猜测，这是第⼀个⽇志回滚⽂件，⽽正在写的⽇志⽂件路径，则是/tmp/logtest.txt。

当然，这只是我们的猜测，⾃然还需要验证。我们可以使用工具lsof验证。lsof是专门用来查看进程打开文件列表，不过，这里的“文“ 不只有普通文件，还包括了目录、块设备、动态库、网络套接字等

接下来，我们在终端中运⾏下⾯的 lsof 命令，看看进程 18940 都打开了哪些⽂件：

$ 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

*  这个输出界⾯中，FD 表示⽂件描述符号，TYPE 表示⽂件类型，NAME 表示⽂件路径。这也是我们需要关注的重点。
 *  再看最后⼀⾏，这说明，这个进程打开了⽂件 /tmp/logtest.txt，并且它的⽂件描述符是 3 号，⽽3 后⾯的 w ，表示以写的⽅式打开。

这跟刚才 strace 完我们猜测的结果⼀致，看来这就是问题的根源：进程 18940 以每次 300MB 的速度，在“疯狂”写⽇志，⽽⽇志⽂件的路径是 /tmp/logtest.txt。

既然找出了问题根源，接下来按照惯例，就该查看源代码，然后分析为什么这个进程会狂打⽇志了。

以运⾏ docker cp 命令，把案例应⽤的源代码拷⻉出来，然后查看它的内容。

#拷⻉案例应⽤源代码到当前⽬录
    $ docker cp app:/app.py .
    #查看案例应⽤的源代码
    $ cat app.py
    logger = logging.getLogger(__name__)
    logger.setLevel(level=logging.INFO)
    rHandler = RotatingFileHandler("/tmp/logtest.txt", maxBytes=1024 * 1024 * 1024, backupCount=1)
    rHandler.setLevel(logging.INFO)
    
    def write_log(size):
    	'''Write logs to file'''
    	message = get_message(size)
    	while True:
    	logger.info(message)
    	time.sleep(0.1)
    	
    if __name__ == '__main__':
    	msg_size = 300 * 1024 * 1024
    	write_log(msg_size)

分析这个源码，我们发现，它的⽇志路径是 /tmp/logtest.txt，默认记录 INFO 级别以上的所有⽇志，⽽且每次写⽇志的⼤⼩是300MB。这跟我们上⾯的分析结果是⼀致的。

⼀般来说，⽣产系统的应⽤程序，应该有动态调整⽇志级别的功能。继续查看源码，你会发现，这个程序也可以调整⽇志级别。如果你给它发送 SIGUSR1 信号，就可以把⽇志调整为 INFO 级；发送 SIGUSR2 信号，则会调整为 WARNING 级：

def set_logging_info(signal_num, frame):
    '''Set loging level to INFO when receives SIGUSR1'''
    	logger.setLevel(logging.INFO)
    
    def set_logging_warning(signal_num, frame):
    '''Set loging level to WARNING when receives SIGUSR2'''
    	logger.setLevel(logging.WARNING)
    
    signal.signal(signal.SIGUSR1, set_logging_info)
    signal.signal(signal.SIGUSR2, set_logging_warning)

根据源码中的⽇志调⽤ logger. info(message) ，我们知道，它的⽇志是 INFO 级，这也正是它的默认级别。那么，只要把默认级别调⾼到 WARNING 级，⽇志问题应该就解决了。

接下来，我们就来检查⼀下，刚刚的分析对不对。在终端中运⾏下⾯的 kill 命令，给进程 18940 发送 SIGUSR2 信号：

$ kill -SIGUSR2 18940

然后，再执⾏ top 和 iostat 观察⼀下：

$ top
    ...
    %Cpu(s): 0.3 us, 0.2 sy, 0.0 ni, 99.5 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st

$ 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
    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 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0

观察top 和 iostat 的输出，你会发现，稍等⼀段时间后，iowait 会变成 0，⽽ sda 磁盘的 I/O 使⽤率也会逐渐减少到 0。

到这⾥，我们不仅定位了狂打⽇志的应⽤程序，并通过调⾼⽇志级别的⽅法，完美解决了 I/O 的性能瓶颈。

案例最后，当然不要忘了运⾏下⾯的命令，停⽌案例应⽤：

$ docker rm -f app

## 小结 ##

⽇志，是了解应⽤程序内部运⾏情况，最常⽤、也最有效的⼯具。⽆论是操作系统，还是应⽤程序，都会记录⼤量的运⾏⽇志，以便事后查看历史记录。这些⽇志⼀般按照不同级别来开启，⽐如，开发环境通常打开调试级别的⽇志，⽽线上环境则只记录警告和错误⽇志。

在排查应⽤程序问题时，我们可能需要，在线上环境临时开启应⽤程序的调试⽇志。有时候，事后⼀不⼩⼼就忘了调回去。没把线上的⽇志调⾼到警告级别，可能会导致 CPU 使⽤率、磁盘 I/O 等⼀系列的性能问题，严重时，甚⾄会影响到同⼀台服务器上运⾏的其他应⽤程序。

今后，在碰到这种“狂打⽇志”的场景时，你可以⽤ iostat、strace、lsof 等⼯具来定位狂打⽇志的进程，找出相应的⽇志⽂件，再通过应⽤程序的接⼝，调整⽇志级别来解决问题。

如果应⽤程序不能动态调整⽇志级别，你可能还需要修改应⽤的配置，并重启应⽤让配置⽣效。

[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_20_color_FFFFFF_t_70_g_se_x_16]: /images/20220828/997bde9f7370422e857330a5fc367709.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_20_color_FFFFFF_t_70_g_se_x_16 1]: /images/20220828/d8fcaf92f8ab4ca39375f40ec1923ee0.png