以下來分享一個關於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毫秒，完成滿足系統上線要求。