【性能调优】一次关于慢查询及FGC频繁的调优经历

　　如下来分享一个关于MySQL数据库慢查询和FGC频繁的性能案例。

1、系统架构

　　

 　　

　　一个简单的dubbo服务，服务提供者提供接口，而且提供接口的实现，提供方注册服务到Zookeeper注册中心，而后消费者要用其某个服务的时候，就去zookeeper上订阅该服务。这样，咱们只须要使用接口，而后经过spring getbean，就可让这个接口实例化，拿来使用，经过传参去Mysql数据库查询数据。

    同时由于消费者只能获得接口，而没法看到接口的实现，也保证了服务者的安全。

服务注册与调用

脚本实现接口调用

 

关于如何编写dubbo服务脚本可参考上篇文章： https://www.cnblogs.com/zhang-zhi/p/9929447.html

2、现象及问题

　　上图为10用户并发时，系统的总体性能表现，包括TPS与平均响应时间指标。

从上图能够看出，该系统主要存在如下方面几个问题：

一、其中一个事务响应时间过长，超过1秒；

二、部分接口响应时间波动较大；         

三、系统业务处理能力：即TPS，存在波动且起伏加大。

 3、分析思路及解决方法

主要分析思路能够从如下几个方面考虑：

一、业务问题，系统代码自己业务逻辑问题，如：事务失败率；

二、系统服务器资源出现瓶颈致使，如：CPU、内存、I/O等；

三、数据库层面问题，如：慢查询；

四、java应用的堆内存相关；

五、受第三方系统的问题影响；

六、其它方面等等。

问题排查及解决

一、首先，controller中系统没有出现业务失败，查看日志，没有发现有错误日志，因此能够初步排查代码逻辑处理失败；

二、其次，先解决比较明显的问题，那个响应时间过长的接口，一般咱们先想到的就是可能存在慢查询问题；

打开慢查询：

 1 mysql> show variables like "slow_query_log%";
 2 +-----------------------------------+---------------------------------+
 3 | Variable_name                     | Value                           |
 4 +-----------------------------------+---------------------------------+
 5 | slow_query_log                    | ON                              |
 6 | slow_query_log_always_write_time  | 10.000000                       |
 7 | slow_query_log_file               | /disk1/mysql5.7.21/tmp/slow.log |//慢查询日志存放路径
 8 | slow_query_log_use_global_control |                                 |
 9 +-----------------------------------+---------------------------------+
10 4 rows in set (0.00 sec)
11 //设置慢查询开关，0表明关闭慢查询，1表明打开慢查询。
12 mysql> set global slow_query_log = 1;
13 Query OK, 0 rows affected (0.00 sec)
14 //查看慢查询时间
15 mysql> show variables like "long_query%";
16 +-----------------+----------+
17 | Variable_name   | Value    |
18 +-----------------+----------+
19 | long_query_time | 2.000000 |
20 +-----------------+----------+
21 1 row in set (0.00 sec)
22 //设置慢查询为1秒
23 mysql> set long_query_time=1;
24 Query OK, 0 rows affected (0.00 sec)
25 
26 mysql> 

 经过查看慢查询日志，找到慢查询sql，以下：

　　①接下来，对找到的sql进行分析，查看sql执行计划：

如何查看执行计划：

1 mysql> explain select * from test;
2 +----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
3 | id | select_type | table | partitions | type  | possible_keys | key     | key_len | ref  | rows | filtered | Extra       |
4 +----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
5 |  1 | SIMPLE      | test  | NULL       | index | NULL          | PRIMARY | 4       | NULL |    6 |   100.00 | Using index |
6 +----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
7 1 row in set, 1 warning (0.00 sec)
8 
9 mysql> 

 如下是本次发现慢查询sql的执行计划：

其中最重要的字段为：id、type、key、rows、Extra

一、id：select查询中的序列号，包含一组数字，表示查询中执行select字句或操做表的顺序；

二、type：访问类型，sql查询优化一个很重要的指标，结果值从好到坏依次是：

System>const>eq_ref>ref>fulltext>ref_or_null>index_merge>uniqe_subquery>index_subquery>range>index>ALL,通常来讲，好的sql查询至少能达到range级，作好为ref。

