28-案例篇：一个SQL查询要15秒，这是怎么回事？

当数据库出现性能问题时，该如何分析和定位它的瓶颈呢？
这是一个基于Python Flask的商品搜索应用案例
商品信息存在MySQL中，这个应用可以通过MySQL接口
根据客户端提供的商品名称，去数据库表中查询商品信息

案例

环境准备

# 服务端（192.168.1.6）
# 机器配置：2cpu，4GB内存
# 预先安装docker、sysstat、git、make、psmisc包

# 客户端（192.168.1.5）

# 案例说明
案例总共由三个容器组成
1. MySQL数据库应用
2. 商品搜索应用以
3. 数据处理的应用

其中商品搜索应用以HTTP的形式提供了一个接口
1. /：返回Index Pag
2. /db/insert/products/：插入指定数量的商品信息
3. /products/：查询指定商品的信息，并返回处理时间

在服务端，下载案例环境所需要的代码包，准备服务端环境

# 代码下载地址: https://alnk-blog-pictures.oss-cn-shenzhen.aliyuncs.com/blog-pictures/linux-perf-examples-master.zip

# 1. wget下载代码
[root@local_sa_192-168-1-6 ~]# wget https://alnk-blog-pictures.oss-cn-shenzhen.aliyuncs.com/blog-pictures/linux-perf-examples-master.zip

# 2. 解压
[root@local_sa_192-168-1-6 ~]# unzip linux-perf-examples-master.zip

# 3. 改名
[root@local_sa_192-168-1-6 ~]# mv linux-perf-examples-master linux-perf-examples

# 4. 编译运行
[root@local_sa_192-168-1-6 ~]# cd linux-perf-examples/mysql-slow

# 注意下面的随机字符串是容器ID，每次运行均会不同
[root@local_sa_192-168-1-6 ~]#  make run
docker run --name=mysql -itd -p 10000:80 -m 800m feisky/mysql:5.6
WARNING: Your kernel does not support swap limit capabilities or the cgroup is not mount
4156780da5be0b9026bcf27a3fa56abc15b8408e358fa327f472bcc5add4453f
docker run --name=dataservice -itd --privileged feisky/mysql-dataservice
f724d0816d7e47c0b2b1ff701e9a39239cb9b5ce70f597764c793b68131122bb
docker run --name=app --network=container:mysql -itd feisky/mysql-slow
81d3392ba25bb8436f6151662a13ff6182b6bc6f2a559fc2e9d873cd07224ab6

# 5. 检查 确认三个容器都处在运行UP状态
[root@local_sa_192-168-1-6 ~]# docker ps
CONTAINER ID   IMAGE                     COMMAND                CREATED           STATUS        PORTS    NAMES
63c0d2c6a4af   feisky/mysql-slow         "python /app.py"       About an hour ago Up 53 minutes          app
6c18207ee54b   feisky/mysql-dataservice  "python /dataservice…" About an hour ago Up 13 seconds          dataservice
57c79ec8d453   feisky/mysql:5.6          "docker-entrypoint.s…" About an hour ago Up 55 minutes 3306/tcp mysql

服务端，mysql初始化工作

# 1. 当看到下面这个输出时，说明MySQL初始化完成，可以接收外部请求了
[root@local_sa_192-168-1-6 ~]# docker logs -f mysql
...
2021-12-22 02:22:00 1 [Note] mysqld: ready for connections.
Version: '5.6.42-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server (GPL)

# 2. 商品搜索应用则是在10000端口监听
[root@local_sa_192-168-1-6 ~]# curl http://127.0.0.1:10000/
Index Page

# 3. 运行make init命令，初始化数据库，并插入10000条商品信息
# 需要等待十几分钟
[root@local_sa_192-168-1-6 mysql-slow]# pwd
/root/linux-perf-examples/mysql-slow

[root@local_sa_192-168-1-6 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@local_deploy_192-168-1-5 ~]# curl http://192.168.1.6:10000/products/geektime
Got data: () in 4.129796028137207 sec
##
这个接口返回的是空数据，而且处理时间超过4秒
这么慢的响应速度到底出了什么问题呢？
##
在具体分析前，为了避免在分析过程中客户端的请求结束，把curl命令放到一个循环里执行
[root@local_deploy_192-168-1-5 ~]# while true; do curl http://192.168.1.6:10000/products/geektime; sleep 1; done
Got data: () in 2.157280206680298 sec
Got data: () in 1.8675053119659424 sec
Got data: () in 2.502699375152588 sec

