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

小程序：扫一扫查出行
【扫一扫了解最新限行尾号】
复制小程序

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

一、系统架构

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

同时因为消费者只能得到接口，而无法看到接口的实现，也保证了服务者的安全。

服务注册与调用

脚本实现接口调用

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

二、现象及问题

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

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

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

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

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

三、分析思路及解决方法

主要分析思路可以从以下几个方面考虑：

1、业务问题，系统代码本身业务逻辑问题，如：事务失败率；

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

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

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

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

6、其它方面等等。

问题排查及解决

1、首先，controller中系统没有出现业务失败，查看日志，没有发现有错误日志，所以可以初步排查代码逻辑处理失败；

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

打开慢查询：

 mysql> show variables like "slow_query_log%";

 +-----------------------------------+---------------------------------+

 | Variable_name                     | Value                           |

 +-----------------------------------+---------------------------------+

 | slow_query_log                    | ON                              |

 | slow_query_log_always_write_time  | 10.000000                       |

 | slow_query_log_file               | /disk1/mysql5.7.21/tmp/slow.log |//慢查询日志存放路径

 | slow_query_log_use_global_control |                                 |

 +-----------------------------------+---------------------------------+

 4 rows in set (0.00 sec)

 //设置慢查询开关，0代表关闭慢查询，1代表打开慢查询。

 mysql> set global slow_query_log = 1;

 Query OK, 0 rows affected (0.00 sec)

 //查看慢查询时间

 mysql> show variables like "long_query%";

 +-----------------+----------+

 | Variable_name   | Value    |

 +-----------------+----------+

 | long_query_time | 2.000000 |

 +-----------------+----------+

 1 row in set (0.00 sec)

 //设置慢查询为1秒

 mysql> set long_query_time=1;

 Query OK, 0 rows affected (0.00 sec)

 mysql>

通过查看慢查询日志，找到慢查询sql，如下：

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

如何查看执行计划：

 mysql> explain select * from test;

 +----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+

 | id | select_type | table | partitions | type  | possible_keys | key     | key_len | ref  | rows | filtered | Extra       |

 +----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+

 |  1 | SIMPLE      | test  | NULL       | index | NULL          | PRIMARY | 4       | NULL |    6 |   100.00 | Using index |

 +----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+

 1 row in set, 1 warning (0.00 sec)

 mysql>

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

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

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

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

System>const>eq_ref>ref>fulltext>ref_or_null>index_merge>uniqe_subquery>index_subquery>range>index>ALL,一般来说，好的sql查询至少能达到range级，做好为ref。

3、Key:实际使用的索引，如果未NULL，则没有使用索引；

4、rows：根据表统计信息及索引选取情况，大致估算出找到所需的记录所需要的行数，一般该值越小越好；

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

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

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

 mysql> show variables like "%profiling%";

 +------------------------+-------+

 | Variable_name          | Value |

 +------------------------+-------+

 | have_profiling         | YES   |

 | profiling              | OFF   |

 | profiling_history_size | 15    |

 +------------------------+-------+

 3 rows in set (0.00 sec)

 //设置profiling开关，1代表打开，0代表关闭

 mysql> set profiling=1;

 Query OK, 0 rows affected, 1 warning (0.00 sec)

 //执行sql语句

 mysql> select * from test;

 +----+

 | id |

 +----+

 |  1 |

 |  2 |

 |  3 |

 |  4 |

 |  5 |

 |  6 |

 | 10 |

 +----+

 7 rows in set (0.00 sec)

 //查看profiles文件

 mysql> show profiles;

 +----------+------------+--------------------+

 | Query_ID | Duration   | Query              |

 +----------+------------+--------------------+

 |        1 | 0.00037925 | select * from test |

 +----------+------------+--------------------+

 1 row in set, 1 warning (0.00 sec)

 //查看profile文件中，第一个查询的profile情况，查看时间消耗在哪里

 mysql> show profile for query 1;

 +----------------------+----------+

 | Status               | Duration |

 +----------------------+----------+

 | starting             | 0.000065 |//开始

 | checking permissions | 0.000009 |//检查权限

 | Opening tables       | 0.000043 |//打开表

 | init                 | 0.000027 |//初始化

 | System lock          | 0.000014 |//系统锁

 | optimizing           | 0.000004 |//优化

 | statistics           | 0.000016 |//统计

 | preparing            | 0.000011 |//准备

 | executing            | 0.000002 |//执行

 | Sending data         | 0.000113 |//发送数据

 | end                  | 0.000004 |//结束

 | query end            | 0.000008 |//查询结束

 | closing tables       | 0.000008 |//关闭表/删除TEMP表

 | freeing items        | 0.000022 |//释放items

 | cleaning up          | 0.000037 |//清理

 +----------------------+----------+

 15 rows in set, 1 warning (0.00 sec)