21. MySQL: database level monitoring and common counter analysis

In the last article, we talked about the global analysis of the database. In today's article, we continue to look at how to do directional analysis in the database.

Remember the tools I mentioned in my last article? MySQL report, Pt query digest and mysql_exportor+Prometheus+Grafana. We have finished mysqlreport in the last article. Today, let's take a look at the remaining ones.

Directional fetch SQL: Pt query Digest

PT query digest is a good tool. It can analyze slow log, general log, binary log, and MySQL protocol data captured by tcpdump. We can see how powerful this tool is. PT query digest belongs to the Percona tool tool set. The Percona company has also produced several special tools for monitoring mysql.

The report logic generated by Pt query digest when analyzing slow log is very clear, and the data is relatively complete. A report is generated after the command is executed.

Let me explain the report a little. Let's first look at the first part of the report:

# 88.3s user time, 2.5s system time, 18.73M rss, 2.35G vsz
# Current date: Thu Jun 22 11:30:02 2017
# Hostname: localhost
# Files: /Users/Zee/Downloads/log/10.21.0.30/4001/TENCENT64-slow.log.last
# Overall: 210.18k total, 43 unique, 0.26 QPS, 0.14x concurrency _________
# Time range: 2017-06-12 21:20:51 to 2017-06-22 09:26:38
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time        118079s   100ms      9s   562ms      2s   612ms   293ms
# Lock time            15s       0     7ms    71us   119us    38us    69us
# Rows sent          1.91M       0  48.42k    9.53   23.65  140.48    2.90
# Rows examine      13.99G       0   3.76M  69.79k 101.89k  33.28k  68.96k
# Rows affecte       3.36M       0   1.98M   16.76    0.99   4.90k       0
# Query size       102.82M       6  10.96k  512.99  719.66  265.43  719.66

As can be seen from the above table, in this slow log, the total execution time reaches 118079s, the average execution time is 562ms, the longest execution time is 9s, and the standard deviation is 612ms.

It can be seen that in this example, SQL execution is still a little slow.

At this time, someone may ask, how long is SQL execution slow? Previously, in a financial institution, I discussed their SQL execution time index with a core system team. After judging, they said that they hoped that the average execution time of SQL would be set at 500ms. I said, you need 500ms, and there are a series of nodes in front of you to reach the end user. If each link requires itself in this way, doesn't the end user obviously feel very slow?

After a round of discussion, it was finally set within 100ms.

In fact, from my experience, for most real-time businesses, the average execution time of an SQL is set at more than 100ms. But for performance, there is no fixed standard in all links, only empirical data and evolving system performance capability.

We then analyze the above data. Let's look at the load report given by Pt query Digest:

# Profile
# Rank Query ID           Response time    Calls  R/Call V/M   Item
# ==== ================== ================ ====== ====== ===== ===========
#    1 0x6A516B681113449F 73081.7989 61.9%  76338 0.9573  0.71 UPDATE mb_trans
#    2 0x90194A5C40980DA7 38014.5008 32.2% 105778 0.3594  0.20 SELECT mb_trans mb_trans_finan
#    3 0x9B56065EE2D0A5C8  3893.9757  3.3%   9709 0.4011  0.11 UPDATE mb_finan
# MISC 0xMISC              3088.5453  2.6%  18353 0.1683   0.0 <40 ITEMS>

It can be seen from this table that the execution time of two SQL accounts for 94% of the total execution time. Obviously, these two SQL are the focus of next analysis.

Let's continue to look at the first SQL performance report given by this tool:

