从操作系统层面去分析慢SQL的一种思路
Contents
一 背景说明
两台机器，server1跑数据库和应用；server2向server1的应用执行一个查询请求，并持续监控该请求延迟；
以前，都是从DBA的视角分析和解决问题，定位发现慢SQL，分析原因，执行SQL优化改写，解决问题。
今天，尝试从操作系统层面去分析性能问题的另外一种思路。
server1: 172.16.17.7，4C 8G；
server2: 172.16.11.36，24C 64G；
二 分析步骤和思路
1 server1启动container
# 先下载对应的文件和代码： # git clone https://github.com/feiskyer/linux-perf-examples [root@guoxin7 ~]# git clone https://github.com/feiskyer/linux-perf-examples 正克隆到 'linux-perf-examples'... remote: Enumerating objects: 340, done. remote: Total 340 (delta 0), reused 0 (delta 0), pack-reused 340 接收对象中: 100% (340/340), 476.49 KiB | 0 bytes/s, done. 处理 delta 中: 100% (154/154), done. [root@guoxin7 ~]# # cd linux-perf-examples/mysql-slow [root@guoxin7 ~]# cd linux-perf-examples/mysql-slow/ [root@guoxin7 mysql-slow]# pwd /root/linux-perf-examples/mysql-slow [root@guoxin7 mysql-slow]# ll 总用量 36 -rwxr-xr-x 1 root root 2604 3月 22 16:41 app.py -rw-r--r-- 1 root root 445 3月 22 16:41 dataservice.py -rw-r--r-- 1 root root 143 3月 22 16:41 Dockerfile -rw-r--r-- 1 root root 126 3月 22 16:41 Dockerfile.dataservice -rw-r--r-- 1 root root 189 3月 22 16:41 Dockerfile.mysql -rw-r--r-- 1 root root 945 3月 22 16:41 Makefile -rw-r--r-- 1 root root 1336 3月 22 16:41 mysqld.cnf -rw-r--r-- 1 root root 803 3月 22 16:41 README.md -rw-r--r-- 1 root root 657 3月 22 16:41 tables.sql [root@guoxin7 mysql-slow]# # make run [root@guoxin7 mysql-slow]# make run docker run --name=mysql -itd -p 10000:80 -m 800m feisky/mysql:5.6 22af305e0ae9712e5c0cfb0eeccd172a95824b79f33e5f228b7c2dc3e35fb14c docker run --name=dataservice -itd --privileged feisky/mysql-dataservice 50e0234b81be4d456b0780d05773328ed16f49f3c89578cb8c37a7d75d6d2ab8 docker run --name=app --network=container:mysql -itd feisky/mysql-slow e15f238546d93833741f1ae487ad10290842092d246340481126ffe07ac3ef16 [root@guoxin7 mysql-slow]# # 确定3个container正常运行 [root@guoxin7 mysql-slow]# docker ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES e15f238546d9 feisky/mysql-slow "python /app.py" 22 seconds ago Up 17 seconds app 50e0234b81be feisky/mysql-dataservice "python /dataservi..." 23 seconds ago Up 22 seconds dataservice 22af305e0ae9 feisky/mysql:5.6 "docker-entrypoint..." 24 seconds ago Up 23 seconds 3306/tcp, 0.0.0.0:10000->80/tcp mysql [root@guoxin7 mysql-slow]# # 验证服务：curl http://127.0.0.1:10000/ [root@guoxin7 mysql-slow]# curl http://127.0.0.1:10000/ Index Page[root@guoxin7 mysql-slow]# [root@guoxin7 mysql-slow]#
2 server1给名为mysql的container初始化数据
#该步骤可能需要一定的时间完成 [root@guoxin7 mysql-slow]# pwd /root/linux-perf-examples/mysql-slow [root@guoxin7 mysql-slow]# make init docker exec -i mysql mysql -uroot -P3306 < tables.sql curl http://127.0.0.1:10000/db/insert/products/10000 insert 10000 lines [root@guoxin7 mysql-slow]#
3 server2持续向server1发送服务请求，并监控延迟
# 把服务请求放到一个while循环里，并且间隔2秒，持续请求，并打印出服务响应的时间； [root@centos-master ~]# while true; do time curl http://172.16.17.7:10000/products/geektime;sleep 2; done; Got data: () in 0.5451030731201172 sec real 0m0.555s user 0m0.003s sys 0m0.005s Got data: () in 1.4194972515106201 sec real 0m1.431s user 0m0.004s sys 0m0.004s Got data: () in 1.1215379238128662 sec real 0m1.132s user 0m0.006s sys 0m0.002s Got data: () in 0.8462660312652588 sec real 0m0.857s user 0m0.004s sys 0m0.005s Got data: () in 0.9769577980041504 sec real 0m0.988s user 0m0.003s sys 0m0.005s Got data: () in 0.1878516674041748 sec real 0m0.199s user 0m0.006s sys 0m0.003s ^C [root@centos-master ~]#
从请求跟踪结果看到，服务的响应快时0.18秒就结束了，而慢的时候则要1秒多，这说明服务的响应时间不够稳定。
4 监控server1的CPU、IO指标
[root@guoxin7 ~]# top
top - 16:57:31 up 1 day, 6:01, 3 users, load average: 0.75, 0.96, 0.76
Tasks: 220 total, 2 running, 218 sleeping, 0 stopped, 0 zombie
%Cpu0 : 3.7 us, 9.0 sy, 0.0 ni, 51.8 id, 34.8 wa, 0.0 hi, 0.7 si, 0.0 st
%Cpu1 : 1.7 us, 6.7 sy, 0.0 ni, 80.1 id, 11.1 wa, 0.0 hi, 0.3 si, 0.0 st
%Cpu2 : 0.7 us, 10.0 sy, 0.0 ni, 79.6 id, 9.4 wa, 0.0 hi, 0.3 si, 0.0 st
%Cpu3 : 0.7 us, 0.7 sy, 0.0 ni, 92.6 id, 6.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 41037092 total, 35861428 free, 1870708 used, 3304956 buff/cache
KiB Swap: 8257532 total, 8257532 free, 0 used. 36242360 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
14813 polkitd 20 0 833756 59956 8036 S 16.3 0.1 0:20.00 mysqld --log_bin=on --sync_binlog=1
14941 root 20 0 24336 7256 2728 S 9.3 0.0 0:39.58 python /dataservice.py
1 root 20 0 191172 4068 2624 S 0.7 0.0 1:37.85 /usr/lib/systemd/systemd --switched-root --system --deserialize 22 查看系统的IO指标：iostat -dx 1;
[root@guoxin7 ~]# iostat -dx 1 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 0.00 1013.00 5.00 466224.00 164.00 916.28 10.22 9.84 9.62 54.60 0.77 78.40 scd0 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 1025.00 6.00 472368.00 172.00 916.66 10.22 9.72 9.51 45.50 0.76 78.40 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 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 0.00 383.00 18.00 152032.00 188.00 759.20 8.07 20.64 20.60 21.44 2.30 92.40 scd0 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 372.00 17.00 145896.00 180.00 751.03 8.07 21.27 21.20 22.71 2.38 92.40 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 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 0.00 1349.00 0.00 69604.00 0.00 103.19 4.32 3.20 3.20 0.00 0.20 27.10 scd0 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 1348.00 0.00 69596.00 0.00 103.26 4.32 3.21 3.21 0.00 0.20 27.10 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 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 0.00 767.00 0.00 392704.00 0.00 1024.00 9.10 11.79 11.79 0.00 1.06 81.60 scd0 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 783.00 0.00 400896.00 0.00 1024.00 9.10 11.54 11.54 0.00 1.04 81.60 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 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 0.00 211.00 0.00 107728.00 0.00 1021.12 3.32 16.04 16.04 0.00 1.36 28.80 scd0 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 195.00 0.00 99536.00 0.00 1020.88 3.32 17.36 17.36 0.00 1.48 28.80 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 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 0.00 1.00 1.00 4.00 4.00 8.00 0.03 13.00 8.00 18.00 13.00 2.60 scd0 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 1.00 1.00 4.00 4.00 8.00 0.03 13.00 8.00 18.00 13.00 2.60 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 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 0.00 978.00 0.00 500432.00 0.00 1023.38 6.43 6.58 6.58 0.00 0.63 61.20 scd0 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 978.00 0.00 500432.00 0.00 1023.38 6.42 6.57 6.57 0.00 0.63 61.20 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 ^C [root@guoxin7 ~]#
跟踪mysqld进程的IO指标：pidstat -d -l -p 14813
[root@guoxin7 ~]# pidstat -d -l -p 14813 1 Linux 3.10.0-1160.59.1.el7.x86_64 (guoxin7) 2022年03月22日 _x86_64_ (4 CPU) 17时04分51秒 UID PID kB_rd/s kB_wr/s kB_ccwr/s Command 17时04分52秒 999 14813 0.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时04分53秒 999 14813 242946.53 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时04分54秒 999 14813 168004.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时04分55秒 999 14813 0.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时04分56秒 999 14813 87024.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时04分57秒 999 14813 0.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时04分58秒 999 14813 97792.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时04分59秒 999 14813 402640.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时05分00秒 999 14813 0.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时05分01秒 999 14813 396800.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时05分02秒 999 14813 103632.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时05分03秒 999 14813 0.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时05分04秒 999 14813 380416.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时05分05秒 999 14813 120016.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时05分06秒 999 14813 0.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 17时05分07秒 999 14813 302592.00 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 ^C 平均时间: 999 14813 143928.29 0.00 0.00 mysqld --log_bin=on --sync_binlog=1 [root@guoxin7 ~]#
其实，到这里的话，从DBA的视角来分析，此时，看到这些信息，大概能看出来，mysqld进程在执行一些慢SQL了，可以进入MySQL数据库里，执行show full processlist;查看慢SQL并分析了。
但是，这里，我们可以从操作系统的角度，继续分析一下该问题了。
5 跟踪mysqld进程的读写文件
strace -fp 14813；加上-f选项，可以跟踪看到进程里的线程的内核调用信息：
[root@guoxin7 ~]# strace -fp 14813 strace: Process 14813 attached with 22 threads [pid 15869] futex(0x55de811f6044, FUTEX_WAIT_PRIVATE, 371, NULL <unfinished ...> [pid 15653] rt_sigtimedwait([HUP QUIT ALRM TERM TSTP], NULL, NULL, 8 <unfinished ...> [pid 15652] restart_syscall(<... resuming interrupted futex ...> <unfinished ...> ... [pid 15869] read(37, "WVyYSro50pa8VH3knzlPDp5U51YZMsnX"..., 24576) = 24576 [pid 15869] read(37, "h8eOUppxAgkNCezmYTYZxw1cgv7A\10\0000q"..., 131072) = 131072 [pid 15869] read(37, "r3T249CjU2StnOLyHJdr0jBe0jAsb2WM"..., 20480) = 20480 [pid 15869] read(37, "YpdGvDesdyiaBBNMYcUqADdTRk92Shol"..., 131072) = 131072 [pid 15869] read(37, "A4RLFrKXd7LiD8S2Zss972xxklYt3YYk"..., 24576) = 24576 [pid 15869] read(37, "am0cVxqqD9WCU9QRV2Ad6QJ0v6PF67qP"..., 131072) = 131072 [pid 15869] read(37, "X7wofeSpni1jVpNDOvzlFSTkS2GAojGP"..., 20480) = 20480 [pid 15869] read(37, ^C"JZ31V0lkO5bnrXwDW3EoRPjvUwXQivG3"..., 131072) = 131072 strace: Process 15634 detached ... strace: Process 15869 detached [root@guoxin7 ~]#
看到mysqld进程14813在读写37号文件。
lsof -p 14813；查看进程打开file descriptor文件句柄信息：
[root@guoxin7 ~]# lsof -p 14813 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME mysqld 14813 polkitd cwd DIR 253,0 239 12182228 /var/lib/mysql mysqld 14813 polkitd rtd DIR 0,37 28 201445261 / ... mysqld 14813 polkitd 34u REG 253,0 0 201453422 /var/lib/mysql/mysql/event.MYD mysqld 14813 polkitd 36u REG 253,0 105472 42706 /var/lib/mysql/test/products.MYI mysqld 14813 polkitd 37u REG 253,0 512440000 42714 /var/lib/mysql/test/products.MYD [root@guoxin7 ~]#
MySQL在读写/var/lib/mysql/test/products.MYD，熟悉MySQL数据库的话，就可以看出个大概了。
6 跟踪分析系统缓存情况
使用vmstat跟踪系统的内存情况：
[root@guoxin7 ~]# vmstat 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 0 0 36238072 0 2928668 0 0 6804 484 95 21 11 2 85 2 0
0 1 0 36237476 0 2929080 0 0 512 0 1725 667 0 0 98 2 0
1 1 0 36453100 0 2713112 0 0 288204 68 3588 1869 2 11 78 10 0
0 0 0 36450888 0 2715296 0 0 1816 144 2480 1248 1 1 92 6 0
1 0 0 36279616 0 2886488 0 0 171520 0 1817 1106 1 2 87 10 0
1 0 0 36137124 0 3029224 0 0 328840 4 2733 1692 1 8 78 13 0
0 0 0 36326932 0 2838596 0 0 125616 0 4977 4699 3 4 80 13 0
0 1 0 36147444 0 3018600 0 0 179712 0 2079 982 1 3 92 4 0
0 0 0 35828540 0 3339104 0 0 320720 428 2956 1629 1 4 81 14 0
0 0 0 36454524 0 2712964 0 0 4 4 1979 706 0 6 94 0 0
0 1 0 36323364 0 2845236 0 0 132404 0 2287 996 1 2 90 8 0
0 0 0 35953572 0 3214948 0 0 369848 0 3118 1645 2 4 90 4 0
0 0 0 36454432 0 2712992 0 0 4 4 1940 725 0 6 93 0 0
1 0 0 35958036 0 3207912 0 0 495104 0 3362 1890 1 6 85 8 0
^C
[root@guoxin7 ~]# free -m
total used free shared buff/cache available
Mem: 40075 1823 35107 2436 3143 35395
Swap: 8063 0 8063
[root@guoxin7 ~]# free -m
total used free shared buff/cache available
Mem: 40075 1824 35589 2444 2661 35437
Swap: 8063 0 8063
[root@guoxin7 ~]# 从上，我们可以看到系统缓存page cache信息的明显变化，cache列的系统缓存，io列中的bi变动非常大。
free -m看到的结果中，buff/cache抖动也非常明显。
说明系统缓存不断的在剧烈变化。
7 查看docker容器具体内容
[root@guoxin7 ~]# docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
e15f238546d9 feisky/mysql-slow "python /app.py" 38 minutes ago Up 38 minutes app
50e0234b81be feisky/mysql-dataservice "python /dataservi..." 38 minutes ago Up 38 minutes dataservice
22af305e0ae9 feisky/mysql:5.6 "docker-entrypoint..." 38 minutes ago Up 38 minutes 3306/tcp, 0.0.0.0:10000->80/tcp mysql
[root@guoxin7 ~]# docker exec -it dataservice /bin/bash
root@50e0234b81be:/# ls
bin boot dataservice.py dev etc home lib lib64 media mnt opt proc root run sbin srv sys tmp usr var
root@50e0234b81be:/# cat dataservice.py
#!/usr/bin/env python
# -*- coding: UTF-8 -*-
import time
filename = "/tmp/dataservice"
def write():
with open(filename, "w+") as f:
f.write("data")
def read():
with open(filename) as f:
return f.read()
def clean_cache():
with open("/proc/sys/vm/drop_caches", "w") as f:
f.write("1")
if __name__ == "__main__":
while True:
write()
clean_cache()
read()
time.sleep(3)
root@50e0234b81be:/# 原来dataservice这个容器在清理系统缓存。
8 停掉该container
[root@guoxin7 ~]# docker stop dataservice dataservice [root@guoxin7 ~]# docker ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES e15f238546d9 feisky/mysql-slow "python /app.py" 40 minutes ago Up 40 minutes app 22af305e0ae9 feisky/mysql:5.6 "docker-entrypoint..." 40 minutes ago Up 40 minutes 3306/tcp, 0.0.0.0:10000->80/tcp mysql [root@guoxin7 ~]# vmstat 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 0 0 35807660 0 3370024 0 0 6931 482 97 23 11 2 85 3 0 0 0 0 35807660 0 3370092 0 0 0 0 1386 607 0 0 100 0 0 0 0 0 35807536 0 3370092 0 0 0 0 1686 760 1 4 95 0 0 0 0 0 35806592 0 3370096 0 0 0 0 3575 3717 3 2 96 0 0 0 0 0 35806664 0 3370100 0 0 0 0 1774 809 1 5 94 0 0 0 0 0 35806664 0 3370100 0 0 0 0 1618 605 0 0 100 0 0 0 0 0 35806664 0 3370224 0 0 124 0 1707 780 1 4 94 2 0 0 0 0 35806568 0 3370224 0 0 0 0 1366 570 0 0 99 0 0 0 0 0 35806664 0 3370224 0 0 0 0 1779 770 1 4 95 0 0 0 0 0 35806600 0 3370224 0 0 0 0 1438 648 0 0 100 0 0 ^C [root@guoxin7 ~]#
停掉dataservice这个container之后，看到系统缓存基本维持不变。同时，客户端的服务请求也维持在稳定的响应延迟了：
[root@centos-master ~]# while true; do time curl http://172.16.17.7:10000/products/geektime;sleep 2; done; Got data: () in 0.17266535758972168 sec real 0m0.184s user 0m0.002s sys 0m0.006s Got data: () in 0.17386388778686523 sec real 0m0.186s user 0m0.007s sys 0m0.002s Got data: () in 0.1739194393157959 sec real 0m0.185s user 0m0.004s sys 0m0.005s ^C [root@centos-master ~]#
三小结和收获
从DBA的视角来看这个性能问题的话，从top和iostat以及pidstat -d -l -p mysql_pid 1;看出确实是数据库的进程“慢”的话，就会从数据库层面去分析并优化这个case了。
但是，这里提供了另外一个思路，从操作系统层面，通过strace -fp mysqld_pid；lsof -p mysqld_pid;以及vmstat 继续跟踪分析系统内存和mysqld进程在内核内部的系统调用和读写文件来分析问题。
当然，最后还可以继续优化那个SQL，给where条件中的查询字段加上index，这里略过并没有包含进来。
四 参考
倪朋飞老师的Linux性能优化实战，28 | 案例篇：一个SQL查询要15秒，这是怎么回事？
只是，我这里的演示环境，并不像倪朋飞老师环境的，查询需要15秒那么明显。
一条评论
Pingback: