【Mysql】Mysql負載過大，app訪問延遲

1. 我們一般先看整體負載如何，負載高的話，肯定所有的程式跑起來都慢
2. [yejr@imysql.com:~ ]# w 11:52:58 up 702 days, 56 min, 1 user, load average: 7.20, 6.70, 6.47 USER TTY FROM LOGIN@ IDLE JCPU PCPU WHAT root pts/0 1.xx.xx.xx 11:51 0.00s 0.03s 0.00s w

或者 sar -q 的觀察結果
[yejr@imysql.com:~ ]# sar -q 1 Linux 2.6.32-431.el6.x86_64 (yejr.imysql.com) 01/13/2016 _x86_64_ (24 CPU) 02:51:18 PM runq-sz plist-sz ldavg-1 ldavg-5 ldavg-15 blocked 02:51:19 PM 4 2305 6.41 6.98 7.12 3 02:51:20 PM 2 2301 6.41 6.98 7.12 4 02:51:21 PM 0 2300 6.41 6.98 7.12 5 02:51:22 PM 6 2301 6.41 6.98 7.12 8 02:51:23 PM 2 2290 6.41 6.98 7.12 8

load average大意表示當前CPU中有多少任務在排隊等待，等待越多說明負載越高，跑資料庫的伺服器上，一般load值超過5的話，已經算是比較高的了。

我們可以看到此時系統的負載有點高
點選(此處)摺疊或開啟

1. 某些程式/服務消耗更多CPU資源（服務響應更多請求或存在某些應用瓶頸）；
   
2. 發生比較嚴重的swap（可用實體記憶體不足）；
   
3. 發生比較嚴重的中斷（因為SSD或網路的原因發生中斷）；
   
4. 磁碟I/O比較慢（會導致CPU一直等待磁碟I/O請求）；

這時我們可以執行下面的命令來判斷到底瓶頸在哪個子系統

1. top命令
2. [yejr@imysql.com:~ ]# top top - 11:53:04 up 702 days, 56 min, 1 user, load average: 7.18, 6.70, 6.47 Tasks: 576 total, 1 running, 575 sleeping, 0 stopped, 0 zombie Cpu(s): 7.7%us, 3.4%sy, 0.0%ni, 77.6%id, 11.0%wa, 0.0%hi, 0.3%si, 0.0%st ----%us 和 %wa 的值較高，表示當前比較大的瓶頸可能是在使用者程式消耗的CPU以及磁碟I/O等待上。
3. Mem: 49374024k total, 32018844k used, 17355180k free, 115416k buffers Swap: 16777208k total, 117612k used, 16659596k free, 5689020k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 14165 mysql 20 0 8822m 3.1g 4672 S 162.3 6.6 89839:59 mysqld 40610 mysql 20 0 25.6g 14g 8336 S 121.7 31.5 282809:08 mysqld 49023 mysql 20 0 16.9g 5.1g 4772 S 4.6 10.8 34940:09 mysqld
   

如果%us過高

1. 1：有大量的排序工作
   
2. 2：sql索引不合理
3. 檢視慢日誌，分析最佳化SQL

如果%sy過高

1. 1.sys佔用cpu過高，並且swap大量使用而memory還有剩餘。表示NUMA沒關，關了就好了
   
2. 
   
3. 2.sys佔用cpu過高，可以使用perf top（centos6.0之後的命令）檢視核心的具體使用情況

%sys過高還可以參考下面這篇文章

既然wait比較高，那麼就要分析一下磁碟的io了

1. [root@HaoDai_App_DB01 ~]# iostat -x -m 2
   Linux 2.6.32-504.16.2.el6.x86_64 (HaoDai_App_DB01)      03/18/2016      _x86_64_        (40 CPU)
   
   
   avg-cpu:  %user   %nice %system %iowait  %steal   %idle
              4.29    0.00    0.20    0.05    0.00   95.46
   
   
   Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
   sda               0.00     2.97    0.04    0.48     0.00     0.01    72.81     0.00    0.49   0.28   0.01
   sdb               0.00   143.43    0.00  131.67     0.00     1.04    16.10     0.01    0.10   0.07   0.91
   
   
   avg-cpu:  %user   %nice %system %iowait  %steal   %idle
             12.54    0.00    0.38    0.03    0.00   87.06
   
   
   Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
   sda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
   sdb               0.00   174.00    0.00  137.50     0.00     1.17    17.40     0.03    0.19   0.14   1.95
   
   
