linux性能优化定位分析狂打日志的问题

Posted 2021-07-30 sysu_lluozh

一、文件系统和磁盘I/O

回顾一下文件系统和磁盘I/O的原理

1.1 文件系统

对存储设备上的文件进行组织管理的一种机制
为了支持各类不同的文件系统，Linux在各种文件系统上抽象了一层虚拟文件系统VFS

它定义了一组所有文件系统都支持的数据结构和标准接口。这样，应用程序和内核中的其他子系统，就只需要跟VFS提供的统一接口进行交互

1.2 通用块层

在文件系统的下层，为了支持各种不同类型的存储设备，Linux又在各种存储设备的基础上抽象了一个通用块层

通用块层，为文件系统和应用程序提供了访问块设备的标准接口，同时，为各种块设备的驱动程序提供了统一的框架
此外，通用块层还会对文件系统和应用程序发送过来的I/O请求进行排队，并通过重新排序、请求合并等方式，提高磁盘读写的效率

1.3 设备层

通用块层的下一层自然就是设备层，包括各种块设备的驱动程序以及物理存储设备

文件系统、通用块层以及设备层构成了Linux的存储 I/O栈

1.4 效率优化

存储系统的I/O，通常是整个系统中最慢的一环，所以Linux 采用多种缓存机制来优化I/O的效率，比如：

• 为了优化文件访问的性能

采用页缓存、索引节点缓存、目录项缓存等多种缓存机制，减少对下层块设备的直接调用

• 为了优化块设备的访问效率

使用缓冲区来缓存块设备的数据

不过，在碰到文件系统和磁盘的I/O问题时，具体应该怎么定位和分析呢？接下来以一个最常见的应用程序记录大量日志的案例分析这种情况

二、案例

2.1 案例准备

在终端中执行命令启动目标应用：

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

在终端中运行ps命令，确认案例应用正常启动

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

如果操作无误，可以在ps的输出中看到一个app.py的进程

2.2 性能指标关注

分析系统有没有性能问题要观察哪些性能指标呢？
CPU、内存和磁盘I/O等系统资源很容易出现资源瓶颈，所以观察一下这些资源的使用情况

在开始之前需要考虑清楚，要使用哪些工具以及工具的使用顺序又是怎样的？

首先用top观察CPU和内存的使用情况，然后再用iostat观察磁盘的I/O情况

2.3 top分析CPU和内存

在终端中运行top命令：

# 按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的输出

• 首先查看不同Cpu的数据

发现CPU0的使用率非常高，系统CPU使用率(sys%)为6%，而iowait超过90%
这说明CPU0上可能正在运行I/O密集型的进程。不过究竟是什么原因呢？这个疑问先保留着先继续看完top数据

• 接着查看进程部分的CPU使用情况

python进程的CPU使用率已经达到6%，而其余进程的CPU使用率都比较低，不超过0.3%
看起来python是个可疑进程，记下python进程的PID号18940稍后分析

• 最后查看内存的使用情况

总内存 8G，剩余内存只有730MB，而Buffer/Cache占用内存高达6GB，这说明内存主要被缓存占用
虽然大部分缓存可回收，但是还是得了解下缓存的去处，确认缓存使用都是合理的

2.4 iostat分析I/O

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

运行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
loop0            0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0
sdb              0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0
sda              0.00   64.00      0.00  32768.00     0.00     0.00   0.00   0.00    0.00 7270.44 110

观察iostat的最后一列，可以看到磁盘sda的I/O使用率已经高达99%，很可能已经接近I/O饱和

再看前面的各个指标，每秒写磁盘请求数是64，写大小是32MB，写请求的响应时间为7秒，而请求队列长度则达到1100

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

到这里可以理解为什么前面看到的iowait高达90%，这正是磁盘sda的I/O瓶颈导致，接下来的重点就是分析I/O性能瓶颈的根源

2.5 pidstat获取每个进程I/O

那要怎么知道，这些I/O请求相关的进程呢？可以用pidstat或者iotop观察进程的I/O情况

使用pidstat加上-d参数，可以显示每个进程的I/O情况，所以可以在终端中运行如下命令：

$ 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 

从pidstat的输出可以发现，只有python进程的写比较大，而且每秒写的数据超过45MB，比上面iostat发现的32MB的结果还要大
很明显，正是python进程导致了I/O瓶颈

• iodelay

再往下看iodelay项，虽然只有python在大量写数据，但应该注意到有两个进程(kworker和jbd2)的延迟比python进程还大很多

这其中，kworker是一个内核线程，而jbd2是ext4文件系统中用来保证数据完整性的内核线程，他们都是保证文件系统基本功能的内核线程，所以延迟的根源还是大量I/O

综合pidstat的输出来看，还是python进程的嫌疑最大

2.6 strace获取具体进程写数据

接下来，分析python进程到底在写什么

首先留意python进程的PID18940，其实前面在使用top时记录CPU使用率最高的进程也正是PID18940，不过，虽然在top中使用率最高，但才6%并不算高。所以，以I/O问题为分析方向还是正确的

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

读写文件必须通过系统调用完成，观察系统调用情况就可以知道进程正在写的文件，接下来可以使用strace分析系统调用

在终端中运行strace命令，并通过-p 18940指定python进程的PID：

$ 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 

从write()系统调用上，可以看到进程向文件描述符编号为3的文件中写入了300MB的数据，看来这应该是要找的文件。不过write()调用中只能看到文件的描述符编号，文件名和路径还是未知

再观察后面的stat()调用，可以看到它正在获取/tmp/logtest.txt.1的状态
这种"点+数字格式"的文件，在日志回滚中非常常见，是否可以猜测这是第一个日志回滚文件，而正在写的日志文件路径则是/tmp/logtest.txt

2.7 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

2.8 分析源码问题根因

既然找出了问题根源，接下来查看源代码分析为什么这个进程狂打日志

可以运行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，这跟上面的分析结果是一致的

2.9 问题解决

一般来说，生产系统的应用程序应该有动态调整日志级别的功能
继续查看源码可以发现，这个程序也可以调整日志级别。如果发送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
loop0            0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0
sdb              0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0
sda              0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0

观察top和iostat的输出可以发现，稍等一段时间后iowait会变成0，而sda磁盘的I/O使用率也会逐渐减少到0

不仅定位了狂打日志的应用程序，并通过调高日志级别的方法完美解决了I/O的性能瓶颈

三、小结

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

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

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

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