MySQL数据库诊断：InnoDB关机问题

今天发现了一个db服务器，在错误的日志中有innodb 报错信息如下：

space 1131 offset 1221565 (448 records, index id 2730)  206 InnoDB: Submit a detailed bug report to https://www.tulingxueyuan.cn/d/file/p/20230609/oxo1urmopsa  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 0x7f30e81ffec 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，关闭时不会对changee进行 buffer合并，所以这种操作将在下次启动时进行。因为MySQL 5.5版本InnoDB存储引擎的change buffer可以使用1/2的buffer Pool，因此，可能测试期间的update操作大多在changee中 在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  ...

　　这里可以看到Mainnn thread process显示当前状态为doing insert buffer merge，可以判断，change正在处理中 buffer。MySQL命令SHOW ENGINE INNODB 通过对STATUS的小改进，您可以看到每个线程对应于Linux的流程号，即iotop对流程号，默认情况下只能看到相应的流程号。innodb_在配置文件中使用purge_thread=因此，你也可以看到purge线程信息。

　　可以发现，535和536是IOTOP中IO负载较高的过程。因此，问题已基本得到证实。然而，通过iotop发现，purge线程的IO负载远高于main线程。之前没有特别注意到这一点，尽管InnoDB快速关闭不会进行changee 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，也就是说，Undoo接近3000W log记录。OMG,真的很多。。。但是很容易理解，毕竟所有的测试都是update操作。

　　此外，当前MySQL数据库线程调用的函数信息也可以通过类似的pstack工具找到:

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和changee buffer操作。之前的猜测也可以从这里进一步证实。pstack的另一个优点是可以看到具体的线程函数调用，通过之前的SHOW ENGINE INNODB 从STATUS获得的main线程号140593741342464(16进制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 00007fe65a138 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，关闭时不进行changee buffermerge操作和purge操作。如果你想在下次开始时不发生这种现象，你必须使用innodb_fast_shutdown的值设置为0。其实也就是说，也就是说，mergege change buffer和purge的操作时间是关闭数据库的时候。但是，在数据库升级或测试环境中，可能需要进行此类操作。