2. 如果，吞吐量（rMB/s+wMB/s)過低，但是util過高表示：隨機io特別的嚴重（可用pt-ioprofile去定位導致問題出現的表）
3. IOPS=R/s+W/s

再利用 iotop 確認到底哪些程式消耗的磁碟I/O資源最多：

1. Total DISK READ: 60.38 M/s | Total DISK WRITE: 640.34 K/s
   
2.   TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
   
3. 16397 be/4 mysql 8.92 M/s 0.00 B/s 0.00 % 94.77 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320       ---排前面的都是mysql
   
4.  7295 be/4 mysql 10.98 M/s 0.00 B/s 0.00 % 93.59 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320
   
5. 14295 be/4 mysql 10.50 M/s 0.00 B/s 0.00 % 93.57 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320
   
6. 14288 be/4 mysql 14.30 M/s 0.00 B/s 0.00 % 91.86 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320
   
7. 14292 be/4 mysql 14.37 M/s 0.00 B/s 0.00 % 91.23 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320
8. 。
   
9. 可以看到，埠號是3320的例項消耗的磁碟I/O資源比較多，那就看看這個例項裡都有什麼查詢在跑吧。

2：接著從mysql層面去檢查

1. 1檢查一下併發以及mysql是那些語句再執行
   
   1. [yejr@imysql.com(db)]> mysqladmin processlist|grep -v Sleep +----+----+----------+----+-------+-----+--------------+-----------------------------------------------------------------------------------------------+ | Id |User| Host | db |Command|Time | State | Info | +----+----+----------+----+-------+-----+--------------+-----------------------------------------------------------------------------------------------+ | 25 | x | 10.x:8519 | db | Query | 68 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>404612 order by Fvideoid) t1 | | 26 | x | 10.x:8520 | db | Query | 65 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>484915 order by Fvideoid) t1 | | 28 | x | 10.x:8522 | db | Query | 130 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>404641 order by Fvideoid) t1 | | 27 | x | 10.x:8521 | db | Query | 167 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>324157 order by Fvideoid) t1 | | 36 | x | 10.x:8727 | db | Query | 174 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>324346 order by Fvideoid) t1 | +----+----+----------+----+-------+-----+--------------+-----------------------------------------------------------------------------------------------+
      
      
   
   
2. 2：可以看到有不少慢查詢還未完成，從slow query log中也能發現，這類SQL發生的頻率很高。這是一個非常低效的SQL寫法，導致需要對整個主鍵進行掃描，但實際上只需要取得一個最大值而已，從slow query log中可看到
3. Rows_sent: 1 Rows_examined: 5502460

4. 每次都要掃描500多萬行資料，卻只為讀取一個最大值，效率非常低。

   經過分析，這個SQL稍做簡單改造即可在個位數毫秒級內完成，原先則是需要150-180秒才能完成，提升了N次方。
   改造的方法是：對查詢結果做一次倒序排序，取得第一條記錄即可。而原先的做法是對結果正序排序，取最後一條記錄，汗啊。。

在這個例子中，產生瓶頸的原因比較好定位，SQL最佳化也不難，實際線上環境中，通常有以下幾種常見的原因導致負載較高：

1. 一次請求讀寫的資料量太大，導致磁碟I/O讀寫值較大，例如一個SQL裡要讀取或更新幾萬行資料甚至更多，這種最好是想辦法減少一次讀寫的資料量；
2. SQL查詢中沒有適當的索引可以用來完成條件過濾、排序（ORDER BY）、分組（GROUP BY）、資料聚合（MIN/MAX/COUNT/AVG等），新增索引或者進行SQL改寫吧；
3. 瞬間突發有大量請求，這種一般只要能扛過峰值就好，保險起見還是要適當提高伺服器的配置，萬一峰值抗不過去就可能發生雪崩效應；
4. 因為某些定時任務引起的負載升高，比如做資料統計分析和備份，這種對CPU、記憶體、磁碟I/O消耗都很大，最好放在獨立的slave伺服器上執行；
5. 伺服器自身的節能策略發現負載較低時會讓CPU降頻，當發現負載升高時再自動升頻，但通常不是那麼及時，結果導致CPU效能不足，抗不過突發的請求；
6. 使用raid卡的時候，通常配備BBU（cache模組的備用電池），早期一般採用鋰電池技術，需要定期充放電（DELL伺服器90天一次，IBM是30天），我們可以透過監控在下一次充放電的時間前在業務低谷時提前對其進行放電，不過新一代伺服器大多采用電容式電池，也就不存在這個問題了。
7. 檔案系統採用ext4甚至ext3，而不是xfs，在高I/O壓力時，很可能導致%util已經跑到100%了，但iops卻無法再提升，換成xfs一般可獲得大幅提升；
8. 核心的io scheduler策略採用cfq而非deadline或noop，可以線上直接調整，也可獲得大幅提升。
9. 基本如果%us使用過高 或者 %us和%iowait都高，一般都是併發時的sql寫的不好導致的