# Query 1: 0.30 QPS, 0.29x concurrency, ID 0x6A516B681113449F at byte 127303589
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.71
# Time range: 2017-06-16 21:12:05 to 2017-06-19 18:50:59
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         36   76338
# Exec time     61  73082s   100ms      5s   957ms      2s   823ms   672ms
# Lock time     19      3s    20us     7ms    38us    66us    29us    33us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  36   5.06G   3.82k 108.02k  69.57k 101.89k  22.70k  68.96k
# Rows affecte   2  74.55k       1       1       1       1       0       1
# Query size    12  12.36M     161     263  169.75  192.76   11.55  158.58
# String:
# Databases    db_bank
# Hosts        10.21.16.50 (38297/50%)... 1 more
# Users        user1
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  ################################################################
#    1s  #########################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `db_bank` LIKE 'mb_trans'\G
#    SHOW CREATE TABLE `db_bank`.`mb_trans`\G
UPDATE mb_trans  
		SET 
		resCode='PCX00000',resultMes='Successful trade',payTranStatus='P03',payRouteCode='CMA'  
		WHERE 
		seqNo='20170619PM010394356875'\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  
		resCode='PCX00000',resultMes='Successful trade',payTranStatus='P03',payRouteCode='CMA' from mb_trans where  
		seqNo='20170619PM010394356875'\G

From the query time distribution diagram, the execution time of this statement is mostly between 100ms and 1s, and 95% of the execution time is less than 2s. Then this SQL is the focus of our next tuning.

I won't repeat the second SQL, because the logic is exactly the same.

Through the analysis of slow logs, we can quickly know which SQL is slow. Of course, if you use mysqldumpslow analysis, you will get the same result.

SQL profiling: profiling

When analyzing the performance of the database, it is obvious that the analysis of SQL is a link that cannot be bypassed. However, as I said before, it is also illogical to analyze SQL comprehensively, because there are so many SQL. If you analyze each SQL in detail, it will obviously slow down the whole system. Moreover, it is not necessary to analyze some fast executing SQL, which will increase resource consumption.

Through the above analysis process, we have located which SQL is slow to execute, so the following is to know the details of SQL execution. Whether in Oracle or MySQL, we should look at the execution plan.

For example:

Select in the figure above_ Type is the meaning of clause type, which is simple and complex, but it can't explain the problem of cost. Here, the most important content is type, because type can tell you how to access this table. ALL in the above figure means full table scanning. Type also has the following values:

Possible in execution plan_ Keys lists the index values that may be used. The key column will list the index values used during execution.

The above information is an important part of the MySQL execution plan. This information can help us analyze SQL and provide evidence for optimization.

In addition to the execution plan, MySQL also provides profiling. What's the use of this? It can list every step of SQL execution in detail, from entering a SQL into the database to completing the whole life cycle.

MySQL profiling takes effect at the session level, so when you use the slow log and know which SQL has a problem, it is most effective to use this function again. If you want to turn on the SQL profiling function of all sessions at the beginning, the cost is too high.

Let me explain the usage and function of profiling in detail.

profiling steps

The operation steps of profiling are relatively simple, as shown below:

Step 1: set profiling=1;  //This step is to turn on the profiling function
 Step 2: execute the statement           //Execute the statements you see in the slow log
 Step 3: show profiles;    //This step is to find the ID of the statement executed in step 2
 Step 4: show profile all for query id; //This step is to show the results of profiling

Let's actually perform the above steps:

