28 Case Study a SQL Query Takes 15 Seconds, What's Going On

28 Case Study A SQL Query Takes 15 Seconds, What’s Going On #

Hello, I’m Ni Pengfei.

In the previous section, we analyzed a case where a word popularity application was responding slowly. After analyzing the CPU and disk I/O usage of the system using top and iostat, we found that there was a disk I/O bottleneck caused by the application.

Then, after using strace and not finding anything significant, I introduced you to two new tools, filetop and opensnoop, to analyze their tracing results for the system calls write() and open().

We found that the application was reading and writing a large number of temporary files, which was causing the performance bottleneck. After identifying the bottleneck, we solved the disk I/O performance issue by storing the file data in memory.

Of course, you may argue that in real applications, a large amount of data would be stored in a database rather than directly using text files. However, databases are not infallible either. So, how do we analyze and locate the bottlenecks when a database has performance issues?

Today, we will analyze a database case. This is a product search application based on Python Flask, where product information is stored in MySQL. This application can retrieve product information from the database table based on the product name provided by the client through the MySQL interface.

Many thanks to Yang Xiangyi, a senior operation and maintenance engineer at Vipshop, for providing today’s case.

Case Preparation #

This case is still based on Ubuntu 18.04 and is also applicable to other Linux systems. The environment I used for this case is as follows:

- Machine configuration: 2 CPUs, 8GB memory

- Pre-installed docker, sysstat, git, make and other tools, such as apt install docker.io sysstat make git

Among them, Docker and sysstat have been used many times, so I won’t go into detail here; git is used to clone the scripts required for this case, which are stored in the Github code repository; finally, make is a commonly used build tool, which is used to run today’s case.

The case consists of three containers, including a MySQL database application, a product search application, and a data processing application. Among them, the product search application provides an interface in the form of HTTP:

- /: Returns the Index page;

- /db/insert/products/: Inserts a specified number of product information;

- /products/: Queries the information of a specified product and returns the processing time.

Due to the number of applications, in order to facilitate your operation, I have also packaged them into several Docker images and pushed them to Github. In this way, you only need to run a few commands to start them.

Today’s case requires two virtual machines, one of which is used as the target machine for case analysis, running the Flask application with an IP address of 192.168.0.10; the other is used as a client to request the popularity of words. I drew a picture to represent their relationship.

Next, open two terminals and SSH into these two virtual machines respectively, and install the above tools on the first virtual machine.

As before, all commands in the case are run by default as the root user. If you log in to the system as a regular user, please run the command sudo su root to switch to the root user.

With this, the preparation work is complete. Next, let’s move on to the actual operation.

Case Study #

First, execute the following commands in the first terminal to clone the required scripts for this case study:

$ git clone https://github.com/feiskyer/linux-perf-examples
$ cd linux-perf-examples/mysql-slow

Next, run the command below to run the target application for this case study. Under normal circumstances, you should see the following output:

# Note that the random string below is the container ID, which will be different each time you run it. You don't need to pay attention to it as we will only use the name.
$ 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

Then, run the command docker ps to make sure that all three containers are running (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       3306/tcp, 0.0.0.0:10000->80/tcp   mysql

The startup process for the MySQL database requires some initialization work, which usually takes a few minutes. You can run the command docker logs to view its startup process.

When you see the following output, it means that MySQL has finished initializing and is ready to receive external requests:

$ 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)

The product search application listens on port 10000. You can press Ctrl+C to stop the docker logs command; then, run the following command to verify that it is also running correctly. If everything is fine, you will see the output of the Index Page:

$ curl http://127.0.0.1:10000/
Index Page

Next, run the command make init to initialize the database and insert 10,000 product information. This process is slow; for example, on my machine, it took more than ten minutes. After waiting patiently for a while, you will see the following output:

$ 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

Then, switch to the second terminal and access the product search interface to see if the desired product can be found. Execute the following curl command:

$ curl http://192.168.0.10:10000/products/geektime
Got data: () in 15.364538192749023 sec

After waiting for a moment, you will find that this interface returns empty data and takes more than 15 seconds to process. This slow response time is unacceptable. What could be the problem?

Since MySQL is being used today, you would probably guess that it is a slow query issue.

But don’t worry, before analyzing it in detail, to prevent the curl command from ending during the analysis process, let’s put the curl command in a loop so that it runs continuously. Also, to avoid putting too much stress on the system, we set a 5-second wait after each query before starting a new request.