在服务端，运行top命令

[root@local_sa_192-168-1-6 ~]# top
top - 11:27:15 up 2 days, 22:13,  2 users,  load average: 1.23, 0.51, 0.30
Tasks: 125 total,   1 running,  66 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.0 us,  1.0 sy,  0.0 ni,  0.0 id, 99.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  0.3 us,  0.7 sy,  0.0 ni, 63.0 id, 36.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  4027996 total,  3104368 free,   754016 used,   169612 buff/cache
KiB Swap:  8388604 total,  8354036 free,    34568 used.  3066060 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
15190 polkitd   20   0  916996  63520  13564 S   0.7  1.6   1:17.84 mysqld
15404 root      20   0  669644 425548   8796 S   0.7 10.6   2:37.21 python
##
分析top输出，发现两个CPU的iowait都比较高
而具体到各个进程CPU使用率并不高
既然CPU的嫌疑不大，那问题应该还是出在了I/O上

在服务端，运行iostat命令

[root@local_sa_192-168-1-6 mysql-slow]# iostat -d -x 1
Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 	2021年12月22日 	_x86_64_	(2 CPU)
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               6.00     0.00  291.00    0.00 284680.00     0.00  1956.56     1.63    5.60    5.60    0.00   3.00  87.30
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   94.00    0.00 290312.00     0.00  6176.85     1.09   11.64   11.64    0.00   3.59  33.70
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
##
发现磁盘sda每秒的读数据为28MB，而I/O使用率高达87%，接近饱和
这说明，磁盘sda的读取确实碰到了性能瓶颈，I/O请求到底是哪些进程导致的呢?

在服务端，运行pidstat命令

# # -d 选项表示展示进程的I/O情况
[root@local_sa_192-168-1-6 mysql-slow]# pidstat -d 1
Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 	2021年12月22日 	_x86_64_	(2 CPU)
11时42分25秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
11时42分26秒   999     15190 323584.00      0.00      0.00  mysqld
##
分析输出
PID为15190的mysqld进程正在进行大量的读，而且读取速度是32MB/s，跟刚才iostat的发现差不多
I/O瓶颈的根源，就是mysqld进程
##
为什么mysqld会去读取大量的磁盘数据呢？
按照前面猜测，这有可能是个慢查询问题
可是，慢查询的现象大多是CPU使用率高（比如 100% ），但这里看到的却是I/O问题
这并不是一个单纯的慢查询问题，有必要分析一下MySQL读取的数据

分析进程的数据读取，用strace+ lsof组合

[root@local_sa_192-168-1-6 mysql-slow]# strace -f -p 15190
......
[pid 15441] read(39, "z5LlwdM9JJjhbrItzg9aStZrG1vgWFTn"..., 131072) = 131072
[pid 15441] read(39, "Aah3tAosXlxI8xwTi7qvt07IFVW35Mzu"..., 20480) = 20480
[pid 15441] read(39, "qln7yy2PkvPHSiY7rljE6U5oxw7h4qfB"..., 131072) = 131072
[pid 15441] read(39, "jiuyU0RiUPUONfIMBlmNHMbbeNU2CjM7"..., 24576) = 24576
[pid 15441] read(39, "enSTyq1XFDwxTlGCW2pkYREk0p70qYid"..., 131072) = 131072
[pid 15441] read(39, "dxthUzPKXETbuzcJwh1VvauYNjbXDwQN"..., 20480) = 20480
[pid 15441] read(39, "Ani3Gew31wQVg2hNgbN5aCuUHq7lzII3"..., 131072) = 131072
[pid 15441] read(39, "UIoExJQbW7MPJCdDDqy1gITisZ37bWBN"..., 24576) = 24576
[pid 15441] read(39, "K1k5W7kAQqyAtZAOPXeY28yom8Da15wn"..., 131072) = 131072
[pid 15441] read(39, "aKxPVhwdUCKHS5781cnWcM2yprupm8B0"..., 20480) = 20480
[pid 15441] read(39, "1Gjs8flUnYmie3neXD6iC8QGzFcMrv6G"..., 131072) = 131072
[pid 15441] read(39, "vdduAqDkRlEyvAXNWuCnKOChKHk80LbC"..., 24576)
......
##
线程15441正在读取大量数据，且读取文件的描述符编号为39
##
# lsof
# -p 参数需要指定进程号
[root@local_sa_192-168-1-6 mysql-slow]# lsof -p 15190
......
mysqld  15190 polkitd   39u   REG  253,0 512440000  92404435 /var/lib/mysql/test/products.MYD
##
mysqld进程确实打开了大量文件，而根据文件描述符（FD）的编号
描述符为39的是一个路径为/var/lib/mysql/test/products.MYD的文件
39后面的u示，mysqld以读写的方式访问文件
##
MYD文件，是MyISAM引擎用来存储表数据的文件
文件名就是数据表的名字
而这个文件的父目录，也就是数据库的名字
换句话说，mysqld在读取数据库test中的products表
##

