菜鳥排查數據庫異常的事

這件事情起源於上個月作的微信公衆號項目，在項目上線初期，運行平穩，數據庫並無出現異常。

問題出如今微信公衆號推送活動消息後，數據庫cpu直接滿載,並且鏈接數到達了設置的最大值，新用戶打不開或者打開很慢。當時監控顯示的狀況很糟糕。

面對這樣的狀況,運維的兄弟多開了幾臺tomcat試圖來緩減，當時後來的狀況是並無luan用，新開的服務器的負載很快也變的很高，狀況依舊。並且當時的狀況也很趕，各方面都在催，咱們選擇了將數據庫讀寫操做量大的用戶表的操做轉移到redis中這樣一種方式避開對數據的操做，上線後狀況獲得改善，線上的事情告一段落，後面就是排查問題的階段了。

---

到了秋後算帳的時間，要排查問題的所在，首先抓取了一些可能有用的日誌，當時的日誌狀況是這樣的。

SEVERE: Servlet.service() for servlet [web-dispatcher] in context with path [/******] threw exception [Request processing failed; nested exception is org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException:
### Error querying database.  Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 5000, active 73

這個日誌所反映的問題，並且考慮到出問題的時候都是在併發量大的狀況下，第一反應是druid的鏈接池出了問題（在上線的時候也是這麼認爲的，運維哥們專業黑druid　500年啊...），因爲鏈接池沒有及時回收無用的鏈接，致使鏈接池的鏈接數達到了maxActive（設置的鏈接池最大使用鏈接數），使新的鏈接一直處在等待中，直至等待時間超過了獲取鏈接最大等待時間從而拋出異常。從這一角度出發，在作單元測試的時候，將druid的timeout的時間大大的延長，並將清除無用鏈接的等待時間縮短，寄但願於druid的鏈接池處理大量鏈接時將無用的鏈接釋放掉，在跑單元測試的時候確實跑出異常的狀況有所改善，拋出異常的時間延後了，給人的感受是穩定跑的時間長了，可是從實際狀況來講，只是鏈接等待時間的閾值提升了，對問題的解決沒有幫助，從這一方面來排查的結果以失敗了結。

因爲原先裝的是Mysql的衍生版本mariadb，運維兄弟說排查下是否是mysql自身的問題，就給配了一臺裝了原版5.6的服務器。把測試數據庫上的數據dump到了5.6裏，而後進行壓測，在監控上，一樣是數據庫鏈接數很高，並且cpu基本上滿載了，問題沒有獲得改善，能夠認爲這個問題基本與數據庫的版本無關。

斷斷續續的測試了幾天，老是不得要領，事情到這裏我這個菜鳥就感受無從下手了。問了師傅，他老人家說從慢查詢日誌上看看狀況，其實好久之前他就說過，只是我看了之後也沒看出啥問題(菜鳥就是菜鳥啊)，當時看日誌只關注了sql語句，只是時間確實很長，但對於爲啥這麼慢卻一直不知道從哪裏入手。這期間，也優化過一些東西，好比把查詢的時候UNION的操做從原來在數據庫級別搞到在後臺進行，在數據庫級只是進行select的操做，union的操做人工的進行，也有很大的提高，可是因爲在慢查詢日誌中大量的是單條select的查詢操做，union只佔了一小部分，因此最根本的問題沒有解決，測試的時候負載依舊會很高，而後超時致使錯誤率很高。

回頭想一想，幾天前犯了個大錯誤，看日誌只片面的看一部分，沒有對各個參數有所瞭解，漏了重要的一些參數。某天睡醒是後看了慢查詢日誌，發現之前沒注意到的一個參數，就是Rows_examined，日誌每條信息中它的值都很大，能夠認爲是目標表裏的全部數據的數目了，換句話說，在查詢的時候，沒有任何優化作了全表的檢索，時間耗在了這裏。這時候就有了一點點的思路，既然問題出在查詢的時候特別慢，那麼在數據庫中對查詢的性能影響很大的索引就成爲了重點關注對象。

Query_time: 4.107505  Lock_time: 0.000154  Rows_sent: 1  Rows_examined: 259017

有了這樣一個初步的排查的目標，下面就是驗證階段了，看了不一樣服務器上數據庫的表，發現創建的索引都不一致，有些是創建正確的，有些是錯誤的（形成不一致的緣由多是某個時間看到了發現了問題，就改正了這一錯誤，可是當時沒有將全部的數據庫改過來，測試時候用的服務器仍舊是有問題的）。驗證的話就是簡單的對比實驗：代碼和壓測的線程數和服務器等條件都一致，惟一的不一樣就在於數據庫索引的不一樣，一個是正確的索引，一個是出問題時候的索引，進行壓力測試，在測試期間利用jstack抓取進程，並對日誌進行分析。結果以下，經過對比，基本得出是由於索引的問題了，若是後面還發現了這樣的異常，那就另外排查了。

mysql> explain select *  from   user_info where  openid = 'aaaaaaaaaaaaaaaaaaaaaaaa';
+------+-------------+-------------------+------+---------------+------+---------+------+---------+-------------+
| id   | select_type | table             | type | possible_keys | key  | key_len | ref  | rows    | Extra       |
+------+-------------+-------------------+------+---------------+------+---------+------+---------+-------------+
|    1 | SIMPLE      | lottery_user_info | ALL  | NULL          | NULL | NULL    | NULL | 1182759 | Using where |
+------+-------------+-------------------+------+---------------+------+---------+------+---------+-------------+
1 row in set (0.01 sec)

mysql> explain select *  from   user_info where  openid = 'aaaaaaaaaaaaaaaaaaaaaaaa';
+------+-------------+-------------------+------+---------------+--------------+---------+-------+------+-----------------------+
| id   | select_type | table             | type | possible_keys | key          | key_len | ref   | rows | Extra                 |
+------+-------------+-------------------+------+---------------+--------------+---------+-------+------+-----------------------+
|    1 | SIMPLE      | user_info | ref  | openid_index  | openid_index | 98      | const |    1 | Using index condition |
+------+-------------+-------------------+------+---------------+--------------+---------+-------+------+-----------------------+
1 row in set (0.01 sec)

對於這樣一個情況的排查直到初步得出結論，感受本身走了好多的彎路，選擇了從上倒下的排查這樣一個步驟，當初若是選擇從最基礎的數據庫設計和語句方面入手的話，可能會節約不少的時間。不過排查的時間久也有好處，最起碼學習了不少新知識(自我安慰下)。

學識淺薄，若是有不對的地方，煩請不吝賜教，謝謝。