性能测试实战30讲00023
上一篇文章中,我们讲了有关数据库的全局分析,那么在今天的文章中,我们继续看看在数据库中,如何做定向分析。
还记得我在上篇文章中提到的工具吗?mysqlreport、pt-query-digest和mysql_exportor+Prometheus+Grafana。我们在上一篇中已经讲完了mysqlreport,今天我们来看看剩下的这几个。
定向抓取SQL:pt-query-digest
pt-query-digest
是个挺好的工具,它可以分析slow log
、general log
、binary log
,还能分析tcpdump抓取的MySQL协议数据,可见这个工具有多强大。pt-query-digest
属于Percona-tool工具集,这个Percona公司还出了好几个特别好使的监控MySQL的工具。
pt-query-digest
分析slow log时产生的报告逻辑非常清晰,并且数据也比较完整。执行命令后就会生成一个报告。
我来稍微解释一下这个报告。我们先看这个报告的第一个部分:
# 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
从上表中可以看得出来,在这个慢日志中,总执行时间达到了118079s,平均执行时间为562ms,最长执行时间为9s,标准方差为612ms。
可见在此示例中,SQL执行还是有点慢的。
这时也许会有人问,SQL执行多长时间才是慢呢?之前在一个金融机构,我跟一个做核心系统的团队讨论他们的SQL执行时间指标。他们判断之后说,希望SQL平均执行时间指标定在500ms。我说,你们要500ms,那前面还有一连串的节点才能到达最终的用户,如果每个环节都这样要求自己,那最终的用户不就明显感觉到很慢了吗?
经过一轮轮的讨论,最后定在了100ms以内。
其实从我的经验上来看,对于大部分实时的业务,一个SQL执行的平均时间指标定在100ms都多了。但是对性能来说就是这样,在所有的环节中都没有固定的标准,只有经验数据和不断演化的系统性能能力。
我们再接着分析上面的数据。再来看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>
从这个表中可以看到,有两个SQL的执行时间占了总执行时间的94%,显然这两个SQL是要接下来要分析的重点。
我们再接着看这个工具给出的第一个SQL的性能报表:
# 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='交易成功',payTranStatus='P03',payRouteCode='CMA'
WHERE
seqNo='20170619PM010394356875'\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select
resCode='PCX00000',resultMes='交易成功',payTranStatus='P03',payRouteCode='CMA' from mb_trans where
seqNo='20170619PM010394356875'\G
从查询时间分布图上来看,这个语句的执行时间在100ms~1s之间居多,95%的执行时间在2s以下。那么这个SQL就是我们接下来要调优的重点了。
第二个SQL我就不赘述了,因为逻辑是完全一样的。
通过对慢日志的分析,我们可以很快知道哪个SQL是慢的了。当然你用mysqldumpslow
分析,也会得到一样的结果。
SQL剖析:profiling
在分析数据库的性能时,显然对SQL的分析是绕不过去的一个环节。但是我之前也说过了,上来就对SQL进行全面剖析也是不合逻辑的,因为SQL那么多,如果对每个SQL都进行详细的执行步骤解析,显然会拖慢整个系统,而且,对一些执行快的SQL进行分析也没有什么必要,徒增资源消耗。
通过上面的分析过程,我们已经定位到了具体是哪个SQL执行得慢,那么下面就是要知道SQL的执行细节。无论是在Oracle还是在MySQL中,我们都要去看执行计划。
比如说下面这样的:
上图中select_type
是子句类型的意思,有简单有复杂,但是它不能说明什么成本的问题。在这里,最重要的内容是type,因为type可以告诉你访问这个表的时候,是通过什么样的方式访问的。上图中的ALL是全表扫描的意思。type还有如下几个值:
执行计划中的possible_keys
会列出可能使用到的索引值。key这一列会列出执行时使用到的索引值。
以上信息就是MySQL的执行计划中比较重要的部分了。这些信息可以帮助我们做SQL的分析,为优化提供证据。
除了执行计划外,MySQL还提供了profiling
,这个有什么用呢?它可以把SQL执行的每一个步骤详细列出来,从一个SQL进入到数据库中,到执行完这整个生命周期。
MySQL的profiling
在session
级生效,所以当你用了慢日志,知道哪个SQL有问题之后,再用这个功能是最见成效的。如果想一开始就把所有session
的SQL profiling
功能打开,那成本就太高了。
下面我来详细解释一下profiling的用法和功能。
profiling操作步骤
profiling的操作步骤比较简单,如下所示:
步骤一 :set profiling=1; //这一步是为了打开profiling功能
步骤二 :执行语句 //执行你从慢日志中看到的语句
步骤三 :show profiles; //这一步是为了查找步骤二中执行的语句的ID
步骤四 :show profile all for query id; //这一步是为了显示出profiling的结果
我们实际执行一下上面的步骤:
// 步骤一:打开profiling功能
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
// 这一步只是为了确认一下profiles列表有没有值,可以不用执行。
mysql> show profiles;
Empty 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 (14.33 sec)
// 步骤三:查看profiles列表中,有了我们刚才执行的语句
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)
// 步骤四:看这个语句的profile信息
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 |