// Step 1: open the profiling function
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
// This step is only to confirm whether there is a value in the profiles list. You don't need to execute it.
mysql> show profiles;
Empty set, 1 warning (0.00 sec)
// Step 2: execute the statement
mysql> select * from t_user where user_name='Zee0355916';
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| id                                   | user_number | user_name  | org_id | email                | mobile      | create_time         |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| 00000d2d-32a8-11ea-91f8-00163e124cff | 00009496    | Zee0355916 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 14:19:32 |
| 77bdb1ef-32a6-11ea-91f8-00163e124cff | 00009496    | Zee0355916 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 14:08:34 |
| d4338339-32a2-11ea-91f8-00163e124cff | 00009496    | Zee0355916 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 13:42:31 |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
3 rows in set (14.33 sec)
// Step 3: check the profiles list and find the statement we just executed
mysql> show profiles;
+----------+-------------+---------------------------------------------------+
| Query_ID | Duration    | Query                                             |
+----------+-------------+---------------------------------------------------+
|        1 | 14.34078475 | select * from t_user where user_name='Zee0355916' |
+----------+-------------+---------------------------------------------------+
1 row in set, 1 warning (0.00 sec)
// Step 4: look at the profile information of this statement
mysql> show profile all for query 1;
+--------------------------------+-----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| Status                         | Duration  | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function       | Source_file      | Source_line |
+--------------------------------+-----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| starting                       |  0.000024 | 0.000012 |   0.000005 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL                  | NULL             |        NULL |
| Waiting for query cache lock   |  0.000004 | 0.000003 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| init                           |  0.000003 | 0.000002 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| checking query cache for query |  0.000052 | 0.000036 |   0.000015 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | send_result_to_client | sql_cache.cc     |        1601 |
| checking permissions           |  0.000007 | 0.000005 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | check_access          | sql_parse.cc     |        5316 |
| Opening tables                 |  0.000032 | 0.000023 |   0.000009 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | open_tables           | sql_base.cc      |        5095 |
| init                           |  0.000042 | 0.000029 |   0.000013 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_prepare_select  | sql_select.cc    |        1051 |
| System lock                    |  0.000016 | 0.000011 |   0.000004 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables     | lock.cc          |         304 |
| Waiting for query cache lock   |  0.000003 | 0.000002 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| System lock                    |  0.000020 | 0.000014 |   0.000006 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| optimizing                     |  0.000012 | 0.000009 |   0.000004 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc |         139 |
| statistics                     |  0.000019 | 0.000013 |   0.000005 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc |         365 |
| preparing                      |  0.000015 | 0.000010 |   0.000005 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc |         488 |
| executing                      |  0.000004 | 0.000003 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                  | sql_executor.cc  |         110 |
| Sending data                   | 14.324781 | 4.676869 |   0.762349 |              1316 |                 132 |      2499624 |           288 |             0 |                 0 |                 8 |             30862 |     0 | exec                  | sql_executor.cc  |         190 |
| end                            |  0.000015 | 0.000007 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_select  | sql_select.cc    |        1106 |
| query end                      |  0.000006 | 0.000005 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc     |        5015 |
| closing tables                 |  0.000016 | 0.000013 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc     |        5063 |
| freeing items                  |  0.000013 | 0.000010 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 2 |     0 | mysql_parse           | sql_parse.cc     |        6490 |
| Waiting for query cache lock   |  0.000003 | 0.000002 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| freeing items                  |  0.000014 | 0.000012 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| Waiting for query cache lock   |  0.000003 | 0.000002 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| freeing items                  |  0.000003 | 0.000002 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| storing result in query cache  |  0.000004 | 0.000002 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | end_of_result         | sql_cache.cc     |        1034 |
| logging slow query             |  0.015645 | 0.000084 |   0.000020 |                 2 |                   0 |           16 |             8 |             0 |                 0 |                 0 |                 2 |     0 | log_slow_do           | sql_parse.cc     |        1935 |
| cleaning up                    |  0.000034 | 0.000024 |   0.000006 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc     |        1837 |
+--------------------------------+-----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
26 rows in set, 1 warning (0.02 sec)

In the whole database, we see that the life cycle is very long from the beginning to the end.

After counting each step in the life cycle, we can see the time consumed by each step. Not only that, you can also see the following information:

  • BLOCK IO
  • Context Switches
  • CPU
  • IPC
  • MEMORY
  • Page Fault
  • SOURCE
  • SWAPS

With this information, we can basically judge what is wrong with the statement.

From the above example statement, you can see that Sending data takes 14 seconds. From the following data, you can also see that there are 1316 active context switches and 132 passive ones, and the amount of block operations is also very large.

In this case, we have to know what the Sending data is. Let's take a look at the implementation plan mentioned earlier:

mysql> explain select * from t_user where user_name='Zee0355916';
+----+-------------+--------+------+---------------+------+---------+------+---------+-------------+
| id | select_type | table  | type | possible_keys | key  | key_len | ref  | rows    | Extra       |
+----+-------------+--------+------+---------------+------+---------+------+---------+-------------+
|  1 | SIMPLE      | t_user | ALL  | NULL          | NULL | NULL    | NULL | 3868195 | Using where |
+----+-------------+--------+------+---------------+------+---------+------+---------+-------------+
1 row in set (0.00 sec)

