如何正确理解RT并监控MySQL的响应时间

用户1278550

发布于 2019-11-12 18:19:12

3.1K0

发布于 2019-11-12 18:19:12

文章被收录于专栏：idbaidba

一前言

响应时间(response time 简称RT)是从系统接收请求开始到返回响应之间的时间跨度，是一项极其重要的性能指标。它可以从侧面反映系统的整体吞吐量，也是业务请求(比如sql 请求)的性能好坏的判断依据。

举个例子 A 要从杭州坐飞机到北京机场，经历如下:

从公司到萧山机场 40min
机场安检，候机，登机 40min
飞机飞行  耗时 100min
飞机落地，打的到望京  耗时40min
RT= 40 + 40 + 100 + 40 =220min

其中真正的'执行'时间就飞机飞行的时间(100min+40+40）。其他安检，候机，堵车的都是等待时间。

RT = 等待时间 + 执行时间

假如到机场的过程中发生堵车，或者空中管制导致候机时间延长，整体的RT也会变长，但是飞机飞行时间是相对一定的。从技术的角度来看SQL的请求路径

app <----> (网络建立连接，data传输) <----> proxy <---->(网络建立连接，data传输) <----> mysql(执行)

因为网络问题丢包，重传等导致数据传输时间增加，进而导致总体的RT时间增加，还有常见的案例app服务器cpu飙高导致程序执行的速度变慢，JAVA 程序 GC 等因素也会导致RT升高。所以说 SQL 慢，其实RT就会高。但是反过来 RT高，不一定是SQL慢的原因。如果是开发同学遇到监控尤其是trace系统发现某个接口慢了，并不一定是SQL 慢。

重点 不要把trace系统中的监控rt直接当做db的执行时间

参考案例 Strace 解决性能问题案例一则

二如何监控

前面说了RT的定义以及它所代表意义。接下来我们看看如何监控数据库的RT ，现有的方式主要有两种。

2.1 tcprstat

tcprstat是 Percona 基于 libpcap 研发的工具，是通过测量 TCP 的 request 和 response 所需的时间间隔，适用于一问一答式协议类型的处理。通常用来监测 MySQL 响应时间，或者说是请求在服务器端的处理时间，其输出结果包括了响应时间相关的统计值，用来诊断服务器端性能状况。举个例子

其输出结果包括了时间戳，以及响应时间的最大值、均值、方差等信息，输出信息可以通过 -f 参数进行定制，其中响应时间的单位为微妙。其中对我们比较重要的是:

count:此间隔内处理完成的请求数量。 avg :此间隔内所有完成的请求，响应的平均时间。 95_avg:此间隔内，95%的请求量的平均响应时间，单位微妙，该值较能体现MySQL Server的查询平均响应时间。

如果我们只需要输出 count, 平均时间， 95_avg, 99_avg 则可以用如下命令。

tcprstat -p 3312 -t 1 -n 0 -l ip_address -f '%T\t%n\t%a\t%95a\t%99a\n'

其中format 的具体格式如下，大家可以根据自己的需求来指定各种输出。

如果遇到如下问题

    # tcprstat -p 3312 -t 1 -n 5

    pcap: SIOCGIFFLAGS: bonding_masters: No such device

可以通过指定本地 ip -l local_ip 来解决。

2.2 MySQL 插件

Percona Server 提供一个叫做响应时间区间的功能，将sql耗时在指定区间的请求次数和总共的执行时间记录到表里面。其中时间区间跨度由 query_response_time_range_base 控制。

常用的区间范围为：(0, 0.000001], (0.000001, 0.000010],(0.000010,0.000100],(0.000100,0.001000],(0.001000, 0.010000], (0.010000,0.100000],(0.100000,1.000000],(1,10] 。

从 MySQL 5.6 开始以插件形式安装：

    INSTALL PLUGIN QUERY_RESPONSE_TIME_AUDIT SONAME 'query_response_time.so';
    INSTALL PLUGIN QUERY_RESPONSE_TIME SONAME 'query_response_time.so';
    INSTALL PLUGIN QUERY_RESPONSE_TIME_READ SONAME 'query_response_time.so';
    INSTALL PLUGIN QUERY_RESPONSE_TIME_WRITE SONAME 'query_response_time.so';

然后通过 show plugins 命令检查插件是否安装成功。

    > SHOW PLUGINS;
    ......
    | QUERY_RESPONSE_TIME         | ACTIVE   | INFORMATION SCHEMA | query_response_time.so | GPL     |
    | QUERY_RESPONSE_TIME_AUDIT   | ACTIVE   | AUDIT              | query_response_time.so | GPL     |
    | QUERY_RESPONSE_TIME_READ    | ACTIVE   | INFORMATION SCHEMA | query_response_time.so | GPL     |
    | QUERY_RESPONSE_TIME_WRITE   | ACTIVE   | INFORMATION SCHEMA | query_response_time.so | GPL     |
    +-----------------------------+----------+--------------------+------------------------+---------

安装完成之后在 INFORMATION_SCHEMA 生成三张表

`QUERY_RESPONSE_TIME_WRITE` 记录所有写请求的响应时间分布
`QUERY_RESPONSE_TIME_READ`  记录所有读请求的响应时间分布
`QUERY_RESPONSE_TIME` 可以认为是所有请求的响应时间分布。

查看 QUERY_RESPONSE_TIME的内容

查询结果中 717个sql请求耗时在 (0, 0.000001]之间。47898个sql请求的耗时在(0.000001, 0.000010]，总耗时0.29秒，其他以此类推。需要注意的是 count 和total是累计值，监控的时候需要取后值减前值除以采样的时间间隔。

如何开启响应时间统计

在命令行中执行

SET GLOBAL query_response_time_stats = 1 ;

在 my.cnf 中

query_response_time_stats = 1

重置(将数据清零)三张表的统计值

SET GLOBAL query_response_time_flush='ON';

常用的sql

INFORMATION_SCHEMA [RW][TEST:qa_single_0:3312] 11:50:44 >SELECT c.count, c.time, (SELECT SUM(a.count) FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME as a WHERE a.count != 0) as query_count, (SELECT COUNT(*)     FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME as b WHERE b.count != 0) as not_zero_region_count, (SELECT COUNT(*)     FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME) as region_count FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME as c WHERE c.count > 0;
+-------+----------------+-------------+-----------------------+--------------+
| count | time           | query_count | not_zero_region_count | region_count |
+-------+----------------+-------------+-----------------------+--------------+
|     1 |       0.000001 |       71370 |                     7 |           14 |
|    86 |       0.000010 |       71370 |                     7 |           14 |
| 47375 |       0.000100 |       71370 |                     7 |           14 |
| 23404 |       0.001000 |       71370 |                     7 |           14 |
|   423 |       0.010000 |       71370 |                     7 |           14 |
|    79 |       0.100000 |       71370 |                     7 |           14 |
|     2 |       1.000000 |       71370 |                     7 |           14 |
+-------+----------------+-------------+-----------------------+--------------+

通过监控脚本获取响应时间的数据在grafna展示的结果如下: