磁盘IO问题排查实战
前言：
有关于磁盘IO过高导致CPU iowait比较高的问题，笔者一直没有在产线遇到过。
所以想去通过写代码来模拟这个操作，但是无奈笔者的Mac机器性能太强了，所以一直压不出来想要的效果。
既然有些效果没法出来，我们就先方法论一下，先用工具了解当前服务及进程的状态，然后逐个分析。
准备工作：
1.代码准备，（笔者会在最后贴出，模拟写磁盘动作），最终打成war包，在docker tomcat中启动
2.工具准备，需要的验证工具，iostat、strace、lsof、pidstat，需要提前安装好
1.问题排查全过程
启动docker tomcat后，在发起http请求后，验证I/O情况
1.1 top查看进程基本情况
top - 01:45:17 up 1 day, 1:27, 0 users, load average: 0.23, 0.10, 0.07
Tasks: 5 total, 0 running, 4 sleeping, 0 stopped, 0 zombie
%Cpu(s): 24.7 us, 1.5 sy, 0.0 ni, 73.5 id, 0.2 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 2036420 total, 2004040 used, 32380 free, 23924 buffers
KiB Swap: 1048572 total, 117648 used, 930924 free. 716924 cached MemPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1 root 20 0 3046980 821692 5948 S 102.2 40.3 0:57.69 java 54 root 20 0 169404 10112 3020 S 0.0 0.5 0:00.13 bash 62 root 20 0 169212 10508 3000 S 0.0 0.5 0:00.06 bash 74 root 20 0 297616 14220 5328 S 0.0 0.7 0:00.08 curl 79 root 0 0 170660 9752 3176 0 0.0 0.5 0:00.00 top 可以看到PID=1的进程，CPU使用率102%，内存使用率40.3%。这时只能看出CPU使用率高，还不知道具体问题
注意：
实际正常的话，应该能看到%Cpu(s)行的 wa（也就是wait）会很高，能很明确的看出是IO的相关问题
笔者这里代码没有模拟出来
1.2 iostat查看磁盘io信息
root@91230cc467cc:/tmp# iostat -x -d -m 3
Linux 5.10.76-linuxkit (91230cc467cc) 03/28/22 _x86_64_ (4 CPU)Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.56 3.56 2.93 1.12 0.09 0.51 305.35 0.00 0.54 0.17 1.48 0.40 0.16Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 14.00 4.33 262.67 0.06 259.60 1991.67 0.35 1.32 1.15 1.32 0.23 6.17Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 15.00 1.33 308.00 0.01 308.06 2039.62 0.78 2.10 0.25 2.10 0.26 8.07Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 6.67 2.00 259.00 0.01 258.58 2029.08 0.36 1.38 0.17 1.38 0.24 6.23Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 14.67 3.00 297.67 0.01 302.69 2061.84 0.71 1.95 0.44 1.97 0.24 7.33Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 14.33 3.33 271.33 0.02 271.52 2024.68 0.37 1.33 0.30 1.34 0.21 5.90由于笔者的Mac磁盘比较强劲，所以这了的%util不算很高。
但是可以很明显的看出来wMB/s，每秒的写达到了271M，这个还是很高的。
我们需要找出是哪个进程在做这种写操作。
1.3 pidstat查看进程信息
root@91230cc467cc:/usr/local/tomcat# pidstat -d 2
Linux 5.10.76-linuxkit (91230cc467cc) 03/28/22 _x86_64_ (4 CPU)02:28:02 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:04 0 1 0.00 307232.00 0.00 0 java
02:28:04 0 72 0.00 2.00 2.00 0 pidstat02:28:04 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:06 0 1 11.94 254752.24 0.00 0 java
02:28:06 0 72 0.00 1.99 1.99 0 pidstat02:28:06 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:08 0 1 0.00 307242.00 0.00 0 java
02:28:08 0 72 0.00 2.00 2.00 0 pidstat02:28:08 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:10 0 1 0.00 307240.00 0.00 0 java
02:28:10 0 72 0.00 2.00 2.00 0 pidstat02:28:10 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:12 0 1 0.00 287554.00 0.00 0 java
02:28:12 0 72 0.00 2.00 2.00 0 pidstat通过 pidstat -d模式，只查看I/O情况。
很明显的看出来PID=1的java进程，每秒写kB_wr/s达到了307240KB/s，大概300M左右。
那么我们就可以确定就是PID=1的这个java进程的问题
1.4 通过strace命令跟踪进程操作
root@91230cc467cc:/usr/local/tomcat# strace -p 1笔者在docker容器中启动strace命令直接报错
root@91230cc467cc:/usr/local/tomcat# strace -p 1
/usr/bin/strace: test_ptrace_setoptions_for_all: PTRACE_TRACEME doesn't work: Function not implemented
/usr/bin/strace: test_ptrace_setoptions_for_all: unexpected exit status 1如上所示，到现在还没有找到具体的问题点，希望读者知道原因的可以回复下，感谢。
1.5 lsof查看进程打开的文件
root@91230cc467cc:/usr/local/tomcat# lsof -p 1
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
java 1 root cwd DIR 0,164 4096 1183913 /usr/local/tomcat
java 1 root rtd DIR 0,164 4096 1184675 /
java 1 root txt REG 0,62 2709992 1310738 /usr/bin/qemu-x86_64
java 1 root mem REG 254,1 1310738 /usr/bin/qemu-x86_64 (stat: No such file or directory)
java 1 root mem REG 254,1 1056726 /usr/lib/jvm/java-7-openjdk-amd64/jre/bin/java (path dev=0,164)
java 1 root mem REG 254,1 1048612 /lib/x86_64-linux-gnu/ld-2.19.so (path dev=0,164)
java 1 root mem REG 254,1 1048694 /lib/x86_64-linux-gnu/libpthread-2.19.so (path dev=0,164)
...
java 1 root 45r CHR 1,8 0t0 6 /dev/random
java 1 root 46r CHR 1,9 0t0 10 /dev/urandom
java 1 root 47u IPv4 2162977 0t0 TCP *:http-alt (LISTEN)
java 1 root 48u unix 0x0000000000000000 0t0 2162978 socket
java 1 root 49r FIFO 0,11 0t0 2162980 pipe
java 1 root 50w FIFO 0,11 0t0 2162980 pipe
java 1 root 51u 0000 0,12 0 12341 anon_inode
java 1 root 52u IPv4 2162981 0t0 TCP *:8009 (LISTEN)
java 1 root 53r FIFO 0,11 0t0 2162982 pipe
java 1 root 54w FIFO 0,11 0t0 2162982 pipe
java 1 root 55u 0000 0,12 0 12341 anon_inode
java 1 root 56w REG 0,164 685 1184727 /usr/local/tomcat/logs/localhost_access_log.2022-03-28.txt
java 1 root 57r CHR 1,8 0t0 6 /dev/random
java 1 root 58w REG 0,164 3844 1184789 /tmp/testlog.log
java 1 root 59w REG 0,164 104857600 1186298 /tmp/test.log (deleted)
java 1 root 60w REG 0,164 5242880000 1185856 /tmp/test.log (deleted)
java 1 root 61w REG 0,164 5242880000 1185857 /tmp/test.log (deleted)
java 1 root 62w REG 0,164 5242880000 1185862 /tmp/test.log (deleted)
java 1 root 63w REG 0,164 5242880000 1185979 /tmp/test.log (deleted)
java 1 root 64w REG 0,164 5242880000 1185980 /tmp/test.log (deleted)
java 1 root 65w REG 0,164 5242880000 1185987 /tmp/test.log (deleted)
java 1 root 66w REG 0,164 5242880000 1185989 /tmp/test.log (deleted)
java 1 root 67w REG 0,164 5242880000 1186285 /tmp/test.log (deleted)
java 1 root 68r FIFO 0,11 0t0 2160501 pipe
java 1 root 69w FIFO 0,11 0t0 2160501 pipe
java 1 root 70u 0000 0,12 0 12341 anon_inode
...
java 1 root 80u IPv4 2162151 0t0 TCP 91230cc467cc:http-alt->172.17.0.1:62718 (ESTABLISHED)
java 1 root 82u IPv4 2160507 0t0 TCP localhost:8005 (LISTEN)
java 1 root 84u unix 0x0000000000000000 0t0 2163124 socket
java 1 root 85r REG 0,164 2150368 1056781 /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/charsets.jar
java 1 root 86w REG 0,164 5242880000 1186286 /tmp/test.log (deleted)
java 1 root 87w REG 0,164 358440960 1186297 /tmp/test.log通过lsof命令，可以看到进程打开的那些文件，这里有一个文件/tmp/test.log被频繁的打开删除
如最后一行，正在写入/tmp/test.log，目前文件大小为358440960
倒数第二行，删除了一个/tmp/test.log的文件，大小为5242880000
所以通过这些信息，基本可以确定这个/tmp/test.log的文件应该就是我们要找的那个文件
1.6 代码查询
我们通过test.log来去代码中查看
public class JvmTest {@RequestMapping(path = "/testlog", method = RequestMethod.GET)public String testlog() {StringBuilder sb = new StringBuilder();int length = 100 * 1024 * 1024;byte[] bytes = new byte[length];for (int j = 0; j < length; j++) {bytes[j] = 'a';}String s = sb.toString();FileOutputStream outputStream = null;File f = null;try {f = new File("/tmp/test.log");outputStream = new FileOutputStream(f);} catch (FileNotFoundException e) {e.printStackTrace();}for (int i = 0; i < 1000; i++) {try {outputStream.write(bytes);if (i % 50 == 0) {f.delete();f = new File("/tmp/test.log");outputStream = new FileOutputStream(f);}} catch (IOException e) {e.printStackTrace();}try {Thread.sleep(200);} catch (InterruptedException e) {e.printStackTrace();}}return "success";}
}可以看出，我们最开始触发的这个方法，每200ms写入到/tmp/test.log文件中100M的内容，每50 * 200 = 10秒钟删除一次/tmp/test.log文件。
基本验证了lsof的展示结果。
总结：
有点失败的一次问题排查过程，与标准的验证方式还是有点区别的。
当然，在碰到真正的iowait相关问题时，我们还是可以按照这个标准方式来查询问题。
希望了解完整正确过程的同学可以参考：
极客时间 <<Linux性能优化实战>> 之 案例篇：如何找出狂打日志的“内鬼”？
磁盘IO问题排查实战相关推荐
- 线上操作与线上问题排查实战
转自:https://mp.weixin.qq.com/s?__biz=MjM5ODYxMDA5OQ==&mid=2651960323&idx=1&sn=e04af14d2eb ...
- linux 磁盘并发io,Linux系统 磁盘IO过高排查总结
最近做的一个电商网站因为磁盘 I/O 过高导致访问速度奇慢,问题存在两个月有余未得到解决办法.此次排查原因的经验可以作下次问题的参考. 1.会看懂 top 系统命令出来的各项参数.此次是无意中发现 u ...
- 测试硬盘读写速度c语言实现,一次解决磁盘IO读取慢全过程实战
在两台型号相同的机器上(snap1 和snap3)测试磁盘的读取速度,发现两台机器的读取速度差的很大: #dd if=/dev/dm-93 of=/dev/null bs=4M count=1024 ...
- 磁盘 io 的性能指标 简介
目录 主要关注指标 IOPS 带宽 响应时间 磁盘繁忙程度 服务队列满 文件系统使用率 Inode使用率 业务服务器的操作系统作为存储的用户只能看到disk(存储层面的LUN),而存储管理员才知道存储 ...
- 用Python实现磁盘IO操作全攻略，让数据流动起来！
导读:IO在计算机中指的是Input/Output,也就是输入输出.凡是用到数据交换的地方,都会涉及IO编程,例如磁盘.网络的数据传输. 在IO编程中,Stream(流)是一种重要的概念,分为输入流( ...
- FastDFS（提升磁盘IO性能的几个技巧 FastDFS 5.04之IO读事件）
提升磁盘IO性能的几个技巧 https://www.cnblogs.com/derekchen/archive/2012/04/04/2431573.html 目前磁盘都是机械方式运作的,主 ...
- Linux系统监控命令整理汇总-掌握CPU,内存,磁盘IO等找出性能瓶颈
的性能有问题,总之,每到晚上挖站否的主机就出现了不稳定的情况,系统负载忽高忽低.利用服务器日志分析利器:ngxtop和GoAccess也能查出有一些IP一直在不断地扫描服务器端口还有WP后台. 但是, ...
- Linux 查看磁盘IO的使用
我们在线上linux服务器排查问题时,一般会通过top.free.netstat.df -h等命令排查cpu.内存.网络和磁盘等问题.有的时候我们需要更进一步了解磁盘io的使用情况,那么本文就是重点讲 ...
- 一次 jbd2进程导致磁盘 io 高的分析解决过程
故障现象 在3节点组成的大数据集群中,混部了 ES,kafka,zk,pg,mysql,spark,yarn,hdfs,以及业务的 etl 程序等组件.起初发现业务进程处理数据速度很慢,排查后发现数据 ...
最新文章
- netconf 网络配置协议 简介
- Spring Data JPA 常用注解
- python调用Shell脚本：os.system(cmd)或os.popen(cmd),
- HDU 2191 - 悼念512汶川大地震遇难同胞——珍惜现在，感恩生活 （多重背包）
- Macbook 中如何通过命令行打开 vscode
- jmeter吞吐量_深入理解Jmeter常用定时器
- bzoj1084: [SCOI2005]最大子矩阵
- UI测试常见BUG汇总
- BAPI_SALESDOCU_CREATEFROMDATA1--VA01
- xml-apis-ext.jar
- python3+requests接口自动化-其他接口封装
- ubuntu 中wget (下载)命令用法
- newifi3 高恪魔改_新路由3高恪newifi3固件-支持512M
- centos7搭建radius认证服务器
- PyQt5 UI设计时自动创建qrc文件
- win7蓝屏0x0000003b解决教程
- dijkastra算法实践poj2387
- 自考汉语言文学本科要考几门？专业有哪些课程？
- 入侵检测工具AIDE极简教程
- PHP 无限极分类下拉列表实现
热门文章
- R语言ggplot2可视化绘制累计频率图、累积分布图（cumulative frequency/density distribution）
- PHP的ob_start()
- 数据结构：线性表(List)【详解】
- 已加载插件：fastestmirror, langpacks /var/run/yum.pid 已被锁定，PID 为 2686 的另一个程序正在运行。
- web前端开发大学生自学学习线路图
- matlab中str2func函数,MATLAB 的函数句柄
- BES2300YP - 死机原因分析 和 堆栈还原
- angular js 大小写转换
- Fast DDS入门一、Fast DDS介绍
- SYD定时器系统使用说明指导