26-案例篇：如何找出狂打日志的内鬼？

案例

环境准备

# 机器配置：2cpu，4GB内存
# 预先安装docker、sysstat包

在终端中执行下面的命令

# 执行案例进程启动命令
[root@local_sa_192-168-1-6 ~]# docker run -v /tmp:/tmp --name=app -itd feisky/logapp

# 查看案例进程是否启动
[root@local_sa_192-168-1-6 ~]# ps -ef | grep /app.py
root      6694  6438 92 14:08 pts/0    00:00:07 python /app.py

在终端中运行top命令，观察CPU和内存的使用情况

# 按1切换到每个CPU的使用情况
[root@local_sa_192-168-1-6 ~]# top
top - 14:09:36 up 1 day,  4:26,  2 users,  load average: 1.91, 0.69, 0.25
Tasks: 249 total,   1 running,  60 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.0 us,  0.4 sy,  0.0 ni,  0.0 id, 99.6 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  0.7 us,  2.1 sy,  0.0 ni,  0.0 id, 97.2 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  4027980 total,   831016 free,  1171968 used,  2024996 buff/cache
KiB Swap:  8388604 total,  8388604 free,        0 used.  2616272 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 6824 root      20   0  963332 934468   5432 D  54.2 23.2   0:42.47 python
 
##
观察top的输出，发现CPU的使用率非常高，iowait超过了90%，这说明CPU上，可能正在运行I/O密集型的进程
##
进程部分的CPU使用情况
python进程的CPU使用率已经达到了54%，看起来python是个可疑进程

运行 iostat 命令，观察 I/O 的使用情况

# -d 表示显示I/O性能指标
# -x 表示显示扩展统计（即所有I/O指标）
[root@local_sa_192-168-1-6 ~]# 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
sda               0.00     0.00    0.00   14.00     0.00 17408.00  2486.86     0.99   71.07    0.00   71.07  71.07  99.50
scd0              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
dm-0              0.00     0.00    0.00    1.00     0.00 12288.00 24576.00     0.61  609.00    0.00  609.00  52.00   5.20
dm-1              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
##
观察iostat的最后一列，磁盘sda的I/O使用率已经高达99%，很可能已经接近I/O饱和
##
再看前面的各个指标，每秒写磁盘请求数是14，写大小是17MB，写请求的响应时间为71.07毫秒，而请求队列长度则达到了2486
##
超慢的响应时间和特长的请求队列长度，进一步验证了I/O已经饱和的猜想。sda磁盘已经遇到了严重的性能瓶颈
##
iowait高达90%了，这正是磁盘sda的I/O瓶颈导致的

使用pidstat加上-d参数，就可以显示每个进程的I/O情况

[root@local_sa_192-168-1-6 ~]# pidstat -d 1
Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 	2021年12月17日 	_x86_64_	(2 CPU)

14时25分47秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
14时25分48秒     0      6694      0.00  17000.00      0.00  python

14时25分48秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
14时25分49秒     0      6694      0.00  15912.00      0.00  python

14时25分49秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
14时25分50秒     0      6694      0.00  15096.00      0.00  python

14时25分50秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
14时25分51秒     0      6694      0.00  14552.00      0.00  python
##
从pidstat的输出，发现只有python进程的写比较大，而且每秒写的数据超过15MB
很明显，正是python进程导致了I/O瓶颈

在终端中运行 strace 命令