So, you can continue to run the following command in the second terminal:

$ while true; do curl http://192.168.0.10:10000/products/geektime; sleep 5; done

Next, go back to the first terminal and analyze the reason for the slow response of the interface. However, when you return to the first terminal, you will notice that the system response has also slowed down significantly. Any command execution now requires a pause before the output can be seen.

This phenomenon is similar to the one in the previous section, so it seems that we need to observe the system’s resource usage, such as CPU, memory, and disk I/O.

First, execute the top command in the first terminal to analyze the CPU usage of the system:

$ 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

After observing the output of top command, we found that the iowait of both CPUs is relatively high, especially CPU0, iowait is already over 60%. However, specific to each process, the CPU usage is not high, with the highest being only 1.7%.

Since the suspicion on the CPU is not large, the problem should still lie in I/O. We are still in the first terminal, press Ctrl+C to stop the top command; then, execute the following iostat command to see if there is any I/O performance problem:

```
$ 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
```

You should be very familiar with the output of iostat. Observe this interface, we found that the disk sda reads 32 MB per second and the I/O utilization reaches 97%, which is close to saturation. This indicates that the read operation of disk sda is indeed encountering a performance bottleneck.

Then, how do we know which processes are causing these I/O requests? Of course, we can look for our old friend, pidstat. Next, press Ctrl+C in terminal one to stop the iostat command, and then run the following pidstat command to observe the I/O status of the processes:

```
# The -d option indicates displaying the I/O status of the processes
$ 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
```

From the output of pidstat, we can see that mysqld process with PID 27458 is performing a large number of reads and the read speed is 32 MB/s, which is consistent with the discovery from iostat. Comparing these two results, we naturally find the root cause of the disk I/O bottleneck, which is the mysqld process.

However, this is not the end of the matter. We naturally have to wonder why mysqld is reading a large amount of disk data. According to the previous guess, we have mentioned that this may be a slow query problem.

However, thinking about it, the phenomenon of slow queries is mostly high CPU usage (such as 100%). But here, we see an I/O problem. It seems that this is not a simple slow query problem, so we need to analyze the data read by MySQL.

To analyze the data read by the process, of course we still rely on the combination of strace and lsof that we used in the previous section.

Next, still in terminal one, execute the strace command and specify the process number of mysqld as 27458. We know that MySQL is a multi-threaded database application, in order not to miss the data reading situation of these threads, remember to add the -f parameter when executing the stace command.

$ 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

After observing for a while, you will notice that thread 28014 is reading a large amount of data, with file descriptor 38. But which file does 38 correspond to? We can execute the following lsof command and specify the thread number 28014 to check this suspicious thread and its corresponding file:

$ lsof -p 28014

Strangely, lsof does not output anything. In fact, if you check the return value of the lsof command, you will find that it failed.

We know that in the SHELL, the special scalar $? represents the return value of the last command when it exits. Checking this special scalar, you will find that its return value is 1. But don’t forget, in Linux, a return value of 0 indicates that the command was successful. A return value of 1 clearly indicates that it failed.

$ echo $?
1

Why did the lsof command fail? Here, I want you to take a moment to think about the reason yourself. Remember what I said, when you encounter an unexplainable phenomenon, go and check the documentation of the tools first.

In fact, by consulting the documentation of lsof, you will find that the -p parameter requires specifying a process ID, while we just passed in a thread ID, so lsof failed. You see, every detail can become a “roadblock” in performance analysis.

Going back, the process ID of mysqld is 27458, while 28014 is just one of its threads. And if you observe the threads of the mysqld process, you will find that mysqld actually has many other running threads:

# -t shows threads, -a shows command line arguments, -p shows process ID
$ pstree -t -a -p 27458
mysqld,27458 --log_bin=on --sync_binlog=1
...
  ├─{mysqld},27922
  ├─{mysqld},27923
  └─{mysqld},28014

Once we found the reason, it becomes easy to solve the issue with lsof. Just replace the thread ID with the process ID and continue to execute the lsof command:

$ 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

This time we got the output of lsof. From the output, we can see that the mysqld process did indeed open a large number of files. According to the file descriptor (FD) number, we know that the descriptor 38 corresponds to a file with the path /var/lib/mysql/test/products.MYD. Here, note that the ‘u’ after 38 indicates that mysqld is accessing the file in read-write mode.

When you see this file, if you are familiar with MySQL, you may laugh:

The MYD file is used by the MyISAM engine to store table data;
The file name is the name of the table;
The parent directory of this file is the name of the database.

In other words, this file tells us that mysqld is reading the ‘products’ table in the ’test’ database.

In fact, you can execute the following command to view the storage files used by mysqld when managing the ’test’ database. However, please note that since MySQL runs in a container, you need to use docker exec to enter the container and view it:

$ docker exec -it mysql ls /var/lib/mysql/test/
db.opt    products.MYD  products.MYI  products.frm

From here, you can see that there are four files in the /var/lib/mysql/test/ directory. The function of each file is as follows:

The MYD file is used to store table data;
The MYI file is used to store table indexes;
The frm file is used to store table meta information (such as table structure);
The opt file is used to store database meta information (such as character set, character validation rules, etc.).

Of course, you may have another question when you see these files: Are these files the database files that mysqld is currently using, or could they be old data that is no longer in use? In fact, this can be easily confirmed by checking the data path configured for mysqld.

You can continue executing the following command in terminal 1:

$ docker exec -i -t mysql mysql -e 'show global variables like "%datadir%";'
+---------------+-----------------+
| Variable_name | Value           |
+---------------+-----------------+
| datadir       | /var/lib/mysql/ |
+---------------+-----------------+

Here, you can see that /var/lib/mysql/ is indeed the data storage directory currently used by mysqld. The ’test’ database and the ‘products’ table we analyzed earlier are both in use.

Note: In fact, the results of lsof can confirm that these files are being accessed by mysqld. Querying datadir is just to have another way of confirming it.

Now that we have found the database and table, the next step is to figure out what kind of SQL is being executed in the database. We continue to run the docker exec command in terminal 1 to enter the MySQL command line interface:

$ docker exec -i -t mysql mysql
...

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql>

At this point, you should be able to think of running the show processlist command in the MySQL command line interface to see the currently executing SQL statements.

However, to ensure that the SQL statements are not truncated, here we can execute the show full processlist command. If everything goes well, you should see the following output:

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)

In this output:

db indicates the name of the database;
Command indicates the type of SQL;
Time indicates the execution time;
State indicates the state;
Info shows the detailed information about the SQL statements being executed.
The Info contains the complete SQL statement.

Running the show full processlist command multiple times, you can see that the execution time of the SQL statement select * from products where productName='geektime' is relatively long.

Recall that at the beginning of the case, we queried the product name at http://192.168.0.10:10000/products/geektime, where the product name “geektime” also satisfies this query condition.

We know that the slow query problem in MySQL is likely caused by not utilizing indexes properly. Is this query statement the same? How can we confirm if the query statement is utilizing the index?

In fact, the built-in explain command in MySQL can help you solve this problem. Continue running the following explain command in the MySQL terminal:

# Switch to the test database
mysql> use test;
# Run the explain command
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)

Observe the output of this execution. In this interface, there are several important fields that you need to pay attention to. Let’s explain them based on this output:

select_type represents the query type, and here SIMPLE indicates that this query doesn’t include a UNION query or subquery.
table represents the name of the table, which is products here.
type represents the query type, and here ALL indicates a full table scan, but an index query should be of type index.
possible_keys represents the possible keys that may be used, and here it is NULL.
key represents the exact key that will be used, and here it is also NULL.
rows represents the number of rows scanned in the query, which is 10000 here.

Based on this information, we can conclude that this query statement didn’t utilize an index at all. Therefore, during the query execution, a full table scan is performed, scanning a total of 10000 rows. It’s no wonder the response speed is so slow.

At this point, you should easily think of the optimization method: if there’s no index, we can create one ourselves. We can create an index on productName. However, before adding an index, you need to understand what the table structure looks like.

Execute the following MySQL command to query the structure of the products table. You will see that it only has one id primary key and doesn’t include an index for productName:

mysql> show create table products;
...
| products | CREATE TABLE `products` (
  `id` int(11) NOT NULL,
  `productCode` text NOT NULL COMMENT 'Product Code',
  `productName` text NOT NULL COMMENT 'Product Name',
...
  PRIMARY KEY (`id`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC |
...

Next, we can create an index for productName by executing the following CREATE INDEX command:

mysql> CREATE INDEX products_index ON products (productName);
ERROR 1170 (42000): BLOB/TEXT column 'productName' used in key specification without a key length

However, the noticeable error tells us that this command failed to run. According to the error message, productName is a BLOB/TEXT type and requires a length to be specified for indexing. Therefore, to create an index, we must specify a prefix length for productName.

What’s the appropriate prefix length? There is actually a dedicated algorithm for determining the index length through calculating the selectivity of the prefix length. However, we can simplify it a bit and directly use a fixed value (such as 64). Execute the following command to create the index:

mysql> CREATE INDEX products_index ON products (productName(64));
Query OK, 10000 rows affected (14.45 sec)
Records: 10000  Duplicates: 0  Warnings: 0

Now you can see that the index has been created. We have done everything we can. Finally, let’s check if the performance problem has been solved.

Switch to terminal two and check the result of the ongoing curl command:

Got data: () in 15.383180141448975 sec
Got data: () in 15.384996891021729 sec
Got data: () in 0.0021054744720458984 sec
Got data: () in 0.003951072692871094 sec

Obviously, the query time has been reduced from 15 seconds to 3 milliseconds. It seems that the lack of an index is indeed the culprit of this performance issue. By solving the index, we have also solved the slow query problem.

Case Study #

So far, the problem of slow queries in the product search application has been perfectly resolved. However, there is one more thing I would like to explain about this case.

You may or may not remember that at the beginning of the case, we started several container applications. In addition to MySQL and the product search application, there was also a DataService application. Why did we run an apparently unrelated application at the beginning of this case?

In fact, DataService is a disruptive application that seriously affects the performance of MySQL. Leaving aside the index optimization methods mentioned earlier, there is another optimization method for this case, which is to stop the DataService application.

Next, let’s delete the database index and return to the original state. Then, we will stop the DataService application to see the effect of the optimization.

First, stop the curl command in Terminal 2, and then go back to Terminal 1 and execute the following command to delete the index:

# Delete the index
$ docker exec -i -t mysql mysql

mysql> use test;
mysql> DROP INDEX products_index ON products;

Then, in Terminal 2, rerun the curl command. Of course, this time you will notice that the processing time has become slower again:

$ while true; do curl http://192.168.0.10:10000/products/geektime; sleep 5; done
Got data: ()in 16.884345054626465 sec

Next, return to Terminal 1 and execute the following command to stop the DataService application:

# Stop the DataService application
$ docker rm -f dataservice

Finally, go back to Terminal 2 and observe the result of 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

Indeed, after stopping DataService, the processing time was reduced from 15 seconds to 0.1 seconds. Although this is not as fast as the 3 milliseconds after adding the index, it is still a significant improvement compared to 15 seconds.

So, in this case, is there still an I/O bottleneck?

Switch back to Terminal 1, run the following vmstat command (not iostat, I will explain why later), and observe the changes in I/O:

$ 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

You can see that disk read (bi) and iowait (wa) were initially quite high, but after a while, they both became 0. In other words, the I/O bottleneck disappeared.

Why did this happen? The reason will be left as a mystery for now, as a thinking question for today.

Going back to explain the previous operation, when observing the I/O situation, I didn’t use the iostat command, but used vmstat instead. Actually, compared to iostat, vmstat can provide information about CPU, memory, and I/O usage simultaneously.

In the process of performance analysis, being able to synthesize multiple indicators and analyze them in conjunction with the workings of the system can often provide unexpected help in explaining performance phenomena.

Summary #

Today we analyzed a product search application. First, we analyzed the CPU and disk usage of the system using top and iostat, and discovered a disk I/O bottleneck.

Then, using pidstat, we found that the bottleneck was caused by mysqld. Subsequently, we used strace and lsof to identify the files being read by mysqld. At the same time, based on the file names and paths, we found the databases and tables being accessed by mysqld. Taking all this information into account, we concluded that this was a slow query problem caused by the lack of indexes.

Therefore, we logged into the MySQL command line terminal and used a database analysis tool to validate our findings. It turned out that the MySQL query statement was accessing fields without indexes. So, adding indexes will solve the performance problem in this case.

Reflection #

Finally, I have a question for you to ponder, which I mentioned at the end of the case study. After stopping DataService, the processing time for the product search application was reduced from 15 seconds to 0.1 seconds. Why is this?

Here’s a little hint. You can first take a look at the source code of dataservice.py. You will find that DataService is actually reading and writing a small file that contains only the string “data”. However, before reading the file, it sets /proc/sys/vm/drop_caches to 1.

Do you remember what this operation does? If you don’t remember, you can use the man command to query the documentation of the proc file system.

Feel free to discuss with me in the comments section, and feel free to share this article with your colleagues and friends. Let’s practice in reality and make progress through communication.