以下来分享一个关于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、其次，先解决比较明显的问题，那个响应时间过长的接口，通常我们先想到的就是可能存在慢查询问题；
打开慢查询：
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
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进行分析，看时间具体消耗在哪里
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毫秒
3、系统业务处理能力弱且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毫秒，完成满足系统上线要求。