[root@local_sa_192-168-1-6 ~]# strace -p 6824
strace: Process 6694 attached
munmap(0x7f39f2298000, 314576896)       = 0
write(3, "\n", 1)                       = 1
munmap(0x7f3a04e99000, 314576896)       = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=103547, tv_nsec=193451960}) = 0
select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=100000}) = 0 (Timeout)
clock_gettime(CLOCK_REALTIME, {tv_sec=1639722511, tv_nsec=679972197}) = 0
getpid()                                = 1
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3a04e99000
mmap(NULL, 393220096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f39ed798000
mremap(0x7f39ed798000, 393220096, 314576896, MREMAP_MAYMOVE) = 0x7f39ed798000
munmap(0x7f3a04e99000, 314576896)       = 0
lseek(3, 0, SEEK_END)                   = 943718535
lseek(3, 0, SEEK_CUR)                   = 943718535
munmap(0x7f39ed798000, 314576896)       = 0
close(3)                                = 0
stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0

##
从write()系统调用上，可以看到进程向文件描述符编号为3的文件中，写入了300MB的数据
不过，write()调用中只能看到文件的描述符编号，文件名和路径还是未知的
##
再观察后面的stat()调用，可以看到它正在获取/tmp/logtest.txt.1的状态
这种"点+数字格式"的文件，在日志回滚中非常常见
可以猜测这是第一个日志回滚文件，而正在写的日志文件路径，则是/tmp/logtest.txt

lsof专门用来查看进程打开文件列表
不过，这里的“文件”不只有普通文件，还包括了目录、块设备、动态库、网络套接字等

[root@local_sa_192-168-1-6 ~]# lsof -p 6824
COMMAND  PID USER   FD   TYPE DEVICE  SIZE/OFF      NODE NAME
python  6824 root  cwd    DIR   0,45        17  44605131 /
python  6824 root  rtd    DIR   0,45        17  44605131 /
......
python  6824 root    2u   CHR  136,0       0t0         3 /dev/pts/0
python  6824 root    3w   REG  253,0 754737152   9831016 /tmp/logtest.txt
##
FD 表示文件描述符号
TYPE 表示文件类型
NAME 表示文件路径
##
看最后一行说明这个进程打开了文件/tmp/logtest.txt，并且它的文件描述符是3号
而3后面的w，表示以写的方式打开
##
这跟刚才strace完猜测的结果一致，看来这就是问题的根源
进程6824在疯狂写日志，而日志文件的路径是/tmp/logtest.txt

把案例应用的源代码拷贝出来，然后查看它的内容

# 拷贝案例应用源代码到当前目录
[root@local_sa_192-168-1-6 ~]# docker cp app:/app.py .

# 查看案例应用的源代码
[root@local_sa_192-168-1-6 ~]# cat app.py
#!/usr/bin/env python
# -*- coding: UTF-8 -*-

import logging
import random
import string
import signal
import time

from logging.handlers import RotatingFileHandler

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.INFO)
rHandler = RotatingFileHandler("/tmp/logtest.txt", maxBytes=1024 * 1024 * 1024, backupCount=1)
rHandler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
rHandler.setFormatter(formatter)
logger.addHandler(rHandler)


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)


def get_message(N):
    '''Get message for logging'''
    return N * ''.join(random.choices(string.ascii_uppercase + string.digits, k=1))


def write_log(size):
    '''Write logs to file'''
    message = get_message(size)
    while True:
        logger.info(message)
        time.sleep(0.1)


signal.signal(signal.SIGUSR1, set_logging_info)
signal.signal(signal.SIGUSR2, set_logging_warning)

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命令，给进程6824发送SIGUSR2信号
```
[root@local_sa_192-168-1-6 ~]# kill -SIGUSR2 6824
```

再执行top和iostat观察一下

[root@local_sa_192-168-1-6 ~]# top
%Cpu(s):  0.0 us,  0.2 sy,  0.0 ni, 99.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st

[root@local_sa_192-168-1-6 ~]# iostat -d -x 1
Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 	2021年12月17日 	_x86_64_	(2 CPU)
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    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
scd0              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
dm-0              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
dm-1              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
##
观察top和iostat的输出，发现稍等一段时间后iowait会变成0
而sda磁盘的I/O使用率也会逐渐减少到0
##
停止案例应用
docker rm -f app

小结

日志是了解应用程序内部运行情况，最常用、也最有效的工具
无论是操作系统，还是应用程序，都会记录大量的运行日志，以便事后查看历史记录
这些日志一般按照不同级别来开启
比如开发环境通常打开调试级别的日志，而线上环境则只记录警告和错误日志

在排查应用程序问题时，可能需要在线上环境临时开启应用程序的调试日志
有时候，事后一不小心就忘了调回去
没把线上的日志调高到警告级别，可能会导致CPU使用率、磁盘I/O等一系列的性能问题
严重时，甚至会影响到同一台服务器上运行的其他应用程序

在碰到这种狂打日志的场景时
可以用iostat、strace、lsof等工具来定位狂打日志的进程，找出相应的日志文件
再通过应用程序的接口，调整日志级别来解决问题

如果应用程序不能动态调整日志级别，可能还需要修改应用的配置，并重启应用让配置生效

posted @ 2021-12-17 15:04 李成果阅读(116) 评论(0) 编辑收藏举报

刷新页面返回顶部

Alnk

邮箱:1029612787@qq.com

26-案例篇：如何找出狂打日志的内鬼？

案例

小结

公告