【性能調優】一次關於慢查詢及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毫秒，完成知足系統上線要求。