文件系统,是一种对存储设备上的文件进行组织管理的机制,为了支持不同类型的文件系统,Linux延伸出了一层抽象的虚拟文件系统VFS
定义了一组和所有文件系统都支持的数据结构和标准接口,应用程序和内核中其他的子系统,只需要和VFS提供的统一接口进行交互即可
在文件系统之下,为了隔绝块设备和文件系统的交互差异,Linux又抽象出了一层通用块层
通用块层,是文件系统和应用程序提供了访问块设备的标准接口,为块设备提供了统一框架,打通了上下层,并且提供了重新排序,请求合并等方式,提高读写效率
最后就是实际的设备层
那么文件系统 通用块层 设备层,构成了Linux的存储IO栈,存储系统的IO,是整个文件系统中最慢的一环,所以Linux有着多种机制,来进行优化IO效率
1.文件系统有 页缓存 索引节点缓存 目录项缓存等多种缓存机制,减少对下层块设备的调用
2.通用层有,缓存区来缓存块设备的数据
说完了这些,我们聊一下今天遇到的Linux问题和案例
一个docker镜像带来的IO性能问题
首先是运行一个docker命令
docker run -v /tmp:/tmp –name=app -itd feisky/logapp
然后运行ps命令,确认启动无误,
ps -ef |grep /app.py
我确认了对应的pid和启动无误
我们观察一下对应的性能情况
首先是top命令,观察CPU和内存的使用情况,然后使用iostat,观察磁盘的IO情况
首先是top 观察对应的CPU使用情况
观察top的输出,可以看出CPU0的使用率很高,CPU使用率为6.0%
然后尤其是iowait,达到了惊人的92.7%,这说明,对应的CPU0上,运行着io密集型的进程
那么我们继续分析,在top下面的进程中,cpu最高的是python进程,高达6%
其他的CPU使用率都比较低,不超过0.3%
然后看内存的使用情况,总内存为8G,剩余内存只有730MB,而Buffer/Cache占用的内存有6GB,这个说明内存被缓存占用了
那么,顺着iowait继续观察IO的使用情况,
iostat -x -d 1
-d显示IO性能 -x显示扩展统计
在输出中
| # -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-sz rareq-sz wareq-sz svctm %util loop0 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 0.00 0.00 sdb 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 0.00 0.00 sda 0.00 64.00 0.00 32768.00 0.00 0.00 0.00 0.00 0.00 7270.44 1102.18 0.00 512.00 15.50 99.20 |
sda磁盘的IO使用率高达99%,接近了IO饱和
w/s每秒的写请求为64, wkB/s每秒的写大小为32MB,响应时间为7秒,w_awit写其你去队列为1100
上述的情况说明了,sda受到了严重的性能瓶颈
这也是为啥,iowait高达90%了,这也是磁盘sda的IO瓶颈导致的,然后是分析是哪个进程导致的IO性能瓶颈了
我们说过,可以使用pidstat或者iotop,观察进程IO
pidstat -d 1
| $ 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,基本可以判断是IO性能导致的
那么剩余的就是分析源码
基本可以使用进程分析调用工具 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的数据,这应该就是我们需要找的文件
然后后面的start调用,说明其正在获取 /tmp/logtest.txt.1,基本上说一种日志回滚文件格式
然后我们利用lsof来查看进程打开文件的列表
lsof -p 即可查看进程打开了那些文件
| $ 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号,后面的w说明了正在使用写的方式打开
这样,就说明了就是python进程有问题,疯狂的在写入文件
对应的源码中,发现日志路径的确为 /tmp/logtest.txt
每次写的日志大小都是300MB,问题就这样排查到了
那么我们总结一下
本次拿一个日志作为io排查故障的案例来看,我们分别利用了top iostat strace lsof进行定位日志进程,获取到对应的日志文件,通过应用程序的接口,调整日志级别来解决问题
对于这个日志打印中,内存中的Buffer和Cache哪个更多呢?
我想可能是Cache更多一些,Cache主要负责文件的读写缓存
对应的验证手段,可以查看对应的/proc/meminfo