4
Linux系统中负载较高&磁盘I/O %util特别高问题排查思路与解决方法（学完Linux问题...
source link: https://blog.51cto.com/linhuchong/5241886
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
一、Load分析：
情况1：CPU高、Load高
- 通过top命令查找占用CPU最高的进程PID；
- 通过top -Hp PID查找占用CPU最高的线程TID;
- 对于java程序，使用jstack打印线程堆栈信息（可联系业务进行排查定位）；
- 通过printf %x tid打印出最消耗CPU线程的十六进制；
- 在堆栈信息中查看该线程的堆栈信息；
情况2：CPU低、Load高（此情况出现几率很大）
- 通过top命令查看CPU等待IO时间，即%wa；
- 通过iostat -d -x -m 1 10查看磁盘IO情况；(安装命令 yum install -y sysstat)
- 通过sar -n DEV 1 10查看网络IO情况；
- 通过如下命令查找占用IO的程序；
ps -e -L h o state,cmd | awk '{if($1=="R"||$1=="D"){print $0}}' | sort | uniq -c | sort -k 1nr
二、CPU高、Load高情况分析
- 使用vmstat 查看系统纬度的 CPU 负载；
- 使用 top 查看进程纬度的 CPU 负载；
2.1、使用 vmstat 查看系统纬度的 CPU 负载
可以通过 vmstat 从系统维度查看 CPU 资源的使用情况
格式：vmstat -n 1 表示结果一秒刷新一次
[root@k8s-10 ~]# vmstat -n 1
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
1 1 0 2798000 2076 6375040 0 0 10 76 10 49 6 2 91 1 0
0 0 0 2798232 2076 6375128 0 0 0 207 7965 12525 7 2 90 2 0
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
1 1 0 2798000 2076 6375040 0 0 10 76 10 49 6 2 91 1 0
0 0 0 2798232 2076 6375128 0 0 0 207 7965 12525 7 2 90 2 0
返回结果中的主要数据列说明：
- r： 表示系统中 CPU 等待处理的线程。由于 CPU 每次只能处理一个线程，所以，该数值越大，通常表示系统运行越慢。
- b： 表示阻塞的进程,这个不多说，进程阻塞，大家懂的。
- us： 用户CPU时间，我曾经在一个做加密解密很频繁的服务器上，可以看到us接近100,r运行队列达到80(机器在做压力测试，性能表现不佳)。
- sy： 系统CPU时间，如果太高，表示系统调用时间长，例如是IO操作频繁。
- wa：IO 等待消耗的 CPU 时间百分比。该值较高时，说明 IO 等待比较严重，这可能磁盘大量作随机访问造成的，也可能是磁盘性能出现了瓶颈。
- id：处于空闲状态的 CPU 时间百分比。如果该值持续为 0，同时 sy 是 us 的两倍，则通常说明系统则面临着 CPU 资源的短缺。
常见问题及解决方法： - 如果r经常大于4，且id经常少于40，表示cpu的负荷很重。
- 如果pi，po长期不等于0，表示内存不足。
- 如果disk经常不等于0，且在b中的队列大于3，表示io性能不好。
2.1、使用 top 查看进程纬度的 CPU 负载
可以通过 top 从进程纬度来查看其 CPU、内存等资源的使用情况。
[root@k8s-10 ~]# top -c
top - 19:53:49 up 2 days, 7:57, 3 users, load average: 0.76, 0.79, 0.58
Tasks: 282 total, 2 running, 280 sleeping, 0 stopped, 0 zombie
%Cpu(s): 2.4 us, 1.4 sy, 0.0 ni, 95.0 id, 1.2 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 12304204 total, 2800864 free, 3119064 used, 6384276 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 8164632 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29884 root 20 0 5346580 929332 14556 S 0.0 7.6 6:19.19 /opt/jdk1.8.0_144/bin/java -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apach+
875 root 20 0 729524 563424 38612 S 3.1 4.6 93:22.70 kube-apiserver --authorization-mode=Node,RBAC --service-node-port-range=80-60000 --advertise-address=10.68.7.162 --allow-privileged=true -+
3870 nfsnobo+ 20 0 910376 317248 22812 S 1.6 2.6 42:29.59 /bin/prometheus --config.file=/etc/prometheus/prometheus.yml --storage.tsdb.path=/prometheus --storage.tsdb.retention=1d --web.enable-life+
top - 19:53:49 up 2 days, 7:57, 3 users, load average: 0.76, 0.79, 0.58
Tasks: 282 total, 2 running, 280 sleeping, 0 stopped, 0 zombie
%Cpu(s): 2.4 us, 1.4 sy, 0.0 ni, 95.0 id, 1.2 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 12304204 total, 2800864 free, 3119064 used, 6384276 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 8164632 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29884 root 20 0 5346580 929332 14556 S 0.0 7.6 6:19.19 /opt/jdk1.8.0_144/bin/java -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apach+
875 root 20 0 729524 563424 38612 S 3.1 4.6 93:22.70 kube-apiserver --authorization-mode=Node,RBAC --service-node-port-range=80-60000 --advertise-address=10.68.7.162 --allow-privileged=true -+
3870 nfsnobo+ 20 0 910376 317248 22812 S 1.6 2.6 42:29.59 /bin/prometheus --config.file=/etc/prometheus/prometheus.yml --storage.tsdb.path=/prometheus --storage.tsdb.retention=1d --web.enable-life+
默认界面上第三行会显示当前 CPU 资源的总体使用情况，下方会显示各个进程的资源占用情况。
可以直接在界面输入大小字母 P，来使监控结果按 CPU 使用率倒序排列，进而定位系统中占用 CPU 较高的进程。最后，根据系统日志和程序自身相关日志，对相应进程做进一步排查分析，以判断其占用过高 CPU 的原因。
2.2、strace命令分析
strace -tt -T -v -f -e trace=file -o /data/log/strace.log -s 1024 -p 23489
- -tt：在每行输出的前面，显示毫秒级别的时间
- -T：显示每次系统调用所花费的时间
- -v：对于某些相关调用，把完整的环境变量，文件 stat 结构等打出来。
- -f：跟踪目标进程，以及目标进程创建的所有子进程
- -e：控制要跟踪的事件和跟踪行为，比如指定要跟踪的系统调用名称
- -o：把 strace 的输出单独写到指定的文件
- -s：当系统调用的某个参数是字符串时，最多输出指定长度的内容，默认是 32 个字节
- -p：指定要跟踪的进程 pid，要同时跟踪多个 pid，重复多次 -p 选项即可。
三、CPU低、Load高情况分析
问题描述：
Linux 系统没有业务程序运行，通过 top 观察，类似如下图所示，CPU 很空闲，但是 load average 却非常高：
处理办法：
- load average 是对 CPU 负载的评估，其值越高，说明其任务队列越长，处于等待执行的任务越多。
- 出现此种情况时，可能是由于僵死进程导致的。可以通过指令ps -axjf查看是否存在 D 状态进程。
- D 状态是指不可中断的睡眠状态。该状态的进程无法被 kill，也无法自行退出。只能通过恢复其依赖的资源或者重启系统来解决。
等待I/O的进程通过处于uninterruptible sleep或D状态；通过给出这些信息我们就可以简单的查找出处在wait状态的进程
ps -eo state,pid,cmd | grep "^D"; echo "----"
- 查找占用IO的程序
ps -e -L h o state,cmd | awk '{if($1=="R"||$1=="D"){print $0}}' | sort | uniq -c | sort -k 1nr
ps -eo state,pid,cmd | grep "^D"; echo "----"
- 查找占用IO的程序
ps -e -L h o state,cmd | awk '{if($1=="R"||$1=="D"){print $0}}' | sort | uniq -c | sort -k 1nr
四、案例分析：磁盘I/O %util特别高
4.1、环境复现
- 环境配置：本次测试使用128C_512G_4TSSD服务器配置，MySQL版本为8.0.27
- 场景模拟：使用sysbench创建5个表，每个表2亿条数据，执行产生笛卡尔积查询的sql语句，产生io,可以模拟业务压力。首先使用sysbench进行数据压测
4.2、系统层面底层故障排查
Shell> sysbench --test=/usr/local/share/sysbench/oltp_insert.lua --mysql-host=XXX --mysql-port=3306 --mysql-user=pcms --mysql-password=abc123 --mysql-db=sysbench --percentile=99 --table-size=2000000000 --tables=5 --threads=1000 prepare
使用sysbench进行模拟高并发
shell> sysbench --test=/usr/local/share/sysbench/oltp_write_only.lua --mysql-host=xxx --mysql-port=3306 --mysql-user=pcms --mysql-password=abc123 --mysql-db=sysbench --percentile=99 --table-size=2000000000 --tables=5 --threads=1000 --max-time=60000 --report-interval=1 --threads=1000 --max-requests=0 --mysql-ignore-errors=all run
执行笛卡尔积sql语句
mysql> select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc;
4.3、检查当前服务器状态
shell> top
top - 19:49:05 up 10 days, 8:16, 2 users, load average: 72.56, 40.21, 17.08
Tasks: 1288 total, 1 running, 586 sleeping, 0 stopped, 0 zombie
%Cpu(s): 19.7 us, 4.2 sy, 0.0 ni, 75.9 id, 1.0 wa, 0.0 hi, 0.2 si, 0.0 st
KiB Mem : 53542118+total, 23667507+free, 22735366+used, 71392448 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 23128006+avail Mem
top - 19:49:05 up 10 days, 8:16, 2 users, load average: 72.56, 40.21, 17.08
Tasks: 1288 total, 1 running, 586 sleeping, 0 stopped, 0 zombie
%Cpu(s): 19.7 us, 4.2 sy, 0.0 ni, 75.9 id, 1.0 wa, 0.0 hi, 0.2 si, 0.0 st
KiB Mem : 53542118+total, 23667507+free, 22735366+used, 71392448 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 23128006+avail Mem
由上可知：目前一分钟负载为72.56，且呈上升趋势，并且存在io压力
4.4、查看当前各个磁盘设备的io情况
shell> iostat -m -x 1
Linux 4.14.0-115.el7a.0.1.aarch64 (mysql-4) 01/08/2022 _aarch64_ (128 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
sda 0.00 0.00 14213.00 27430.00 222.08 465.15 33.80 5.39 0.13 0.14 0.12 0.02 86.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
dm-0 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
dm-1 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
dm-2 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
Linux 4.14.0-115.el7a.0.1.aarch64 (mysql-4) 01/08/2022 _aarch64_ (128 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
sda 0.00 0.00 14213.00 27430.00 222.08 465.15 33.80 5.39 0.13 0.14 0.12 0.02 86.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
dm-0 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
dm-1 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
dm-2 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磁盘的io压力较大
4.5、检查sda磁盘当前的io读写情况
shell> iostat -d /dev/sda -m -x 1
Linux 4.14.0-115.el7a.0.1.aarch64 (mysql-4) 01/08/2022 _aarch64_ (128 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
sda 0.00 0.17 7.86 81.23 0.29 3.96 97.88 0.23 2.53 0.22 2.76 0.04 0.33
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 21109.00 42839.00 329.81 710.90 33.33 19.47 0.30 0.16 0.37 0.02 96.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 19287.00 41404.00 301.36 692.29 33.53 15.73 0.26 0.18 0.30 0.02 93.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 22135.00 43044.00 345.86 1165.18 47.48 100.87 1.55 0.20 2.24 0.01 97.00
Linux 4.14.0-115.el7a.0.1.aarch64 (mysql-4) 01/08/2022 _aarch64_ (128 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
sda 0.00 0.17 7.86 81.23 0.29 3.96 97.88 0.23 2.53 0.22 2.76 0.04 0.33
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 21109.00 42839.00 329.81 710.90 33.33 19.47 0.30 0.16 0.37 0.02 96.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 19287.00 41404.00 301.36 692.29 33.53 15.73 0.26 0.18 0.30 0.02 93.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 22135.00 43044.00 345.86 1165.18 47.48 100.87 1.55 0.20 2.24 0.01 97.00
由上可知：目前sda磁盘的压力比较大，每秒写入比每秒读差距较大，证明目前有大量的io写入
4.6、检查sda磁盘中哪个应用程序占用的io比较高
shell> pidstat -d 1
Linux 4.14.0-115.el7a.0.1.aarch64 (mysql-4) 01/08/2022 _aarch64_ (128 CPU)
08:01:43 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
08:01:44 PM 1000 73739 62018.35 171346.79 0.00 mysqld
08:01:44 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
08:01:45 PM 1000 73739 145328.00 435216.00 0.00 mysqld
08:01:45 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
08:01:46 PM 1000 73739 141488.00 433232.00 0.00 mysqld
Linux 4.14.0-115.el7a.0.1.aarch64 (mysql-4) 01/08/2022 _aarch64_ (128 CPU)
08:01:43 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
08:01:44 PM 1000 73739 62018.35 171346.79 0.00 mysqld
08:01:44 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
08:01:45 PM 1000 73739 145328.00 435216.00 0.00 mysqld
08:01:45 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
08:01:46 PM 1000 73739 141488.00 433232.00 0.00 mysqld
由上可知：占用io高的应用程序是mysql，且pid为73739
4.7、分析应用程序中哪一个线程占用的io比较高
shell> pidstat -dt -p 73739 1 执行两三秒即可
Average: 1000 - 73823 0.00 233133.98 0.00 |__mysqld
Average: 1000 - 74674 0.00 174291.26 0.00 |__mysqld
11:56:18 PM 1000 - 74770 124928.00 74688.00 0.00 |__mysqld
11:56:17 PM 1000 - 74770 124603.77 73358.49 0.00 |__mysqld
Average: 1000 - 74770 124761.17 74003.88 0.00 |__mysqld
Average: 1000 - 73823 0.00 233133.98 0.00 |__mysqld
Average: 1000 - 74674 0.00 174291.26 0.00 |__mysqld
11:56:18 PM 1000 - 74770 124928.00 74688.00 0.00 |__mysqld
11:56:17 PM 1000 - 74770 124603.77 73358.49 0.00 |__mysqld
Average: 1000 - 74770 124761.17 74003.88 0.00 |__mysqld
由上可知：74770这个线程占用的io比较高
4.8、分析这个线程在干什么？
Shell> perf trace -t 74770 -o /tmp/tmp_aa.pstrace
Shell> cat /tmp/tmp_aa.pstrace
2850.656 ( 1.915 ms): futex(uaddr: 0x653ae9c4, op: WAIT|PRIVATE_FLAG, val: 1) = 0
2852.572 ( 0.001 ms): futex(uaddr: 0x653ae990, op: WAKE|PRIVATE_FLAG, val: 1) = 0
2852.601 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2852.690 ( 0.040 ms): write(fd: 159, buf: 0xd7a30020, count: 65536) = 65536
2852.796 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2852.798 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f58) = 0
2852.939 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f38) = 0
2852.950 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2852.977 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2853.029 ( 0.035 ms): write(fd: 64, buf: 0xcd51e020, count: 65536) = 65536
2853.164 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2853.167 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f58) = 0
2853.302 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f38) = 0
Shell> cat /tmp/tmp_aa.pstrace
2850.656 ( 1.915 ms): futex(uaddr: 0x653ae9c4, op: WAIT|PRIVATE_FLAG, val: 1) = 0
2852.572 ( 0.001 ms): futex(uaddr: 0x653ae990, op: WAKE|PRIVATE_FLAG, val: 1) = 0
2852.601 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2852.690 ( 0.040 ms): write(fd: 159, buf: 0xd7a30020, count: 65536) = 65536
2852.796 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2852.798 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f58) = 0
2852.939 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f38) = 0
2852.950 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2852.977 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2853.029 ( 0.035 ms): write(fd: 64, buf: 0xcd51e020, count: 65536) = 65536
2853.164 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68) = 0
2853.167 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f58) = 0
2853.302 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f38) = 0
由上可知：目前这个线程在写入多个文件，fd为文件句柄，文件句柄号有64、159
4.9、查看这个文件句柄是什么
shell> lsof -p 73739|grep 159u
mysqld 73739 mysql 159u REG 8,0 212143246 7046482357 /mysql/mysqldata/16320fff-5fd5-4c47-889a-a9e1a8591d0d/tmp/#7046482357 (deleted)
[root@mysql-4 ~]# lsof -p 73739|grep 64u
mysqld 73739 mysql 64u REG 8,0 211872724 6979323031 /mysql/mysqldata/16320fff-5fd5-4c47-889a-a9e1a8591d0d/tmp/#6979323031 (deleted)
mysqld 73739 mysql 159u REG 8,0 212143246 7046482357 /mysql/mysqldata/16320fff-5fd5-4c47-889a-a9e1a8591d0d/tmp/#7046482357 (deleted)
[root@mysql-4 ~]# lsof -p 73739|grep 64u
mysqld 73739 mysql 64u REG 8,0 211872724 6979323031 /mysql/mysqldata/16320fff-5fd5-4c47-889a-a9e1a8591d0d/tmp/#6979323031 (deleted)
由上可知：这个线程在大量的写入临时文件
五、分析MySQL应用程序
5.1、查看当前的会话列表
mysql> select * from information_schema.processlist where command !='sleep';
| 9 | pcms | 172.16.76.12:57596 | sysbench | Query | 67 | executing | select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc | 66477 | 0 | 0 |
| 9 | pcms | 172.16.76.12:57596 | sysbench | Query | 67 | executing | select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc | 66477 | 0 | 0 |
由上可知：目前这个sql已经执行了67s，且此sql使用了group by和order by，必然会产生io
5.2、通过线程号查询会话
mysql> select * from threads where thread_os_id=74770\G;
*************************** 1. row ***************************
THREAD_ID: 95
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 9
PROCESSLIST_USER: pcms
PROCESSLIST_HOST: 172.16.76.12
PROCESSLIST_DB: sysbench
PROCESSLIST_COMMAND: Query
PROCESSLIST_TIME: 91
PROCESSLIST_STATE: NULL
PROCESSLIST_INFO: select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc
PARENT_THREAD_ID: 1
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: TCP/IP
THREAD_OS_ID: 74770
RESOURCE_GROUP: USR_default
1 row in set (0.00 sec)
*************************** 1. row ***************************
THREAD_ID: 95
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 9
PROCESSLIST_USER: pcms
PROCESSLIST_HOST: 172.16.76.12
PROCESSLIST_DB: sysbench
PROCESSLIST_COMMAND: Query
PROCESSLIST_TIME: 91
PROCESSLIST_STATE: NULL
PROCESSLIST_INFO: select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc
PARENT_THREAD_ID: 1
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: TCP/IP
THREAD_OS_ID: 74770
RESOURCE_GROUP: USR_default
1 row in set (0.00 sec)
由上可知：通过查询threads表可以进行验证，该线程在频繁创建临时表的原因就来源于此sql
5.3、查看该sql语句的执行计划，进行进一步认证
mysql> explain select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc\G;
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: a
partitions: NULL
type: ALL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: 1
filtered: 100.00
Extra: Using temporary; Using filesort
*************************** 2. row ***************************
id: 1
select_type: SIMPLE
table: b
partitions: NULL
type: eq_ref
possible_keys: PRIMARY
key: PRIMARY
key_len: 4
ref: sysbench.a.id
rows: 1
filtered: 100.00
Extra: NULL
2 rows in set, 2 warnings (0.00 sec)
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: a
partitions: NULL
type: ALL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: 1
filtered: 100.00
Extra: Using temporary; Using filesort
*************************** 2. row ***************************
id: 1
select_type: SIMPLE
table: b
partitions: NULL
type: eq_ref
possible_keys: PRIMARY
key: PRIMARY
key_len: 4
ref: sysbench.a.id
rows: 1
filtered: 100.00
Extra: NULL
2 rows in set, 2 warnings (0.00 sec)
由上可知：该sql的执行计划用到了临时表及临时文件，符合
5.4、查看全局状态进一步进行确认
mysql> show global status like '%tmp%';
+-------------------------+-------+
| Variable_name | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 3 |
| Created_tmp_files | 22 |
| Created_tmp_tables | 8 |
+-------------------------+-------+
+-------------------------+-------+
| Variable_name | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 3 |
| Created_tmp_files | 22 |
| Created_tmp_tables | 8 |
+-------------------------+-------+
多执行几次，可以看出tmp_files和tmp_disk_tables的值在增长，证明在大量的创建临时文件及磁盘临时表，符合该线程的行为
六、故障处理
通过上述的一系列排查，我们已经分析出来：目前sda磁盘的io使用率最高，且mysqld程序占用的最多。
通过排查有一个线程在频繁的创建临时表或临时文件且通过登录mysql排查会话及线程视图可以找到是由某一个慢sql导致的。
查看此慢sql的执行计划也会创建临时表和临时文件符合我们之前排查的预期。
此时我们就需要针对此慢sql进行优化。
慢sql优化完成后可以进行io的继续观察，看io是否有下降。
七、代码分析
我们可以使用pstack进行跟踪线程号，获取当前的线程堆栈信息。切记pstack会调用gdb进行debug调试
shell> pstack 74770 >/tmp/74770.pstack
Thread 1 (process 74770):
#0 ha_innobase::general_fetch (this=0xea654228, buf=0xea662028 "\212t\317\030\002", direction=1, match_mode=0 ) at /builds/naiwei.fang/percona-server/storage/innobase/handler/ha_innodb.cc:11159
#1 0x0000000000d9913c in handler::ha_rnd_next (this=0xea654228, buf=0xea662028 "\212t\317\030\002") at /build
s/naiwei.fang/percona-server/sql/handler.cc:3173
#2 0x0000000000f77db0 in TableScanIterator::Read (this=0xd256d5e8) at /builds/naiwei.fang/percona-server/sql/
row_iterator.h:208
#3 0x000000000124c714 in WriteRowsToChunks (xxhash_seed=899339, write_to_build_chunk=true, write_rows_with_nu
ll_in_join_key=false, join_key_buffer=0xd01fdb98, tables_to_get_rowid_for=0, chunks=0xd01fdb58, join_condition
s=..., tables=..., iterator=0xd256d5e8, thd=0xdb888000) at /builds/naiwei.fang/percona-server/sql/hash_join_it
erator.cc:282
#4 HashJoinIterator::BuildHashTable (this=this@entry=0xd01fd028) at /builds/naiwei.fang/percona-server/sql/ha
sh_join_iterator.cc:495
#5 0x000000000124c8ac in Init (this=0xd01fd028) at /builds/naiwei.fang/percona-server/sql/hash_join_iterator.
cc:203
#6 HashJoinIterator::Init (this=0xd01fd028) at /builds/naiwei.fang/percona-server/sql/hash_join_iterator.cc:1
45
#7 0x00000000010eca14 in Query_expression::ExecuteIteratorQuery (this=0xdec3a8b8, thd=thd@entry=0xdb888000) a
t /builds/naiwei.fang/percona-server/sql/sql_union.cc:1224
#8 0x00000000010ecccc in Query_expression::execute (this=this@entry=0xdec3a8b8, thd=thd@entry=0xdb888000) at
/builds/naiwei.fang/percona-server/sql/sql_union.cc:1284
#9 0x0000000001083db0 in Sql_cmd_dml::execute_inner (this=0xd256bcb0, thd=0xdb888000) at /builds/naiwei.fang/
percona-server/sql/sql_select.cc:791
#10 0x000000000108cac8 in Sql_cmd_dml::execute (this=0xd256bcb0, thd=0xdb888000) at /builds/naiwei.fang/percon
a-server/sql/sql_select.cc:575
#11 0x00000000010384e8 in mysql_execute_command (thd=thd@entry=0xdb888000, first_level=first_level@entry=true)
at /builds/naiwei.fang/percona-server/sql/sql_parse.cc:4677
#12 0x000000000103b314 in dispatch_sql_command (thd=thd@entry=0xdb888000, parser_state=parser_state@entry=0xff
f7bd4735b0, update_userstat=update_userstat@entry=false) at /builds/naiwei.fang/percona-server/sql/sql_parse.c
c:5273
#13 0x000000000103ccf0 in dispatch_command (thd=thd@entry=0xdb888000, com_data=0xffffb467c4d0, com_data@entry=
0xfff7bd474640, command=COM_QUERY) at /builds/naiwei.fang/percona-server/sql/sql_parse.cc:1938
#14 0x000000000103da40 in do_command (thd=thd@entry=0xdb888000) at /builds/naiwei.fang/percona-server/sql/sql_
parse.cc:1386
#15 0x0000000001152ca8 in handle_connection (arg=arg@entry=0xda53ab10) at /builds/naiwei.fang/percona-server/s
ql/conn_handler/connection_handler_per_thread.cc:307
#16 0x00000000022bc3ec in pfs_spawn_thread (arg=<optimized out>) at /builds/naiwei.fang/percona-server/storage
/perfschema/pfs.cc:2899
#17 0x0000ffffb43c7c48 in start_thread () from /lib64/libpthread.so.0
#18 0x0000ffffb3c0f600 in thread_start () from /lib64/libc.so.6
Thread 1 (process 74770):
#0 ha_innobase::general_fetch (this=0xea654228, buf=0xea662028 "\212t\317\030\002", direction=1, match_mode=0 ) at /builds/naiwei.fang/percona-server/storage/innobase/handler/ha_innodb.cc:11159
#1 0x0000000000d9913c in handler::ha_rnd_next (this=0xea654228, buf=0xea662028 "\212t\317\030\002") at /build
s/naiwei.fang/percona-server/sql/handler.cc:3173
#2 0x0000000000f77db0 in TableScanIterator::Read (this=0xd256d5e8) at /builds/naiwei.fang/percona-server/sql/
row_iterator.h:208
#3 0x000000000124c714 in WriteRowsToChunks (xxhash_seed=899339, write_to_build_chunk=true, write_rows_with_nu
ll_in_join_key=false, join_key_buffer=0xd01fdb98, tables_to_get_rowid_for=0, chunks=0xd01fdb58, join_condition
s=..., tables=..., iterator=0xd256d5e8, thd=0xdb888000) at /builds/naiwei.fang/percona-server/sql/hash_join_it
erator.cc:282
#4 HashJoinIterator::BuildHashTable (this=this@entry=0xd01fd028) at /builds/naiwei.fang/percona-server/sql/ha
sh_join_iterator.cc:495
#5 0x000000000124c8ac in Init (this=0xd01fd028) at /builds/naiwei.fang/percona-server/sql/hash_join_iterator.
cc:203
#6 HashJoinIterator::Init (this=0xd01fd028) at /builds/naiwei.fang/percona-server/sql/hash_join_iterator.cc:1
45
#7 0x00000000010eca14 in Query_expression::ExecuteIteratorQuery (this=0xdec3a8b8, thd=thd@entry=0xdb888000) a
t /builds/naiwei.fang/percona-server/sql/sql_union.cc:1224
#8 0x00000000010ecccc in Query_expression::execute (this=this@entry=0xdec3a8b8, thd=thd@entry=0xdb888000) at
/builds/naiwei.fang/percona-server/sql/sql_union.cc:1284
#9 0x0000000001083db0 in Sql_cmd_dml::execute_inner (this=0xd256bcb0, thd=0xdb888000) at /builds/naiwei.fang/
percona-server/sql/sql_select.cc:791
#10 0x000000000108cac8 in Sql_cmd_dml::execute (this=0xd256bcb0, thd=0xdb888000) at /builds/naiwei.fang/percon
a-server/sql/sql_select.cc:575
#11 0x00000000010384e8 in mysql_execute_command (thd=thd@entry=0xdb888000, first_level=first_level@entry=true)
at /builds/naiwei.fang/percona-server/sql/sql_parse.cc:4677
#12 0x000000000103b314 in dispatch_sql_command (thd=thd@entry=0xdb888000, parser_state=parser_state@entry=0xff
f7bd4735b0, update_userstat=update_userstat@entry=false) at /builds/naiwei.fang/percona-server/sql/sql_parse.c
c:5273
#13 0x000000000103ccf0 in dispatch_command (thd=thd@entry=0xdb888000, com_data=0xffffb467c4d0, com_data@entry=
0xfff7bd474640, command=COM_QUERY) at /builds/naiwei.fang/percona-server/sql/sql_parse.cc:1938
#14 0x000000000103da40 in do_command (thd=thd@entry=0xdb888000) at /builds/naiwei.fang/percona-server/sql/sql_
parse.cc:1386
#15 0x0000000001152ca8 in handle_connection (arg=arg@entry=0xda53ab10) at /builds/naiwei.fang/percona-server/s
ql/conn_handler/connection_handler_per_thread.cc:307
#16 0x00000000022bc3ec in pfs_spawn_thread (arg=<optimized out>) at /builds/naiwei.fang/percona-server/storage
/perfschema/pfs.cc:2899
#17 0x0000ffffb43c7c48 in start_thread () from /lib64/libpthread.so.0
#18 0x0000ffffb3c0f600 in thread_start () from /lib64/libc.so.6
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK