案例
这是⼀个基于 Python Flask 的商品搜索应⽤,商品信息存在 MySQL 中。这个应
⽤可以通过 MySQL 接⼝,根据客户端提供的商品名称,去数据库表中查询商品信息。
准备
- 机器配置:2 CPU,8GB 内存
- 预先安装 docker、sysstat 、git、make 等⼯具,如 apt installdocker.io sysstat make git
- git ⽤来拉取本次案例所需脚本,这些脚本存储在 Github 代码仓库
中; - 最后的 make 则是⼀个常⽤构建⼯具,这⾥⽤来运⾏今天的案例
- git ⽤来拉取本次案例所需脚本,这些脚本存储在 Github 代码仓库
案例总共由三个容器组成,包括⼀个 MySQL 数据库应⽤、⼀个商品搜索应⽤以及⼀个数据处理的应⽤。其中,商品搜索应⽤以 HTTP 的形式提供了⼀个接⼝:
- /:返回 Index Page;
- /db/insert/products/:插⼊指定数量的商品信息;
- /products/:查询指定商品的信息,并返回处理时间。
今天的案例需要两台虚拟机,其中⼀台作为案例分析的⽬标机器,运⾏ Flask 应⽤,它的 IP 地址是 192.168.0.10;另⼀台则是作为客户端,请求单词的热度
接下来,打开两个终端,分别 SSH 登录到这两台虚拟机中,并在第⼀台虚拟机中安装上述⼯具。
分析
⾸先,我们在第⼀个终端中执⾏下⾯命令,拉取本次案例所需脚本:
$ git clone https://github.com/feiskyer/linux-perf-examples
$ cd linux-perf-examples/mysql-slow
接着,执⾏下⾯的命令,运⾏本次的⽬标应⽤
# 注意下⾯的随机字符串是容器ID,每次运⾏均会不同,并且你不需要关注它,因为我们只会⽤到名字
$ 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 mounted. Memory limited without swap.
4156780da5be0b9026bcf27a3fa56abc15b8408e358fa327f472bcc5add4453f
docker run --name=dataservice -itd --privileged feisky/mysql-dataservice
f724d0816d7e47c0b2b1ff701e9a39239cb9b5ce70f597764c793b68131122bb
docker run --name=app --network=container:mysql -itd feisky/mysql-slow
81d3392ba25bb8436f6151662a13ff6182b6bc6f2a559fc2e9d873cd07224ab6
然后,再运⾏ docker ps 命令,确认三个容器都处在运⾏(Up)状态:
$ docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
9a4e3c580963 feisky/mysql-slow "python /app.py" 42 seconds ago Up 36 seconds app
2a47aab18082 feisky/mysql-dataservice "python /dataservice…" 46 seconds ago Up 41 seconds dataservice
4c3ff7b24748 feisky/mysql:5.6 "docker-entrypoint.s…" 47 seconds ago Up 46 seconds
MySQL 数据库的启动过程,需要做⼀些初始化⼯作,这通常需要花费⼏分钟时间。你可以运⾏ docker logs 命令,查看它的启动过程。
当你看到下⾯这个输出时,说明 MySQL 初始化完成,可以接收外部请求了:
$ docker logs -f mysql
...
... [Note] mysqld: ready for connections.
Version: '5.6.42-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 MySQL Community Server (GPL)
⽽商品搜索应⽤则是在 10000 端⼝监听。你可以按 Ctrl+C ,停⽌ docker logs 命令;然后,执⾏下⾯的命令,确认它也已经正常运⾏。如果⼀切正常,你会看到 Index Page 的输出:
$ curl http://127.0.0.1:10000/
Index Page
接下来,运⾏ make init 命令,初始化数据库,并插⼊ 10000 条商品信息。这个过程⽐较慢。耐⼼等待⼀段时间后,你会看到如下的输出:
$ 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
接着,我们切换到第⼆个终端,访问⼀下商品搜索的接⼝,看看能不能找到想要的商品。执⾏如下的 curl 命令:
$ curl http://192.168.0.10:10000/products/geektime
Got data: () in 15.364538192749023 sec
稍等⼀会⼉,你会发现,这个接⼝返回的是空数据,⽽且处理时间超过15 秒。这么慢的响应速度让⼈⽆法忍受,到底出了什么问题呢?
既然今天用了MySQL,你估计会猜到是慢查询的问题
不过别急,在具体分析前,为了避免在分析过程重客户端的请求结束,我们把curl命令放到一个循环里执行。同时,为了避免给系统过大压力,我们设置在每次查询之后,都先等待5s,然后再开始新的请求。即终端二中:
$ while true; do curl http://192.168.0.10:10000/products/geektime; sleep 5; done
接下来,重新回到终端一种,分析接口响应速度慢的原因。不过,重回终端一后,你会发现系统响应也变慢了,随便执行一个命令,都得停顿一会儿才能看到输出。
因此,我们需要先观察一下系统的资源使用情况,比如CPU、内存和磁盘IO等。
首先,我们在终端一执行top命令,分析系统的CPU使用情况:
$ top
top - 12:02:15 up 6 days, 8:05, 1 user, load average: 0.66, 0.72, 0.59
Tasks: 137 total, 1 running, 81 sleeping, 0 stopped, 0 zombie
%Cpu0 : 0.7 us, 1.3 sy, 0.0 ni, 35.9 id, 62.1 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 0.3 us, 0.7 sy, 0.0 ni, 84.7 id, 14.3 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 8169300 total, 7238472 free, 546132 used, 384696 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 7316952 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
27458 999 20 0 833852 57968 13176 S 1.7 0.7 0:12.40 mysqld
27617 root 20 0 24348 9216 4692 S 1.0 0.1 0:04.40 python
1549 root 20 0 236716 24568 9864 S 0.3 0.3 51:46.57 python3
22421 root 20 0 0 0 0 I 0.3 0.0 0:01.16 kworker/u
观察top的输出,我们发现,两个CPU的iowwait都比较高,特别是CPU0,iowait已经超过60%。而具体到各个进程,CPU使用率并不高,最高也只有1.7%
既然CPU的嫌疑不大,那问题还是出现在了IO上。。我们仍然在第⼀个终端,按下 Ctrl+C,停⽌ top 命令;然后,执⾏下⾯的 iostat 命令,看看有没有 I/O 性能问题:
$ iostat -d -x 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
...
sda 273.00 0.00 32568.00 0.00 0.00 0.00 0.00 0.00 7.90 0.00 1.16 119.30 0.00 3.56 97.20
上面可以看出,磁盘sda每秒的读数据为32MB,而IO使用率搞到97%,接近饱和,这说明,磁盘sda的读取确实碰到了性能瓶颈。
那要怎么知道,这些IO请求到底是由哪些进程导致的呢?
- 在终端⼀中,按下Ctrl+C 停⽌ iostat 命令,然后运⾏下⾯的 pidstat 命令,观察进程的 I/O 情况:
# -d 选项表示展示进程的 I/O 情况
$ pidstat -d 1
12:04:11 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
12:04:12 999 27458 32640.00 0.00 0.00 0 mysqld
12:04:12 0 27617 4.00 4.00 0.00 3 python
12:04:12 0 27864 0.00 4.00 0.00 0 systemd-journal
从 pidstat 的输出可以看到,PID 为 27458 的 mysqld 进程正在进⾏⼤量的读,⽽且读取速度是 32 MB/s,跟刚才 iostat 的发现⼀致。两个结果⼀对⽐,我们⾃然就找到了磁盘 I/O 瓶颈的根源,即 mysqld 进程。
不过,这事⼉还没完。我们⾃然要怀疑⼀下,为什么 mysqld 会去读取⼤量的磁盘数据呢?按照前⾯猜测,我们提到过,这有可能是个慢查询问题。
但是,慢查询的现象大多数是CPU使用率高(比如100%),但这里看到的确是IO问题。看来,这并不是一个单纯的慢查询问题,我们有必要分析一下MySQL读取的数据。
要分析进程的数据读取,需要strace+lsof
接下来,还是在终端⼀中,执⾏ strace 命令,并且指定 mysqld 的进程号 27458。我们知道,MySQL 是⼀个多线程的数据库应⽤,为了不漏掉这些线程的数据读取情况,你要记得在执⾏ stace 命令时,加上 -f 参数:
$ strace -f -p 27458
[pid 28014] read(38, "934EiwT363aak7VtqF1mHGa4LL4Dhbks"..., 131072) = 131072
[pid 28014] read(38, "hSs7KBDepBqA6m4ce6i6iUfFTeG9Ot9z"..., 20480) = 20480
[pid 28014] read(38, "NRhRjCSsLLBjTfdqiBRLvN9K6FRfqqLm"..., 131072) = 131072
[pid 28014] read(38, "AKgsik4BilLb7y6OkwQUjjqGeCTQTaRl"..., 24576) = 24576
[pid 28014] read(38, "hFMHx7FzUSqfFI22fQxWCpSnDmRjamaW"..., 131072) = 131072
[pid 28014] read(38, "ajUzLmKqivcDJSkiw7QWf2ETLgvQIpfC"..., 20480) = 20480
观察一会,你会发现,线程28014正在读取大量数据,而且读取文件的描述符编号为38。这⼉的 38 ⼜对应着哪个⽂件呢?我们可以执⾏下⾯的 lsof 命令,并且指定线程号 28014 ,具体查看这个可疑线程和可疑⽂件:
$ lsof -p 28014
奇怪的是,lsof 并没有给出任何输出。实际上,如果你查看 lsof 命令的返回值,就会发现,这个命令的执⾏失败了
$ echo $?
1 #在 Linux 中,返回值为 0 ,才表示命令执⾏成功。返回值为1,显然表明执⾏失败
那为什么lsof会失败呢?
通过查询 lsof 的⽂档,你会发现,-p 参数需要指定进程号,⽽我们刚才传⼊的是线程号,所以 lsof 失败了
回过头我们看,mysqld 的进程号是 27458,⽽ 28014 只是它的⼀个线程。⽽且,如果你观察 ⼀下mysqld 进程的线程,你会发现,mysqld 其实还有很多正在运⾏的其他线程:
# -t 表示显示线程,-a 表示显示命令行参数
$ pstree -t -a -p 27458
mysqld,27458 --log_bin=on --sync_binlog=1
...
├─{mysqld},27922
├─{mysqld},27923
└─{mysqld},28014
找到了原因,lsof 的问题就容易解决了。把线程号换成进程号,继续执行 lsof 命令:
$ lsof -p 27458
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
...
mysqld 27458 999 38u REG 8,1 512440000 2601895 /var/lib/mysql/test/products.MYD
这次我们得到了lsof的输出。从输出中可以看到,mysqld进程确实打开了大量文件,而根据文件描述符(fd)的编号,我们知道,描述符38是一个路径为/var/lib/mysql/test/products.MYD的文件(注意,38后面的u,表示mysqld以读写的方式访问文件)
- MDY文件,是MyISAM引擎用来存储表数据的文件
- 文件名就是数据表的名字
- 而这个文件的父目录,也就是数据库的名字。
换句话说,这个⽂件告诉我们,mysqld 在读取数据库 test 中的 products 表。
实际上,你可以执行下面的命令,查看mysqld在管理数据库test时的存储文件。不过要注意,由于MySQL运行在容器中,你需要通过docker exec到容器中查询:
$ docker exec -it mysql ls /var/lib/mysql/test/
db.opt products.MYD products.MYI products.frm
即使,/var/lib/mysql/test目录中有四个文件,每个文件的作用分布是:
- MYD文件用来存储表的数据
- MYI文件用来存储表的索引
- frm文件用来存储表的元信息(比如表结构)
- opt文件用来存储数据库的元信息(比如字符集、字符校验规则)
当然,看到这些,你可能还有⼀个疑问,那就是,这些⽂件到底是不是 mysqld 正在使⽤的数据库⽂件呢?有没有可能是不再使⽤的旧数据呢?其实,这个很容易确认,查⼀下 mysqld 配置的数据路径即可。
你可以在终端⼀中,继续执⾏下⾯的命令:
$ docker exec -i -t mysql mysql -e 'show global variables like "%datadir%";'
+---------------+-----------------+
| Variable_name | Value |
+---------------+-----------------+
| datadir | /var/lib/mysql/ |
+---------------+-----------------+
这⾥可以看到,/var/lib/mysql/ 确实是 mysqld 正在使⽤的数据存储⽬录。刚才分析得出的数据库 test 和数据表 products ,都是正在使⽤。
注:其实 lsof 的结果已经可以确认,它们都是 mysqld 正在访问的文件。再查询 datadir ,只是想换一个思路,进一步确认一下。
既然已经找出来数据库和表,接下来要做的就是要弄清楚数据库正在执行什么样的SQL了。我们继续在终端一中,运行下面的docker exec命令,进入MySQL的命令行界面:
$ docker exec -i -t mysql mysql
...
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql>
然后执行show processlist命令,来查看当前正在执行的SQL语句
不过,为了保证 SQL 语句不截断,这里我们可以执行 show full processlist 命令。如果一切正常,你应该可以看到如下输出:
mysql> show full processlist;
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| 27 | root | localhost | test | Query | 0 | init | show full processlist |
| 28 | root | 127.0.0.1:42262 | test | Query | 1 | Sending data | select * from products where productName='geektime' |
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
2 rows in set (0.00 sec)
这个输出中,
- 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 命令,就可以帮你解决这个问题。继续在 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 |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
1 row in set (0.00 sec)
- select_type 表示查询类型,⽽这⾥的SIMPLE 表示此查询不包括 UNION 查询或者⼦查询;
- table 表示数据表的名字,这⾥是 products;
- type 表示查询类型,这⾥的 ALL 表示全表查询,但索引查询应该是 index 类型才对;
- possible_keys 表示可能选⽤的索引,这⾥是 NULL;
- key 表示确切会使⽤的索引,这⾥也是 NULL;
- rows 表示查询扫描的⾏数,这⾥是 10000。
根据这些信息,我们可以确定,这条查询语句压根⼉没有使⽤索引,所以查询时,会扫描全表,并且扫描⾏数⾼达 10000⾏。响应速度那么慢也就难怪了。
⾛到这⼀步,你应该很容易想到优化⽅法,没有索引那我们就⾃⼰建⽴,给 productName 建⽴索引就可以了。不过,增加索引前,你需要先弄清楚,这个表结构到底⻓什么样⼉。
执⾏下⾯的 MySQL 命令,查询 products 表的结构,你会看到,它只有⼀个 id 主键,并不包括 productName 的索引:
mysql> show create table products;
...
| products | CREATE TABLE `products` (
`id` int(11) NOT NULL,
`productCode` text NOT NULL COMMENT '产品代码',
`productName` text NOT NULL COMMENT '产品名称',
...
PRIMARY KEY (`id`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC |
...
接下来,我们就可以给 productName 建⽴索引了,也就是执⾏下⾯的 CREATE INDEX 命令:
mysql> CREATE INDEX products_index ON products (productName);
ERROR 1170 (42000): BLOB/TEXT column 'productName' used in key specification without a key length
不过,醒目的 ERROR 告诉我们,这条命令运行失败了。根据错误信息,productName 是一个 BLOB/TEXT 类型,需要设置一个长度。所以,想要创建索引,就必须为 productName 指定一个前缀长度。
那前缀长度设置为多大比较合适呢?这里其实有专门的算法,即通过计算前缀长度的选择性,来确定索引的长度。
- 有时候需要索引很⻓的字符列,这会让索引变得⼤且慢。
- 通常可以索引开始的部分字符,这样可以⼤⼤节约索引空间,从⽽提⾼索引效率。但这样也会降低索引的选择性。
- 索引的选择性是指不重复的索引值(也称为基数,cardinality)和数据表的记录总数的⽐值,范围从1/#T到1之间。
- 索引的选择性越⾼则查询效率越⾼,因为选择性⾼的索引可以让MySQL在查找时过滤掉更多的⾏。
- 唯⼀索引的选择性是1,这是最好的索引选择性,性能也是最好的。⼀般情况下某个前缀的选择性也是⾜够⾼的,⾜以满⾜查询性能。
- 对于BLOB,TEXT,或者很⻓的VARCHAR类型的列,必须使⽤前缀索引,因为MySQL不允许索引这些列的完整⻓度。
- 诀窍在于要选择⾜够⻓的前缀以保证较⾼的选择性,同时⼜不能太⻓(以便节约空间)。前缀应该⾜够⻓,以使得前缀索引的选择性接近于索引的整个列。换句话说,前缀的”基数“应该接近于完整的列的”基数“。
- select count(distinct city)/count(*) from city_demo; 根据这个算出⼀个⽐例,然后 count(distinct left(city,3)) 把这个3逐渐的加⼤,⼀直到算出来的数值接近上⾯的⽐例,这样算出来的前缀索引是性能最好的。
不过,我们可以稍微简化一下,直接使用一个固定数值(比如 64),执行下面的命令创建索引:
mysql> CREATE INDEX products_index ON products (productName(64));
Query OK, 10000 rows affected (14.45 sec)
Records: 10000 Duplicates: 0 Warnings: 0
现在可以看到,索引已经建好了。能做的都做完了,最后就该检查一下,性能问题是否已经解决了。
我们切换到终端二中,查看还在执行的 curl 命令的结果:
Got data: ()in 15.383180141448975 sec
Got data: ()in 15.384996891021729 sec
Got data: ()in 0.0021054744720458984 sec
Got data: ()in 0.003951072692871094 sec
``
显然,查询时间已经从 15 秒缩短到了 3 毫秒。看来,没有索引果然就是这次性能问题的罪魁祸首,解决了索引,就解决了查询慢的问题。`
# 思考
到这⾥,商品搜索应⽤查询慢的问题已经完美解决了。但是,对于这个案例,我还有⼀点想说明⼀下。
不知道你还记不记得,案例开始时,我们启动的⼏个容器应⽤。除了 MySQL 和商品搜索应⽤外,还有⼀个 DataService 应⽤。为什么这个案例开始时,要运⾏⼀个看起来毫不相关的应⽤呢?
实际上,DataService是一个严重影响MySQL性能的干扰应用。抛开上述索引优化⽅法不说,这个案例还有⼀种优化⽅法,也就是停⽌ DataService 应⽤。
接下来,我们就删除数据库索引,回到原来的状态;然后停⽌ DataService 应⽤,看看优化效果如何。
⾸先,我们在终端⼆中停⽌ curl 命令,然后回到终端⼀中,执⾏下⾯的命令删除索引:
```shell
# 删除索引
$ docker exec -i -t mysql mysql
mysql> use test;
mysql> DROP INDEX products_index ON products;
接着,在终端二中重新运行 curl 命令。当然,这次你会发现,处理时间又变慢了:
$ while true; do curl http://192.168.0.10:10000/products/geektime; sleep 5; done
Got data: ()in 16.884345054626465 sec
接下来,再次回到终端一中,执行下面的命令,停止 DataService 应用:
# 停止 DataService 应用
$ docker rm -f dataservice
最后,我们回到终端二中,观察 curl 的结果:
Got data: ()in 16.884345054626465 sec
Got data: ()in 15.238174200057983 sec
Got data: ()in 0.12604427337646484 sec
Got data: ()in 0.1101069450378418 sec
Got data: ()in 0.11235237121582031 sec
果然,停止 DataService 后,处理时间从 15 秒缩短到了 0.1 秒,虽然比不上增加索引后的 3 毫秒,但相对于 15 秒来说,优化效果还是非常明显的。
那么,这种情况下,还有没有 I/O 瓶颈了呢?
我们切换到终端一中,运行下面的 vmstat 命令,观察 I/O 的变化情况:
为什么要用vmstat而不是iostat
- 相对于iostat来说,vmstat可以同时提供CPU、内存和IO的使用情况
- 在性能分析过程中,能够综合多个指标,并结合系统的工作原理进行分析,对解释性能现象通常会有意想不到的帮助。
$ 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
0 1 0 6809304 1368 856744 0 0 32640 0 52 478 1 0 50 49 0
0 1 0 6776620 1368 889456 0 0 32640 0 33 490 0 0 50 49 0
0 0 0 6747540 1368 918576 0 0 29056 0 42 568 0 0 56 44 0
0 0 0 6747540 1368 918576 0 0 0 0 40 141 1 0 100 0 0
0 0 0 6747160 1368 918576 0 0 0 0 40 148 0 1 99 0 0
你可以看到,磁盘读(bi)和 iowait(wa)刚开始还是挺大的,但没过多久,就都变成了 0 。换句话说,I/O 瓶颈消失了。
这是为什么呢?
小结
- 今天我们分析了⼀个商品搜索的应⽤程序。我们先是通过 top、iostat 分析了系统的 CPU 和磁盘使⽤情况,发现了磁盘的 I/O瓶颈。
- 接着,我们借助 pidstat ,发现瓶颈是 mysqld 导致的。紧接着,我们⼜通过 strace、lsof,找出了 mysqld 正在读的⽂件。同时,根据⽂件的名字和路径,我们找出了 mysqld 正在操作的数据库和数据表。综合这些信息,我们判断,这是⼀个没有利⽤索引导致的慢查询问题。
- 于是,我们登录到 MySQL 命令⾏终端,⽤数据库分析⼯具进⾏验证,发现 MySQL 查询语句访问的字段,果然没有索引。所以,增加索引,就可以解决案例的性能问题了。