在服务端，查看mysql容器中的文件

[root@local_sa_192-168-1-6 mysql-slow]# docker exec -it mysql ls /var/lib/mysql/test/
products.MYD  products.MYI  products.frm
##
MYD 文件用来存储表的数据
MYI 文件用来存储表的索引
frm 文件用来存储表的元信息（比如表结构）
##
这些文件到底是不是mysqld正在使用的数据库文件呢？
有没有可能是不再使用的旧数据呢？
查一下mysqld配置的数据路径即可
[root@local_sa_192-168-1-6 mysql-slow]#  docker exec -i -t mysql mysql -e 'show global variables like "%datadir%";'
+---------------+-----------------+
| Variable_name | Value           |
+---------------+-----------------+
| datadir       | /var/lib/mysql/ |
+---------------+-----------------+
##
既然已经找出了数据库和表，接下来要做的，就是弄清楚数据库中正在执行什么样的SQL了

在服务端，运行docker exec命令，进入MySQ 的命令行界面

[root@local_sa_192-168-1-6 mysql-slow]# docker exec -i -t mysql mysql
......
mysql>

##
执行show processlist命令，来查看当前正在执行的SQL语句
为了保证SQL语句不截断，可以执行show full processlist命令
mysql> show full processlist;
+------+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| Id   | User | Host            | db   | Command | Time | State        | Info                                                |
+------+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| 1134 | root | localhost       | NULL | Query   |    0 | init         | show full processlist                               |
| 1151 | root | 127.0.0.1:48258 | test | Query   |    2 | Sending data | select * from products where productName='geektime' |
+------+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
##
db 表示数据库的名字
Command 表示SQL类型
Time 表示执行时间
State 表示状态
Info 包含了完整的SQL语句
##
多执行几次show full processlist命令
可看到select * from products where productName='geektime'这条SQL语句的执行时间比较长
##
案例开始时，在客户端查询的产品名称http://192.168.0.10:10000/products/geektime
其中的geektime也符合这条查询语句的条件
##
MySQL的慢查询问题，很可能是没有利用好索引导致的，那这条查询语句是不是这样呢？
又该怎么确认，查询语句是否利用了索引呢？

在服务端，索引问题

## MySQL内置的explain命令，可以分析索引问题

# 切换到test库
mysql> use test

# 执行explain命令
mysql> explain select * from products where productName='geektime';
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
| id | select_type | table    | type | possible_keys | key  | key_len | ref  | rows  | Extra       |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
|  1 | SIMPLE      | products | ALL  | NULL          | NULL | NULL    | NULL | 10000 | Using where |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
##
select_type 表示查询类型，而这里的SIMPLE表示此查询不包括UNION查询或者子查询
table 表示数据表的名字，这里是products
type 表示查询类型，这里的ALL表示全表查询，但索引查询应该是index类型才对
possible_keys 表示可能选用的索引，这里是NULL
key 表示确切会使用的索引，这里也是NULL
rows 表示查询扫描的行数，这里是10000
##
根据这些信息，可以确定，这条查询语句压根儿没有使用索引
所以查询时，会扫描全表，并且扫描行数高达10000行
响应速度那么慢也就难怪了
##
## 建立索引
# 1. 查询products表的结构
mysql> show create table products\G;
*************************** 1. row ***************************
       Table: products
