一、文件系统和磁盘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 root18940 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 USERPR NI VIRT RES SHR S %CPU %MEMTIME+ COMMAND 18940 root20 0 656108 355740 5236 R 6.3 4.4 0:12.56 python 1312 root20 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/sw/srkB/swkB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aquloop0 0.00 0.000.000.000.000.00 0.00 0.00 0.00 0.00 0sdb 0.00 0.000.000.000.000.00 0.00 0.00 0.00 0.00 0sda 0.00 64.000.00 32768.000.000.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:35UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 15:08:36 0189400.00 45816.000.0096 python 15:08:36UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 15:08:37 0 3540.000.000.00350 jbd2/sda1‑8 15:08:37 0189400.00 46000.000.0096 python 15:08:37 050.000.000.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, "‑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,504096 1549389 / python 18940 root rtd DIR 0,504096 1549389 / … python 18940 root 2u CHR 136,0 0t0 3 /dev/pts/0 python 18940 root 3w REG 8,1 117944320303 /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 1Device r/sw/srkB/swkB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aquloop0 0.00 0.000.000.000.000.00 0.00 0.00 0.00 0.00 0sdb 0.00 0.000.000.000.000.00 0.00 0.00 0.00 0.00 0sda 0.00 0.000.000.000.000.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等工具来定位狂打日志的进程，找出相应的日志文件，再通过应用程序的接口调整日志级别来解决问题
如果应用程序不能动态调整日志级别，可能还需要修改应用的配置并重启应用让配置生效
