MySQL案例-Semaphore wait与undo log-阿里云开发者社区

开发者社区> 数据库> 正文

MySQL案例-Semaphore wait与undo log

简介: -------------------------------------------------------------------------------------------------正文-----------------------------------...
-------------------------------------------------------------------------------------------------正文---------------------------------------------------------------------------------------------------------------
场景:
MySQL-5.7.17, 主从架构, 业务读写分离, 只读从库不定期出现延迟, 并触发Innodb的Semaphore wait导致从库主动Crash;

结论:
数据库升级到5.7.19, 调整block size和buffer_pool_instances;

重点!:
毕竟看不懂innodb的源代码, 没有理清楚详细的逻辑, 只能对问题现象和代码碎片进行分析;

分析:

源代码为5.7.17
现象上, 所有实例中只有这一个业务的实例有这种问题, 且通过更换虚拟机/物理机的方式确认了并非外部原因导致同步延迟;
通过监控的观察, 确认了在延迟出现的时候没有突发性的CPU使用率和IO使用率;

先上error log

点击(此处)折叠或打开

  1. 2017-05-24T15:27:30.303424+08:00 0 [Warning] InnoDB: A long semaphore wait:
  2. --Thread 140484883478272 has waited at trx0undo.ic line 171 for 241.00 seconds the semaphore:
  3. X-lock on RW-latch at 0x7fd08b2ed088 created in file buf0buf.cc line 1459
  4. a writer (thread id 140484736354048) has reserved it in mode exclusive
  5. number of readers 0, waiters flag 1, lock_word: 0
  6. Last time read locked in file trx0undo.ic line 190
  7. Last time write locked in file /export/home/pb2/build/sb_0-21378219-1480360739.71/release-ET46834/mysql-5.7.17/storage/innobase/include/trx0undo.ic line 171
  8. 2017-05-24T15:27:30.303552+08:00 0 [Warning] InnoDB: A long semaphore wait:
  9. --Thread 140484736354048 has waited at trx0rseg.ic line 48 for 241.00 seconds the semaphore:
  10. X-lock on RW-latch at 0x7fd34dff7f60 created in file buf0buf.cc line 1459
  11. a writer (thread id 140484883478272) has reserved it in mode exclusive
  12. number of readers 0, waiters flag 1, lock_word: 0
  13. Last time read locked in file not yet reserved line 0
  14. Last time write locked in file /export/home/pb2/build/sb_0-21378219-1480360739.71/release-ET46834/mysql-5.7.17/storage/innobase/include/trx0rseg.ic line 48
  15. InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
  16. InnoDB: Pending preads 0, pwrites 0
  17. ......
  18. ......
  19. InnoDB: ###### Diagnostic info printed to the standard error stream
  20. 2017-05-24T15:39:22.319643+08:00 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
  21. 2017-05-24 15:39:22 0x7f4223c21700 InnoDB: Assertion failure in thread 139922044491520 in file ut0ut.cc line 916

多数情况下, long semaphore wait是因为突发性的preads或者pwrites,
但是这次看到error log里面的记录都是0, 而且监控也没有发现突发性的CPU和IO负载, 所以感觉这次问题不在负载上面;

在几次出问题的过程中, 也用gdb抓了thread的堆栈信息, 摘抄上面error log中对应的数据


