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, 190和trx0rseg.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=2 
  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

时间： 2024-09-26 20:52:03

MySQL案例-Semaphore wait与undo log的相关文章

MySQL · 引擎特性 · InnoDB undo log 漫游

本文是对整个Undo生命周期过程的阐述,代码分析基于当前最新的MySQL5.7版本.本文也可以作为了解整个Undo模块的代码导读.由于涉及到的模块众多,因此部分细节并未深入. 前言 Undo log是InnoDB MVCC事务特性的重要组成部分.当我们对记录做了变更操作时就会产生undo记录,Undo记录默认被记录到系统表空间(ibdata)中,但从5.6开始,也可以使用独立的Undo 表空间. Undo记录中存储的是老版本数据,当一个旧的事务需要读取数据时,为了能读取到老版本的数据,需要顺着u

MySQL 5.7 新特性：在线truncate undo log文件

在MySQL5.7.5版本中,增加了一个比较有用的功能,即用户可以自己truncate掉undo log. 对应的changeling entry如下: InnoDB: You can now truncate undo logs that reside in undo tablespaces. This feature is enabled using theinnodb_undo_log_truncate configuration option. For more information,

MySQL锁系列（四）之 undo log

什么是undo 1) redo 记录的是对页的重做日志,undo 记录的是对事务的逆向操作 2) undo 会产生redo,undo的产生也会伴随这redo的产生,因为重启恢复的时候,可以通过redo还原这些undo的操作,以达到回滚的目的 undo有什么用 1) 用于对事务的回滚 2)用于MVCC undo的存储结构 rollback segment * 在MySQL5.1的年代,一个MySQL实例,就只有一个rollback segment * 在MySQL5.1+ 的年代,一个MySQL实

MySQL内核月报 2014.11-MySQL·　5.7特性·在线Truncate undo log 表空间

背景 Innodb使用undo log来实现MVCC,这意味着如果一个很老的事务长时间不提交,那么新产生的undo log都无法被及时清理掉.在MySQL 5.5及之前版本中,undo log是存储在ibdata中.从5.6开始可以使用独立的undo log表空间来存储undo.但是直到5.6,一旦undo log膨胀,依然没有任何办法为其 "减肥".因此我们经常看到ibdata被膨胀到几十上百G. 改进 在MySQL5.7.5版本中终于增加了这个众望所归的功能,实现了在线trunca

mysql案例：mysql5.6.14配置my.cnf多实例

mysql案例:mysql5.6.14配置my.cnf多实例,mysql_install_db初始化不读取my.cnf配置文件 1.1.1. mysql5.6.14多实例my.cnf时,初始化不读取my.cnf配置文件 [环境描述] 在多实例配置的/etc/my.cnf环境中,执行mysql_install_db后,启动Mysql报错. [操作步骤] /etc/my.cnf配置文件: [mysqld3307] innodb_data_file_path =ibdata1:1G:autoexten

mysql案例：Java程序访问Mysql报错

mysql案例:Java程序访问Mysql报错'OPTION SQL_SELECT_LIMIT=XXX' [环境描述] mysql版本: 5.6.14-56-log Percona Server (GPL) 程序: 使用JDBC驱动mysql-connector-java访问mysql数据库 [报错信息] 程序访问mysql执行SQL语句的时候报错: You have an error in your SQL syntax; check the manual that corresponds t

MySQL案例-GTID同步失败:master has purged binary logs

GTID工具联动:http://blog.itpub.net/29510932/viewspace-1736132/ -------------------------------------------------------------------------------------------------正文--------------------------------------------------------------------------------------------

MySQL内核月报 2014.12-TokuDB· Binary Log Group Commit with TokuDB

MySQL在开启Binary Log的情况下,使用2PC(图1)来保证事务(XA)完整性的,每次提交事务需要做: 每个事务在提交的时候都要做3次fsync以确保日志真正的落盘,这样在log里,一个事务就会有3种状态: 这样,无论处于任何一个状态,事务的完整性都不会被破坏,但是每次提交会产生3次fsync,性能非常低. 为了提升性能,MySQL 5.6增加了group commit功能,当多个事务并发提交时,让多个都在等待fsync的事务合并做一次fsync,大大提升了吞吐量. 但是这个优化还需要

MySQL 慢查询日志(Slow Query Log)

    同大多数关系型数据库一样,日志文件是MySQL数据库的重要组成部分.MySQL有几种不同的日志文件,通常包括错误日志文件,二进制日志,通用日志,慢查询日志,等等.这些日志可以帮助我们定位mysqld内部发生的事件,数据库性能故障,记录数据的变更历史,用户恢复数据库等等.本文主要描述通用查询日志.   1.MySQL日志文件系统的组成   a.错误日志:记录启动.运行或停止mysqld时出现的问题.   b.通用日志:记录建立的客户端连接和执行的语句.   c.更新日志:记录更改数据的语句