This is a typical full table scan, so the next step is to check whether the index is created.

mysql> show indexes from t_user;
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| Table  | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| t_user |          0 | PRIMARY  |            1 | id          | A         |     3868195 |     NULL | NULL   |      | BTREE      |         |               |
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
1 row in set (0.00 sec)


mysql>

There is still a primary key index, but we can't use it because we don't use the primary key to check.

Some performance test engineers may have this idea in the face of this situation: they don't check the index for the first time, but they put all the data into the cache, so the second time is fast. Therefore, some people may want to "complete" the work as soon as possible and use duplicate data.

Here I'll do it again. You can see what the result is:

+----------+-------------+-----------------------------------------------------------+
| Query_ID | Duration    | Query                                                     |
+----------+-------------+-----------------------------------------------------------+
|        1 | 14.34078475 | select * from t_user where user_name='Zee0355916'         |
|        2 |  0.00006675 | show profile all for 1                                    |
|        3 |  0.00031700 | explain select * from t_user where user_name='Zee0355916' |
|        4 |  0.00040025 | show indexes from t_user                                  |
+----------+-------------+-----------------------------------------------------------+
6 rows in set, 1 warning (0.00 sec)


mysql> select * from t_user where user_name='Zee0355916';
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| id                                   | user_number | user_name  | org_id | email                | mobile      | create_time         |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| 00000d2d-32a8-11ea-91f8-00163e124cff | 00009496    | Zee0355916 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 14:19:32 |
| 77bdb1ef-32a6-11ea-91f8-00163e124cff | 00009496    | Zee0355916 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 14:08:34 |
| d4338339-32a2-11ea-91f8-00163e124cff | 00009496    | Zee0355916 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 13:42:31 |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
3 rows in set (0.00 sec)


mysql> show profiles;
+----------+-------------+-----------------------------------------------------------+
| Query_ID | Duration    | Query                                                     |
+----------+-------------+-----------------------------------------------------------+
|        1 | 14.34078475 | select * from t_user where user_name='Zee0355916'         |
|        2 |  0.00006675 | show profile all for 1                                    |
|        3 |  0.00031700 | explain select * from t_user where user_name='Zee0355916' |
|        4 |  0.00040025 | show indexes from t_user                                  |
|        5 |  0.00027325 | select * from t_user where user_name='Zee0355916'         |
+----------+-------------+-----------------------------------------------------------+
7 rows in set, 1 warning (0.00 sec)


mysql> show profile all for query 5;
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+--------------+-------------+
| Status                         | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function       | Source_file  | Source_line |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+--------------+-------------+
| starting                       | 0.000029 | 0.000018 |   0.000004 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL                  | NULL         |        NULL |
| Waiting for query cache lock   | 0.000006 | 0.000003 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc |         468 |
| init                           | 0.000003 | 0.000003 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc |         468 |
| checking query cache for query | 0.000008 | 0.000006 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | send_result_to_client | sql_cache.cc |        1601 |
| checking privileges on cached  | 0.000003 | 0.000002 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | send_result_to_client | sql_cache.cc |        1692 |
| checking permissions           | 0.000010 | 0.000192 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | check_access          | sql_parse.cc |        5316 |
| sending cached result to clien | 0.000210 | 0.000028 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 1 |     0 | send_result_to_client | sql_cache.cc |        1803 |
| cleaning up                    | 0.000006 | 0.000006 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc |        1837 |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+--------------+-------------+
8 rows in set, 1 warning (0.00 sec)


mys

See, the response time is much faster when using duplicate data, because the data is sent directly from the cache to the client.

However, please resolutely stop this practice, because it does not conform to the appearance of real production. When you change another data, you will stop cooking and have to scan the whole table for another 14 seconds.

Therefore, the correct way is to create an appropriate index to make the statement faster when executing any piece of data. Then, let's create an index now and look at the execution results.