点击(此处)折叠或打开

  1. Thread 334 (Thread 0x7fc526ce8700 (LWP 58644)):
  2. #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  3. #1 0x0000000000ffe7f6 in os_event::wait_low(long) ()
  4. #2 0x00000000010b96bc in sync_array_wait_event(sync_array_t*, sync_cell_t*&) ()
  5. #3 0x00000000010bc510 in rw_lock_x_lock_func(rw_lock_t*, unsigned long, char const*, unsigned long) ()
  6. #4 0x000000000114123d in ?? ()
  7. #5 0x0000000001147a6e in buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*, bool) ()
  8. #6 0x00000000010c9d2a in trx_purge_add_update_undo_to_history(trx_t*, trx_undo_ptr_t*, unsigned char*, bool, unsigned long, mtr_t*) ()
  9. #7 0x00000000010fc5ef in trx_undo_update_cleanup(trx_t*, trx_undo_ptr_t*, unsigned char*, bool, unsigned long, mtr_t*) ()
  10. #8 0x00000000010f42f0 in trx_write_serialisation_history(trx_t*, mtr_t*) ()
  11. #9 0x00000000010f4d9b in trx_commit_low(trx_t*, mtr_t*) ()
  12. #10 0x00000000010f5714 in trx_commit(trx_t*) ()
  13. #11 0x00000000010f6277 in trx_commit_for_mysql(trx_t*) ()
  14. #12 0x0000000000f6a0e7 in innobase_commit_low(trx_t*) ()
  15. #13 0x0000000000f7a133 in ?? ()
  16. #14 0x00000000007f53f7 in ha_commit_low(THD*, bool, bool) ()
  17. #15 0x0000000000e10fd1 in MYSQL_BIN_LOG::process_commit_stage_queue(THD*, THD*) ()
  18. #16 0x0000000000e1ac75 in MYSQL_BIN_LOG::ordered_commit(THD*, bool, bool) ()
  19. #17 0x0000000000e1c128 in MYSQL_BIN_LOG::commit(THD*, bool) ()
  20. #18 0x00000000007f5e22 in ha_commit_trans(THD*, bool, bool) ()
  21. #19 0x0000000000cfa189 in trans_commit(THD*) ()
  22. #20 0x0000000000deade2 in Xid_log_event::do_commit(THD*) ()
  23. #21 0x0000000000deaf5f in Xid_apply_log_event::do_apply_event_worker(Slave_worker*) ()
  24. #22 0x0000000000e52353 in slave_worker_exec_job_group(Slave_worker*, Relay_log_info*) ()
  25. #23 0x0000000000e34f73 in handle_slave_worker ()
  26. #24 0x0000000000e97824 in pfs_spawn_thread ()
  27. #25 0x00007fdba9cc6064 in start_thread (arg=0x7fc526ce8700) at pthread_create.c:309
  28. #26 0x00007fdba878962d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

  29. ......
  30. ......

  31. Thread 494 (Thread 0x7fc52f937700 (LWP 11164)):
  32. #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  33. #1 0x0000000000ffe7f6 in os_event::wait_low(long) ()
  34. #2 0x00000000010b96bc in sync_array_wait_event(sync_array_t*, sync_cell_t*&) ()
  35. #3 0x00000000010bc510 in rw_lock_x_lock_func(rw_lock_t*, unsigned long, char const*, unsigned long) ()
  36. #4 0x000000000114123d in ?? ()
  37. #5 0x0000000001147a6e in buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*, bool) ()
  38. #6 0x00000000010cb380 in ?? ()
  39. #7 0x00000000010d0e48 in ?? ()
  40. #8 0x00000000010d1bdd in trx_purge(unsigned long, unsigned long, bool) ()
  41. #9 0x00000000010abb06 in srv_purge_coordinator_thread ()
  42. #10 0x00007fdba9cc6064 in start_thread (arg=0x7fc52f937700) at pthread_create.c:309
  43. #11 0x00007fdba878962d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

标记出一些方法的信息, 通过搜索, 找到这些方法的描述:
buf_page_get_gen() : 代替了buf_page_get方法, 用来访问page, 在从file读取page到bp, 获取page对应的buf_pool->mutex时, 都会使用rw_lock_x_lock来尝试加锁;
代码位于./mysql-server/storage/innobase/buf/buf0buf.cc

rw_lock_x_lock_func() : 代替了很多底层的rw_lock_x_lock_XXX的方法,  是线程用来加X锁用的方法, 如果无法获得X锁, 则会等待一段时间之后才会阻塞线程;
通过查看./mysql-server/storage/innobase/sync/sync0rw.cc中的源代码, 发现线程可能是始终无法获得对应page的X锁,
一直处于如下的循环: 尝试加锁->加锁失败->sync_array_wait_event->下一次循环;

从源代码的注释和逻辑上看, 这两个线程互相在等待对方的锁;

再通过error log的信息, 看看trx0undo.ic line 171, 190trx0rseg.ic line 48在干嘛 :


点击(此处)折叠或打开

  1. trx0undo.ic

  2. trx_undo_page_get(
  3.         const page_id_t& page_id,
  4.         const page_size_t& page_size,
  5.         mtr_t* mtr)
  6. {
  7.         buf_block_t* block = buf_page_get(page_id, page_size,
  8.                                              RW_X_LATCH, mtr); -- 171
  9.         buf_block_dbg_add_level(block, SYNC_TRX_UNDO_PAGE);

  10.         return(buf_block_get_frame(block));
  11. }

  12. ......

  13. trx_undo_page_get_s_latched(
  14.         const page_id_t& page_id,
  15.         const page_size_t& page_size,
  16.         mtr_t* mtr)
  17. {
  18.         buf_block_t* block = buf_page_get(page_id, page_size,
  19.                                              RW_S_LATCH, mtr); -- 190
  20.         buf_block_dbg_add_level(block, SYNC_TRX_UNDO_PAGE);

  21.         return(buf_block_get_frame(block));
  22. }

从代码的文件名就可以很清晰的看出来, 这是在对undo log的内容进行加锁操作;