用這個思路來分析一下我們生產上157負載高的原因（19:00持續到19:05）

1. 1  uptime  w 檢查負載已經達到了50了，，物理cpu個數 : 2 每個物理CPU核心個數 : 10
   
2. 很明顯負載比較高了
3. 
   

  2  top檢視 分析cpu
  cpu_iowait如圖：

顯示的iowait不高啊，暫時排除io導致的系統負載高

cpu_user如圖：

19:00左右顯示的使用者程式消耗的CPU基本快100%了

看一下記憶體也沒問題


登入mysql檢視，顯示併發達到1000多了，因為7點有一個搶單活動，純併發導致的系統壓力啊！！可以檢查一下慢sql
看下這篇文件：
雖然不是慢sql但是最佳化一下就好了 壓力與負載都降下來了
 

補充一點：

在這個case裡涉及到的鎖有記錄鎖、lock_sys->mutex和trx_sys->mutex，究竟是哪個鎖等待時間最長呢？我們可以用下面的方法確認一下：

mysql> SELECT COUNT_STAR, SUM_TIMER_WAIT, AVG_TIMER_WAIT, EVENT_NAME FROM performance_schema.events_waits_summary_global_by_event_name where COUNT_STAR > 0 and EVENT_NAME like 'wait/synch/%' order by SUM_TIMER_WAIT desc limit 10; +------------+------------------+----------------+--------------------------------------------+ | COUNT_STAR | SUM_TIMER_WAIT   | AVG_TIMER_WAIT | EVENT_NAME                                 |
+------------+------------------+----------------+--------------------------------------------+ |   36847781 | 1052968694795446 |       28575867 | wait/synch/mutex/innodb/lock_mutex         |
|       8096 |   81663413514785 |    10086883818 | wait/synch/cond/threadpool/timer_cond      |
|         19 |    3219754571347 |   169460766775 | wait/synch/cond/threadpool/worker_cond     |
|   12318491 |    1928008466219 |         156446 | wait/synch/mutex/innodb/trx_sys_mutex      |
|   36481800 |    1294486175099 |          35397 | wait/synch/mutex/innodb/trx_mutex          |
|   14792965 |     459532479943 |          31027 | wait/synch/mutex/innodb/os_mutex           |
|    2457971 |      62564589052 |          25346 | wait/synch/mutex/innodb/mutex_list_mutex   |
|    2457939 |      62188866940 |          24909 | wait/synch/mutex/innodb/rw_lock_list_mutex |
|     201370 |      32882813144 |         163001 | wait/synch/rwlock/innodb/hash_table_locks  |
|       1555 |      15321632528 |        9853039 | wait/synch/mutex/innodb/dict_sys_mutex     |
+------------+------------------+----------------+--------------------------------------------+ 10 rows in set (0.01 sec) 

從上面的表可以確認，lock_mutex（在MySQL原始碼裡對應的是lock_sys->mutex）的鎖等待累積時間最長（SUM_TIMER_WAIT）。lock_sys表示全域性的InnoDB鎖系統，在原始碼裡看到InnoDB加/解某個記錄鎖的時候（這個case裡是X鎖），同時需要維護lock_sys，這時會請求lock_sys->mutex。

在這個case裡，因為在Searching rows for update的階段頻繁地加/解X鎖，就會頻繁請求lock_sys->mutex，導致lock_sys->mutex鎖總等待時間過長，同時在等待的時候消耗了大量CPU。