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

最新推荐文章于 2023-02-22 18:41:06 发布

sysu_lluozh

最新推荐文章于 2023-02-22 18:41:06 发布

阅读量9.6k

点赞数 3

分类专栏： # linux 文章标签： linux

本文链接：https://blog.csdn.net/lluozh2015/article/details/117914586

版权

linux 专栏收录该内容

41 篇文章 4 订阅

订阅专栏

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

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

sysu_lluozh

关注

3
点赞
踩
4

收藏

觉得还不错? 一键收藏
打赏
22
评论
【linux性能优化】定位分析狂打日志的问题

一、文件系统和磁盘I/O回顾一下文件系统和磁盘I/O的原理1.1 文件系统对存储设备上的文件进行组织管理的一种机制为了支持各类不同的文件系统，Linux在各种文件系统上抽象了一层虚拟文件系统VFS它定义了一组所有文件系统都支持的数据结构和标准接口。这样，应用程序和内核中的其他子系统，就只需要跟VFS提供的统一接口进行交互1.2 通用块层在文件系统的下层，为了支持各种不同类型的存储设备，Linux又在各种存储设备的基础上抽象了一个通用块层通用块层，为文件系统和应用程序提供了访问块设备的标准接口
复制链接

扫一扫