// Create index
mysql> ALTER TABLE t_user ADD INDEX username_idx (user_name);
Query OK, 0 rows affected (44.69 sec)
Records: 0  Duplicates: 0  Warnings: 0
// Analysis table
mysql> analyze table t_user;
+-----------+---------+----------+----------+
| Table     | Op      | Msg_type | Msg_text |
+-----------+---------+----------+----------+
| pa.t_user | analyze | status   | OK       |
+-----------+---------+----------+----------+
1 row in set (0.08 sec)
// Execute statement 
mysql> select * from t_user where user_name='Zee0046948';
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| id                                   | user_number | user_name  | org_id | email                | mobile      | create_time         |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| 000061a2-31c2-11ea-8d89-00163e124cff | 00009496    | Zee0046948 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-08 10:53:08 |
| 047d7ae1-32a2-11ea-91f8-00163e124cff | 00009496    | Zee0046948 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 13:36:42 |
| 1abfa543-318f-11ea-8d89-00163e124cff | 00009496    | Zee0046948 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-08 04:48:48 |
| 671c4014-3222-11ea-91f8-00163e124cff | 00009496    | Zee0046948 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-08 22:23:12 |
| 9de16dd3-32a5-11ea-91f8-00163e124cff | 00009496    | Zee0046948 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 14:02:28 |
| dd4ab182-32a4-11ea-91f8-00163e124cff | 00009496    | Zee0046948 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 13:57:05 |
| f507067e-32a6-11ea-91f8-00163e124cff | 00009496    | Zee0046948 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-09 14:12:04 |
| f7b82744-3185-11ea-8d89-00163e124cff | 00009496    | Zee0046948 | NULL   | test9495@dunshan.com | 17600009498 | 2020-01-08 03:43:24 |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
8 rows in set (0.02 sec)
// View Query_ID
mysql> show profiles;
+----------+-------------+-----------------------------------------------------------+
| Query_ID | Duration    | Query                                                     |
+----------+-------------+-----------------------------------------------------------+
|        1 | 14.34078475 | select * from t_user where user_name='Zee0355916'         |
|        2 |  0.00006675 | show profile all for 1                                    |
|        3 |  0.00031700 | explain select * from t_user where user_name='Zee0355916' |
|        4 |  0.00005875 | show indexes for table t_user                             |
|        5 |  0.00005850 | show indexes for t_user                                   |
|        6 |  0.00040025 | show indexes from t_user                                  |
|        7 |  0.00027325 | select * from t_user where user_name='Zee0355916'         |
|        8 |  0.00032100 | explain select * from t_user where user_name='Zee0355916' |
|        9 | 12.22490550 | select * from t_user where user_name='Zee0046945'         |
|       10 |  0.00112450 | select * from t_user limit 20                             |
|       11 | 44.68370500 | ALTER TABLE t_user ADD INDEX username_idx (user_name)     |
|       12 |  0.07385150 | analyze table t_user                                      |
|       13 |  0.01516450 | select * from t_user where user_name='Zee0046948'         |
+----------+-------------+-----------------------------------------------------------+
13 rows in set, 1 warning (0.00 sec)
// View profile information
mysql> show profile all for query 13;
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| Status                         | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function       | Source_file      | Source_line |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| starting                       | 0.000030 | 0.000017 |   0.000004 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL                  | NULL             |        NULL |
| Waiting for query cache lock   | 0.000005 | 0.000004 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| init                           | 0.000003 | 0.000002 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| checking query cache for query | 0.000060 | 0.000050 |   0.000011 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | send_result_to_client | sql_cache.cc     |        1601 |
| checking permissions           | 0.000009 | 0.000007 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | check_access          | sql_parse.cc     |        5316 |
| Opening tables                 | 0.000671 | 0.000412 |   0.000000 |                 1 |                   0 |            8 |             0 |             0 |                 0 |                 0 |                 1 |     0 | open_tables           | sql_base.cc      |        5095 |
| init                           | 0.006018 | 0.000082 |   0.000899 |                 1 |                   0 |         5408 |             0 |             0 |                 0 |                 1 |                 0 |     0 | mysql_prepare_select  | sql_select.cc    |        1051 |
| System lock                    | 0.000017 | 0.000011 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables     | lock.cc          |         304 |
| Waiting for query cache lock   | 0.000003 | 0.000003 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| System lock                    | 0.000019 | 0.000015 |   0.000004 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| optimizing                     | 0.000012 | 0.000010 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc |         139 |
| statistics                     | 0.001432 | 0.000167 |   0.000037 |                 1 |                   0 |           32 |             0 |             0 |                 0 |                 0 |                 4 |     0 | optimize              | sql_optimizer.cc |         365 |
| preparing                      | 0.000026 | 0.000043 |   0.000009 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 1 |     0 | optimize              | sql_optimizer.cc |         488 |
| executing                      | 0.000034 | 0.000005 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                  | sql_executor.cc  |         110 |
| Sending data                   | 0.006727 | 0.000439 |   0.001111 |                13 |                   0 |         1536 |             0 |             0 |                 0 |                 0 |                 1 |     0 | exec                  | sql_executor.cc  |         190 |
| end                            | 0.000014 | 0.000007 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_select  | sql_select.cc    |        1106 |
| query end                      | 0.000009 | 0.000008 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc     |        5015 |
| closing tables                 | 0.000015 | 0.000012 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc     |        5063 |
| freeing items                  | 0.000010 | 0.000008 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_parse           | sql_parse.cc     |        6490 |
| Waiting for query cache lock   | 0.000003 | 0.000002 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| freeing items                  | 0.000027 | 0.000022 |   0.000005 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| Waiting for query cache lock   | 0.000003 | 0.000002 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| freeing items                  | 0.000003 | 0.000002 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | try_lock              | sql_cache.cc     |         468 |
| storing result in query cache  | 0.000004 | 0.000004 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | end_of_result         | sql_cache.cc     |        1034 |
| cleaning up                    | 0.000015 | 0.000012 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc     |        1837 |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
25 rows in set, 1 warning (0.01 sec)


