MySQL資料庫診斷：InnoDB關機問題

問題描述，今天發現一臺db伺服器，錯誤日誌中有innodb 報錯資訊，具體如下：

space 1131 offset 1221565 (448 records, index id 2730)
 206 InnoDB: Submit a detailed bug report to http://bugs.mysql.com
 209 2015-01-27 14:47:03 30309 [Warning] 'proxies_priv' entry '@ root@cndb012.5405.zr.sh.gcimg.net
     ' ignored in --skip-name-resolve mode.
 210 InnoDB: Warning: a long semaphore wait:
 211 --Thread 139840252565248 has waited at row0upd.cc line 2391 for 241.00 seconds the semaphore:
 212 X-lock (wait_ex) on RW-latch at 0x7f30e81ffec0 created in file buf0buf.cc line 994
 213 a writer (thread id 139840252565248) has reserved it in mode  wait exclusive
 214 number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
 215 Last time read locked in file btr0sea.cc line 931
 216 Last time write locked in file /root/mysql-5.6.10/storage/innobase/row/row0upd.cc line 2391
 217 InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
 218 InnoDB: Pending preads 1, pwrites 0
 219 
 220 =====================================
 221 2015-02-17 01:33:24 7f2f1c5cd700 INNODB MONITOR OUTPUT
 222 =====================================
 223 Per second averages calculated from the last 9 seconds
 224 -----------------
 225 BACKGROUND THREAD
 226 -----------------
 227 srv_master_thread loops: 9485924 srv_active, 0 srv_shutdown, 12079 srv_idle                  
 228 srv_master_thread log flush and writes: 9498003
 229 ----------
 230 SEMAPHORES
 231 ----------
 232 OS WAIT ARRAY INFO: reservation count 20878957
 233 --Thread 139840305547008 has waited at srv0srv.cc line 2642 for 0.00 seconds the semaphore:
 234 X-lock (wait_ex) on RW-latch at 0x17dcce78 created in file trx0purge.cc line 128
 235 a writer (thread id 139840305547008) has reserved it in mode  wait exclusive
cndb012.5405.zr.sh.gcimg.net.err                                                227,1          11%
a writer (thread id 139840252565248) has reserved it in mode  wait exclusive                 
 242 number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
 243 Last time read locked in file btr0sea.cc line 931
 244 Last time write locked in file /root/mysql-5.6.10/storage/innobase/row/row0upd.cc line 2391
 245 OS WAIT ARRAY INFO: signal count 24461907
 246 Mutex spin waits 46796216, rounds 120553500, OS waits 2922505
 247 RW-shared spins 27488053, rounds 494141792, OS waits 11545932
 248 RW-excl spins 6660716, rounds 158988739, OS waits 3758819
 249 Spin rounds per wait: 2.58 mutex, 17.98 RW-shared, 23.87 RW-excl
 250 ------------
 251 TRANSACTIONS
 252 ------------
 253 Trx id counter 34084627765
 254 Purge done for trx's n:o < 33966059091 undo n:o < 0 state: running but idle
 255 History list length 58473189
 256 LIST OF TRANSACTIONS FOR EACH SESSION:
 257 ---TRANSACTION 34084627619, ACTIVE 207 sec
 258 MySQL thread id 10667405, OS thread handle 0x7f2f164f6700, query id 6964941502 192.168.2.55 m
     ha_user cleaning up
 259 Trx read view will not see trx with id >= 34084627620, sees < 33966059089
 260 ---TRANSACTION 34084627590, ACTIVE 243 sec

。。。。。。。。。。。。。。。。。擷取部分日誌，網上搜到姜老師寫的文章，拿來

 儲存，學習，共享

前段時間遇到一個問題，DBA反映有臺MySQL資料庫非常詭異，在無任何操作的前提下，磁碟IO負載都幾乎跑滿。然後跑了3、4個小時磁碟負載依舊。DBA的初步判斷認為是RAID卡出了問題(之前遇到過類似RAID卡BBU問題導致負載較高)。不過既然是資料庫無任何操作，那麼即使RAID卡出現問題，也不應該出現這個問題。因此在調查了問題現場後，詢問了DBA之前做了哪些操作，之後我便大致定位到了問題所在。

　　DBA的反饋是之前在做sysbench的全update效能測試，測試完成後就關閉了資料庫。但是當再重啟後就發現這個現象，並且等待3，4個小時候後問題依舊。待其敘述完後，我的第一反映是srv_innodb_fast_shutdown預設值為1，在關閉是不會對change buffer進行合併操作，因此會再下次啟動時進行這類操作。因為MySQL 5.5版本InnoDB儲存引擎的change buffer可以使用到1/2的Buffer Pool，故可能測試時期的update操作大部分都在change buffer中完成，再次啟動會導致大量的合併操作。

　　問題可能是定位了，然而怎麼證明我的想法又是另外一個過程了。首先根據DBA的描述，我在測試伺服器上進行了類似的sysbench測試，然後關閉資料庫，並對資料庫進行備份以便再次進行觀察。當再次啟動MySQL資料庫後，通過命令iotop可以觀察到如下的執行狀態：

Total DISK READ: 32.55 M/s | Total DISK WRITE: 0.00 B/s  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND  535  be/4 mysql       3.26 M/s    0.00 B/s  0.00 % 80.88 % mysqld --basedir=...  536 be/4 mysql      29.26 M/s    0.00 B/s  0.00 % 71.93 % mysqld --basedir=...  ......

　　可以發現的確有兩個執行緒的IO負載較高，但是這兩個程式對應於MySQL資料庫的哪兩個執行緒就不得而知了。接著，通過命令SHOW ENGINE INNODB STATUS可以觀察到如下的內容：

