基础：⼀个SQL查询要15秒，这是怎么回事

案例

这是⼀个基于 Python Flask 的商品搜索应⽤，商品信息存在 MySQL 中。这个应
⽤可以通过 MySQL 接⼝，根据客户端提供的商品名称，去数据库表中查询商品信息。

准备

• 机器配置：2 CPU，8GB 内存
• 预先安装 docker、sysstat 、git、make 等⼯具，如 apt installdocker.io sysstat make git
  • git ⽤来拉取本次案例所需脚本，这些脚本存储在 Github 代码仓库
    中；
  • 最后的 make 则是⼀个常⽤构建⼯具，这⾥⽤来运⾏今天的案例

案例总共由三个容器组成，包括⼀个 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 查询语句访问的字段，果然没有索引。所以，增加索引，就可以解决案例的性能问题了。