mysql>

From the last profile information above, you can see that the steps are not less, but the speed is much faster. This is the correct optimization idea.

In the last article, I described how to view data from the perspective of global monitoring in a database. Today, I'm talking about how to find specific slow SQL and how to locate this SQL.

Of course, not all cases are SQL problems, configuration problems or hardware problems. No matter what kind of problem, the analysis idea is like this, which is what I always emphasize: Global Monitoring - directional monitoring.

Of course, here I should also give the idea of MySQL analysis decision tree. From the division of mysqlreport, this paper gives several specific branches of analysis decision tree.

This is a common problem. If you are interested, you can improve the complete tree by yourself, because you may have different tools or ideas for dividing counters, so the tree can change flexibly.

You must remember that what others give you will never become your own. They can only guide you. If you do it yourself, even if you draw only one branch, it will be a great progress.

If you want to use other global monitoring tools, you can also consider the following combination, that is, mysql_exportor+Prometheus+Grafana.

mysql_exportor+Prometheus+Grafana

I have mentioned this kind of combination many times before. Different exporters combined with Prometheus+Grafana can realize real-time monitoring and data storage.

Here, let's take a look at mysql_ What kind of monitoring data can exporter provide us. Here are some screenshots to give you a general view of what this set of tools can see. If you are interested, you can also build it yourself.

summary

There is too much knowledge about database. In these two articles, what I want to tell you is the idea of analyzing database. As for other knowledge points, I think they should be stored before you open the article.

Let's summarize that there are three possible problems in the analysis of the database:

  1. hardware configuration
  2. Database configuration
  3. SQL statement

For hardware configuration, we can only evaluate how much hardware is enough after solving the problems of 2 and 3. Facing the problem of database configuration, there is really no good way. We can only learn to solve it after understanding a series of knowledge such as database architecture. The problem of SQL is the most common one in performance testing and analysis. The analysis idea of SQL performance problems is also relatively clear, that is to judge the specific SQL bottleneck, and then make corresponding optimization. Remember not to be deceived!

There are too many types of databases now. Each database has its own architecture and usage scenarios. We can start to adjust them only after we fully understand them.

Posted by Ferdog on Mon, 23 May 2022 07:09:32 +0300