--------------  ROW OPERATIONS  --------------  ......  Main thread process no. 535, id 140593741342464, state: doing insert buffer merge  Purge thread process no. 536, id 140593707771648  ......

　　這裡可以看到Main thread process顯示當前的狀態為doing insert buffer merge，可以判斷當正在處理change buffer。MySQL對命令SHOW ENGINE INNODB STATUS進行小小的改進，可以看到每個執行緒對應於Linux的程式號，也就是iotop對於的程式號，而預設只能看到對應的執行緒號。配置檔案中啟用了innodb_purge_thread=1，因此還可以看到purge執行緒的資訊。

　　可以發現進行535和536就是上述iotop中IO負載較高的程式。因此問題基本已經被證實。然而通過iotop發現，purge執行緒的IO負載要比main執行緒的要高許多。這是之前沒有特別注意的，雖然InnoDB快速關閉不會進行change buffer的合併操作，但是其也不會等待purge操作全部完成。而之前的測試產生了大量的undo log需要等待被purge。通過命令SHOW ENGINE INNODB STATUS發現：

------------  TRANSACTIONS  ------------  Trx id counter 12552900  Purge done for trx's n:o < ECEB125 undo n:o < 0  History list length 29572089

　　可以看到History list length為29 572 089，也就是說差不多有接近3000W的undo log記錄。OMG,還真不少。。。不過也好理解，畢竟測試的都是update操作。

　　另外，還可通過類似pstack工具找出當前MySQL資料庫執行緒呼叫的函式資訊：

5154 pthread_cond_wait,os_event_wait_low,log_write_up_to,trx_commit_complete_for_mysql,innobase_commit,ha_commit_trans,trans_commit_stmt,mysql_execute_command,mysql_parse,dispatch_command,do_handle_one_connection,handle_one_connection,start_thread(libpthread.so.0),clone(libc.so.6),??  5008 libaio::??(libaio.so.1),os_aio_linux_handle,fil_aio_wait,io_handler_thread,start_thread(libpthread.so.0),clone(libc.so.6),??  1701 pthread_cond_wait,os_event_wait_low,buf_flush_wait_batch_end,log_check_margins,row_upd_step,row_update_for_mysql,ha_innobase::update_row,handler::ha_update_row,mysql_update,mysql_execute_command,mysql_parse,dispatch_command,do_handle_one_connection,handle_one_connection,start_thread(libpthread.so.0),clone(libc.so.6),??  ......  384 pread64(libpthread.so.0),os_file_pread,os_file_read_func,os_aio_func,fil_io,buf_read_page_low,buf_read_page,buf_page_get_gen,trx_purge_rseg_get_next_history_log,trx_purge_get_next_rec,row_purge_step,que_run_threads,trx_purge,srv_purge_thread,start_thread(libpthread.so.0),clone(libc.so.6),??  273 read(libpthread.so.0),my_real_read,my_net_read,do_command,do_handle_one_connection,handle_one_connection,start_thread(libpthread.so.0),clone(libc.so.6),??  ......  128 pread64(libpthread.so.0),os_file_pread,os_file_read_func,os_aio_func,fil_io,buf_read_page_low,buf_read_page,buf_page_get_gen,btr_cur_latch_leaves,btr_cur_search_to_nth_level,btr_pcur_restore_position_func,ibuf_restore_pos,ibuf_delete_rec,ibuf_merge_or_delete_for_page,buf_read_ibuf_merge_pages,ibuf_contract_ext,ibuf_contract_for_n_pages,srv_master_thread,start_thread(libpthread.so.0),clone(libc.so.6),??

　　可以看到有大量的trx_purge，ibuf_contract_for_n_pages函式呼叫，也就是purge和change buffer的操作。從這裡也可以進一步證實之前的猜測。pstack的另一個好處是可以看到執行緒具體的函式呼叫情況，這裡通過之前SHOW ENGINE INNODB STATUS得到的main執行緒號140593741342464(對於十六進位制0x7FDE8802A700)可以看到該執行緒的函式呼叫：

Thread 5 (Thread 0x7fde8802a700 (LWP 535)):  #0  0x00007fe665a1b993 in pread64 () from /lib/libpthread.so.0  #1  0x00000000009227bf in os_file_pread ()  #2  0x0000000000923156 in os_file_read_fuc ()  #3  0x0000000000925ee2 in os_aio_func ()  #4  0x00000000008eb490 in fil_io ()  #5  0x00000000008bef7a in buf_read_page_low ()  #6  0x00000000008bf488 in buf_read_page ()  #7  0x00000000008b4230 in buf_page_get_gen ()  #8  0x000000000089de3c in btr_cur_open_at_rnd_pos_func ()  #9  0x00000000008fe37f in ibuf_contract_ext ()  #10 0x00000000008fe5a0 in ibuf_contract_for_n_pages ()  #11 0x000000000086bb2e in srv_master_thread ()  #12 0x00007fe665a138ca in start_thread () from /lib/libpthread.so.0  #13 0x00007fe664573b6d in clone () from /lib/libc.so.6  #14 0x0000000000000000 in ?? ()

　　問題定位並被證實了。然而為什麼DBA的伺服器在經歷了3，4個小時後還沒有完成purge操作呢?最後發現DBA測試伺服器的磁碟較差，而purge需要大量的離散操作，因此導致了較長的purge與merge時間。

　　總之，innodb_fast_shutdown預設值為1，在關閉時不進行change buffer的merge操作以及purge操作。想要下次啟動時，不發生這樣的現象，那麼必須將innodb_fast_shutdown的值設定為0。其實也就是將merge change buffer和purge的操作時間放在了關閉資料庫的時候。但是，在資料庫升級或者測試環境中，可能必須要進行這樣的操作。

原文出處：http://insidemysql.blog.163.com/blog/static/202834042201331812050259/