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

Posted sysu_lluozh

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了linux性能优化定位分析狂打日志的问题相关的知识,希望对你有一定的参考价值。

一、文件系统和磁盘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等工具来定位狂打日志的进程,找出相应的日志文件,再通过应用程序的接口调整日志级别来解决问题

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

以上是关于linux性能优化定位分析狂打日志的问题的主要内容,如果未能解决你的问题,请参考以下文章

Linux性能优化方向及相关工具

MySQL优化具体

关于线上优化服务器视频笔记1-----调优线上服务器

Linux性能优化从入门到实战:16 文件系统篇:磁盘 I/O 指标/工具总结问题定位和调优

linux 性能优化-- cpu 切换以及cpu过高

Linux性能优化的全景指南