Create Table: CREATE TABLE `products` (
  `id` int(11) NOT NULL,
  `productCode` text NOT NULL COMMENT '产品代码',
  `productName` text NOT NULL COMMENT '产品名称',
  `productLine` text NOT NULL COMMENT '产品线',
  `productScale` text NOT NULL,
  `productVendor` text NOT NULL,
  `productDescription` text NOT NULL,
  `quantityInStock` smallint(6) NOT NULL COMMENT '库存',
  `buyPrice` decimal(10,2) NOT NULL COMMENT '价格',
  `MSRP` decimal(10,2) NOT NULL COMMENT '建议零售价',
  PRIMARY KEY (`id`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC
1 row in set (0.00 sec)

# 2. 创建索引
# 需要等待几分钟
mysql>  CREATE INDEX products_index ON products (productName(64));
Query OK, 10000 rows affected (2 min 28.58 sec)
Records: 10000  Duplicates: 0  Warnings: 0

在客户端，再次访问

[root@local_deploy_192-168-1-5 ~]# while true; do curl http://192.168.1.6:10000/products/geektime; sleep 1; done
Got data: () in 0.04254269599914551 sec
Got data: () in 0.001356363296508789 sec
Got data: () in 0.001417398452758789 sec
Got data: () in 0.0012705326080322266 sec

##
查询时间已经从4秒缩短到了1毫秒
没有索引果然就是这次性能问题的罪魁祸首，解决了索引，就解决了查询慢的问题

案例思考

对于这个案例，还有一点想说明一下
10000条数据，按理说这个配置的数据库就算没有索引，也不需要4s才能查询一条数据

案例开始时，启动的几个容器应用
除了MySQL和商品搜索应用外，还有一个DataService应用
实际上，DataService 是一个严重影响 MySQL 性能的干扰应用
抛开上述索引优化方法不说，这个案例还有一种优化方法，也就是停止 DataService 应用

在服务端，删除索引

[root@local_sa_192-168-1-6 mysql-slow]# docker exec -i -t mysql mysql
....
mysql> use test;
mysql> DROP INDEX products_index ON products;

在客户端重新访问

[root@local_deploy_192-168-1-5 ~]# while true; do curl http://192.168.1.6:10000/products/geektime; sleep 1; done
Got data: () in 2.177647829055786 sec
Got data: () in 1.6284666061401367 sec
##
处理时间变慢了

在服务端停止dataservice应用

[root@local_sa_192-168-1-6 ~]# docker stop dataservice

在客户端查看访问时间

## 优化效果还是非常明显的
Got data: () in 0.08756494522094727 sec
Got data: () in 0.08786535263061523 sec
Got data: () in 0.09025883674621582 sec
Got data: () in 0.090484619140625 sec
Got data: () in 0.08662676811218262 sec

在服务端，运行vmstat命令

[root@local_sa_192-168-1-6 ~]# 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  1  34568 2574496      0 676976    0    0   938    81   20   35  0  0 98  1  0
 1  0  34568 2574244      0 677472    0    0   476     0  550  667  2  4 73 22  0
 0  1  34568 2574244      0 677472    0    0     0    16  107  153  1  1 97  2  0
 ##
磁盘读（bi）和iowait（wa）刚开始还是挺大的，但没过多久，就都变成了0 
换句话说，I/O 瓶颈消失了

小结

查看dataservice.py的源码，发现DataService实际上是在读写一个仅包括"data"字符串的小文件

不过在读取文件前，它会先把/proc/sys/vm/drop_caches改成 1

[root@local_sa_192-168-1-6 mysql-slow]# pwd
/root/linux-perf-examples/mysql-slow

[root@local_sa_192-168-1-6 mysql-slow]# ls
app.py  dataservice.py  Dockerfile  Dockerfile.dataservice  Dockerfile.mysql  Makefile  mysqld.cnf  README.md  tables.sql

[root@local_sa_192-168-1-6 mysql-slow]# 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)

posted @ 2021-12-22 14:14 李成果阅读(310) 评论(0) 编辑收藏举报

会员力量，点亮园子希望

刷新页面返回顶部

Alnk

邮箱:1029612787@qq.com

28-案例篇：一个SQL查询要15秒，这是怎么回事？

案例

案例思考

小结

公告