注册 登录  
 加关注
   显示下一条  |  关闭
温馨提示!由于新浪微博认证机制调整,您的新浪微博帐号绑定已过期,请重新绑定!立即重新绑定新浪微博》  |  关闭

Inside MySQL

MySQL MariaDB InnoDB InnoSQL

 
 
 

日志

 
 
关于我

MySQL技术内幕系列作者, 网易杭州研究院MySQL技术经理, 擅长于MySQL performance tuning、troubleshooting、systems availability and scalability、capacity planning

网易考拉推荐

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

2013-04-18 14:36:25|  分类: troubleshoot |  标签: |举报 |字号 订阅

  下载LOFTER 我的照片书  |
前段时间遇到一个问题,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。InnoSQL对命令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的操作时间放在了关闭数据库的时候。但是,在数据库升级或者测试环境中,可能必须要进行这样的操作。


  评论这张
 
阅读(1272)| 评论(1)
推荐 转载

历史上的今天

评论

<#--最新日志,群博日志--> <#--推荐日志--> <#--引用记录--> <#--博主推荐--> <#--随机阅读--> <#--首页推荐--> <#--历史上的今天--> <#--被推荐日志--> <#--上一篇,下一篇--> <#-- 热度 --> <#-- 网易新闻广告 --> <#--右边模块结构--> <#--评论模块结构--> <#--引用模块结构--> <#--博主发起的投票-->
 
 
 
 
 
 
 
 
 
 
 
 
 
 

页脚

网易公司版权所有 ©1997-2017