三、Key:实际使用的索引，若是未NULL，则没有使用索引；

四、rows：根据表统计信息及索引选取状况，大体估算出找到所需的记录所须要的行数，通常该值越小越好；

五、Extra：不适合在其它字段中显示，可是十分重要的额外信息。

　　从sql的执行计划明显能够看出，sql缺乏相应的索引致使出现慢查询问题，与开发确认后，添加索引后，该接口的响应时间明显变快，如下为添加索引后的sql执行计划。

　　②也能够打开profile功能，对sql进行分析，看时间具体消耗在哪里

 1 mysql> show variables like "%profiling%";
 2 +------------------------+-------+
 3 | Variable_name          | Value |
 4 +------------------------+-------+
 5 | have_profiling         | YES   |
 6 | profiling              | OFF   |
 7 | profiling_history_size | 15    |
 8 +------------------------+-------+
 9 3 rows in set (0.00 sec)
10 //设置profiling开关，1表明打开，0表明关闭
11 mysql> set profiling=1;
12 Query OK, 0 rows affected, 1 warning (0.00 sec)
13 //执行sql语句
14 mysql> select * from test;
15 +----+
16 | id |
17 +----+
18 |  1 |
19 |  2 |
20 |  3 |
21 |  4 |
22 |  5 |
23 |  6 |
24 | 10 |
25 +----+
26 7 rows in set (0.00 sec)
27 //查看profiles文件
28 mysql> show profiles;
29 +----------+------------+--------------------+
30 | Query_ID | Duration   | Query              |
31 +----------+------------+--------------------+
32 |        1 | 0.00037925 | select * from test |
33 +----------+------------+--------------------+
34 1 row in set, 1 warning (0.00 sec)
35 //查看profile文件中，第一个查询的profile状况，查看时间消耗在哪里
36 mysql> show profile for query 1;
37 +----------------------+----------+
38 | Status               | Duration |
39 +----------------------+----------+
40 | starting             | 0.000065 |//开始
41 | checking permissions | 0.000009 |//检查权限
42 | Opening tables       | 0.000043 |//打开表
43 | init                 | 0.000027 |//初始化
44 | System lock          | 0.000014 |//系统锁
45 | optimizing           | 0.000004 |//优化
46 | statistics           | 0.000016 |//统计
47 | preparing            | 0.000011 |//准备
48 | executing            | 0.000002 |//执行
49 | Sending data         | 0.000113 |//发送数据
50 | end                  | 0.000004 |//结束
51 | query end            | 0.000008 |//查询结束
52 | closing tables       | 0.000008 |//关闭表/删除TEMP表
53 | freeing items        | 0.000022 |//释放items
54 | cleaning up          | 0.000037 |//清理
55 +----------------------+----------+
56 15 rows in set, 1 warning (0.00 sec)

  　　慢查询sql的profiling结果为：

优化后的sql  profiling结果:

优化后，单笔查询响应时间大大缩短，约为2毫秒

三、系统业务处理能力弱且TPS波动较大问题，能够先查看系统应用服务器或其它一些组件的CPU资源使用率及线程栈信息，看是否存在线程阻塞或死锁问题。

nmon查看CPU资源使用状况

vmstat -Sm 1--查看系统内存、cpu等资源使用状况

　　CPU、内存资源消耗能够看出，一切都很很正常，经过jstack命令查看线程栈信息，也不存在线程阻塞及死锁问题，因此能够排除这方面的缘由。

　　由于系统TPS波动很大，咱们能够看一下系统的GC状况。

　　jstat -gcutil pid 1000

　　

　　发现FGC频繁，大约2秒一次，找到问题所在，接着看一下JVM的对内存分配状况

　　jmap -heap pid

　　

 

　　解决方法：

　　将JVM的启动参数设置为：-Xms4096M -Xmx4096M,重启系统，在一样的压力下，进行测试，获得优化后的测试结果为：

　　TPS截图：

　　

　　RT截图：

　　

　　

　　优化后，系统性能表现明显提高，TPS能够达到3000笔/秒，系统响应时间约为100毫秒，完成知足系统上线要求。