点击(此处)折叠或打开

  1. trx0rseg.ic

  2. /** Gets a rollback segment header.
  3. @param[in] space space where placed
  4. @param[in] page_no page number of the header
  5. @param[in] page_size page size
  6. @param[in,out] mtr mini-transaction
  7. @return rollback segment header, page x-latched */
  8. UNIV_INLINE
  9. trx_rsegf_t*
  10. trx_rsegf_get(
  11.         ulint space,
  12.         ulint page_no,
  13.         const page_size_t& page_size,
  14.         mtr_t* mtr)
  15. {
  16.         buf_block_t* block;
  17.         trx_rsegf_t* header;

  18.         block = buf_page_get(
  19.                 page_id_t(space, page_no), page_size, RW_X_LATCH, mtr); -- 48

  20.         buf_block_dbg_add_level(block, SYNC_RSEG_HEADER);

  21.         header = TRX_RSEG + buf_block_get_frame(block);

  22.         return(header);
  23. }

从注释可以看到, 这个方法是用来获取回滚段的header的;


再结合gdb中thread的堆栈信息, 可以大致还原出问题的场景:
两个线程在对undo log & rollback segment进行操作, 在对bp的pages进行加锁(从file读取page, 或者是对bp_instance加锁)发生争用, 导致这两个thread一直处于os_wait状态,
最终引起了Semaphore wait导致主动Crash;

而引起这种争用的原因就是对undo log的操作(purge和get), 所以考虑从两个方面来入手解决问题:
增加bp_instance的数量, 减少争用的可能性;
增大block_size, 减少争用的可能性, 并降低undo log的相关操作(往rollback segment list添加内容或者是唤醒purge线程的频率)

那么最终给出了解决方案的建议:
调整buffer_pool_instance的数量 : 8 -> 32
修改block_size的数量 : 8k -> 16k

数据库升级 : 5.7.17 -> 5.7.19
在5.7.18有一个和undo log相关的修复, 感觉可能有效, 就一起升级了吧~

点击(此处)折叠或打开

  1. InnoDB: The restriction that required the first undo tablespace to use space ID 1 was removed. The first undo tablespace may now be assigned a space ID other than 1. Space ID values for undo tablespaces are still assigned in a consecutive sequence. (Bug #25551311)

彩蛋:
这个问题其实持续了比较长的时间, 从开始排查到最后给出解决建议差不多有半个月了, 抓取故障信息的过程中, 也找到了引起这个问题的嫌疑SQL;
写了个shell脚本, 挂在后台跑, 没几个小时就复现了这个问题, 也是Semaphore wait, 不过没有导致同步延迟, 残念~_(:з」∠)_ .....
不过从出问题的error log来看, 是在代码的同一行出的问题, 可惜系统包版本的问题, gdb抓不到堆栈信息, 所以没办法拿出确凿的证据证明这个SQL就是罪魁祸首;


惊喜:
难得看到最后, 给各位看到最后的看官一个惊喜~ 业务更倾向于......
数据库降级!
数据库降级?
数据库降级.......

(╯‵□′)╯︵┻━┻ 

所以??
所以把那个SQL挂起来吧, 嗯嗯...

点击(此处)折叠或打开

  1. select r.id 
  2.     from tb_r r 
  3.     inner join tb_a a on r.id = a.id 
  4.     left join tb_asf asf on r.id = asf.id and asf.created_time > '2999-99-99 99:99:99' 
  5.     inner join tb_ua ua on a.id = ua.id 
  6. where r.type=0 and r.status = 0 and a.type > 0 and r.num > 0 and ua.num=
  7. GROUP BY r.id 
  8. order by a.col1 desc , SUM(IFNULL(asf.col2,0)) desc, a.col3 desc 
  9. limit 28
PS:
所谓的惊喜还是吐槽为主啦~
其实挂了一个修正过后的只读实例, 一直跑着这个语句进行验证, 持续了三天也没有出现Semaphore wait的问题了~
业务还是觉得求稳, 用以前没出问题的老版本也无可厚非~
此事已结~持续半个月的debug is finished

版权声明:本文首发在云栖社区,遵循云栖社区版权声明:本文内容由互联网用户自发贡献,版权归用户作者所有,云栖社区不为本文内容承担相关法律责任。云栖社区已升级为阿里云开发者社区。如果您发现本文中有涉嫌抄袭的内容,欢迎发送邮件至:developer2020@service.aliyun.com 进行举报,并提供相关证据,一经查实,阿里云开发者社区将协助删除涉嫌侵权内容。

分享:
数据库
使用钉钉扫一扫加入圈子
+ 订阅

分享数据库前沿,解构实战干货,推动数据库技术变革

其他文章