AI 助理
备案控制台
开发者社区 数据库 文章 正文

MySQL案例-Semaphore wait与undo log

2017-07-28 3848
版权
版权声明：
本文内容由阿里云实名注册用户自发贡献，版权归原作者所有，阿里云开发者社区不拥有其著作权，亦不承担相应法律责任。具体规则请查看《 阿里云开发者社区用户服务协议》和 《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容，填写 侵权投诉表单进行举报，一经查实，本社区将立刻删除涉嫌侵权内容。
本文涉及的产品
RDS MySQL Serverless 基础系列，0.5-2RCU 50GB
推荐场景：
学生管理系统数据库设计 搭建个人博客
云数据库 RDS MySQL，高可用系列 2核4GB
RDS MySQL Serverless 高可用系列，价值2615元额度，1个月
简介： -------------------------------------------------------------------------------------------------正文-----------------------------------...
-------------------------------------------------------------------------------------------------正文---------------------------------------------------------------------------------------------------------------
场景:
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

  30. ......
  31. ......

  33. Thread 494 (Thread 0x7fc52f937700 (LWP 11164)):
  34. #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  35. #1 0x0000000000ffe7f6 in os_event::wait_low(long) ()
  36. #2 0x00000000010b96bc in sync_array_wait_event(sync_array_t*, sync_cell_t*&) ()
  37. #3 0x00000000010bc510 in rw_lock_x_lock_func(rw_lock_t*, unsigned long, char const*, unsigned long) ()
  38. #4 0x000000000114123d in ?? ()
  39. #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) ()
  40. #6 0x00000000010cb380 in ?? ()
  41. #7 0x00000000010d0e48 in ?? ()
  42. #8 0x00000000010d1bdd in trx_purge(unsigned long, unsigned long, bool) ()
  43. #9 0x00000000010abb06 in srv_purge_coordinator_thread ()
  44. #10 0x00007fdba9cc6064 in start_thread (arg=0x7fc52f937700) at pthread_create.c:309
  45. #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

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

  12.         return(buf_block_get_frame(block));
  13. }

  15. ......

  17. trx_undo_page_get_s_latched(
  18.         const page_id_t& page_id,
  19.         const page_size_t& page_size,
  20.         mtr_t* mtr)
  21. {
  22.         buf_block_t* block = buf_page_get(page_id, page_size,
  23.                                              RW_S_LATCH, mtr); -- 190
  24.         buf_block_dbg_add_level(block, SYNC_TRX_UNDO_PAGE);

  26.         return(buf_block_get_frame(block));
  27. }

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



点击(此处)折叠或打开

  1. trx0rseg.ic

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

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

  23.         buf_block_dbg_add_level(block, SYNC_RSEG_HEADER);

  25.         header = TRX_RSEG + buf_block_get_frame(block);

  27.         return(header);
  28. }

从注释可以看到, 这个方法是用来获取回滚段的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
文章标签：
云数据库 RDS MySQL 版
关系型数据库
数据库
Linux
Unix
NoSQL
Shell
SQL
监控
MySQL
关键词：
云数据库 RDS MySQL 版案例
mysql日志服务
云数据库 RDS MySQL 版log
日志服务undo
云数据库 RDS MySQL 版undo
相关实践学习
每个IT人都想学的“Web应用上云经典架构”实战
本实验从Web应用上云这个最基本的、最普遍的需求出发，帮助IT从业者们通过“阿里云Web应用上云解决方案”，了解一个企业级Web应用上云的常见架构，了解如何构建一个高可用、可扩展的企业级应用架构。
MySQL数据库入门学习
本课程通过最流行的开源数据库MySQL带你了解数据库的世界。   相关的阿里云产品：云数据库RDS MySQL 版 阿里云关系型数据库RDS（Relational Database Service）是一种稳定可靠、可弹性伸缩的在线数据库服务，提供容灾、备份、恢复、迁移等方面的全套解决方案，彻底解决数据库运维的烦恼。 了解产品详情: https://www.aliyun.com/product/rds/mysql 
wangwenan
目录
相关文章
蓝易云
|
6月前
|
存储 SQL 关系型数据库
mysql的undo log、redo log、bin log、buffer pool
MySQL的undo log、redo log、bin log和buffer pool是确保数据库高效、安全和可靠运行的关键组件。理解这些组件的工作原理和作用，对于优化数据库性能和保障数据安全具有重要意义。通过适当的配置和优化，可以显著提升MySQL的运行效率和数据可靠性。
蓝易云
139 16
SlackClimb
|
7月前
|
存储 缓存 关系型数据库
图解MySQL【日志】——Redo Log
Redo Log（重做日志）是数据库中用于记录数据页修改的物理日志，确保事务的持久性和一致性。其主要作用包括崩溃恢复、提高性能和保证事务一致性。Redo Log 通过先写日志的方式，在内存中缓存修改操作，并在适当时候刷入磁盘，减少随机写入带来的性能损耗。WAL（Write-Ahead Logging）技术的核心思想是先将修改操作记录到日志文件中，再择机写入磁盘，从而实现高效且安全的数据持久化。Redo Log 的持久化过程涉及 Redo Log Buffer 和不同刷盘时机的控制参数（如 `innodb_flush_log_at_trx_commit`），以平衡性能与数据安全性。
SlackClimb
272 5
图解MySQL【日志】——Redo Log
蓝易云
|
6月前
|
存储 SQL 关系型数据库
mysql的undo log、redo log、bin log、buffer pool
MySQL的undo log、redo log、bin log和buffer pool是确保数据库高效、安全和可靠运行的关键组件。理解这些组件的工作原理和作用，对于优化数据库性能和保障数据安全具有重要意义。通过适当的配置和优化，可以显著提升MySQL的运行效率和数据可靠性。
蓝易云
109 4
运营研究坊
|
6月前
|
SQL 存储 关系型数据库
简单聊聊MySQL的三大日志（Redo Log、Binlog和Undo Log）各有什么区别
在MySQL数据库管理中，理解Redo Log（重做日志）、Binlog（二进制日志）和Undo Log（回滚日志）至关重要。Redo Log确保数据持久性和崩溃恢复；Binlog用于主从复制和数据恢复，记录逻辑操作；Undo Log支持事务的原子性和隔离性，实现回滚与MVCC。三者协同工作，保障事务ACID特性。文章还详细解析了日志写入流程及可能的异常情况，帮助深入理解数据库日志机制。
运营研究坊
831 0
SlackClimb
|
7月前
|
存储 关系型数据库 MySQL
图解MySQL【日志】——Undo Log
Undo Log（回滚日志）是 MySQL 中用于实现事务原子性和一致性的关键机制。在默认的自动提交模式下，MySQL 隐式开启事务，每条增删改语句都会记录到 Undo Log 中。其主要作用包括：
SlackClimb
262 0
阿里云云原生
|
4月前
|
监控 容灾 算法
阿里云 SLS 多云日志接入最佳实践：链路、成本与高可用性优化
本文探讨了如何高效、经济且可靠地将海外应用与基础设施日志统一采集至阿里云日志服务(SLS)，解决全球化业务扩展中的关键挑战。重点介绍了高性能日志采集Agent（iLogtail/LoongCollector）在海外场景的应用，推荐使用LoongCollector以获得更优的稳定性和网络容错能力。同时分析了多种网络接入方案，包括公网直连、全球加速优化、阿里云内网及专线/CEN/VPN接入等，并提供了成本优化策略和多目标发送配置指导，帮助企业构建稳定、低成本、高可用的全球日志系统。
阿里云云原生
615 55
蓝染-惣右介
|
10月前
|
XML 安全 Java
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
本文介绍了Java日志框架的基本概念和使用方法，重点讨论了SLF4J、Log4j、Logback和Log4j2之间的关系及其性能对比。SLF4J作为一个日志抽象层，允许开发者使用统一的日志接口，而Log4j、Logback和Log4j2则是具体的日志实现框架。Log4j2在性能上优于Logback，推荐在新项目中使用。文章还详细说明了如何在Spring Boot项目中配置Log4j2和Logback，以及如何使用Lombok简化日志记录。最后，提供了一些日志配置的最佳实践，包括滚动日志、统一日志格式和提高日志性能的方法。
蓝染-惣右介
2945 31
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
运维有小邓
|
9月前
|
监控 安全 Apache
什么是Apache日志？为什么Apache日志分析很重要？
Apache是全球广泛使用的Web服务器软件，支持超过30%的活跃网站。它通过接收和处理HTTP请求，与后端服务器通信，返回响应并记录日志，确保网页请求的快速准确处理。Apache日志分为访问日志和错误日志，对提升用户体验、保障安全及优化性能至关重要。EventLog Analyzer等工具可有效管理和分析这些日志，增强Web服务的安全性和可靠性。
运维有小邓
254 9
qhhf_地道酬勤
|
7月前
|
存储 SQL 关系型数据库
MySQL日志详解——日志分类、二进制日志bin log、回滚日志undo log、重做日志redo log
MySQL日志详解——日志分类、二进制日志bin log、回滚日志undo log、重做日志redo log、原理、写入过程；binlog与redolog区别、update语句的执行流程、两阶段提交、主从复制、三种日志的使用场景；查询日志、慢查询日志、错误日志等其他几类日志
qhhf_地道酬勤
628 35
MySQL日志详解——日志分类、二进制日志bin log、回滚日志undo log、重做日志redo log

热门文章

最新文章

  • 1
    基于docker搭建监控系统&日志收集
  • 2
    运维日志里的“读心术”：深度学习能看出啥？
  • 3
    搭建ELK日志收集，保姆级教程
  • 4
    Spring Boot配置优化：Tomcat+数据库+缓存+日志，全场景教程
  • 5
    生成更智能，调试更轻松，SLS SQL Copilot 焕新登场！
  • 6
    生成更智能，调试更轻松，SLS SQL Copilot 焕新登场！
  • 7
    无需复杂正则：SLS 新脱敏函数让隐私保护更简单高效
  • 8
    在Ubuntu系统上设置syslog日志轮替与大小限制
  • 9
    使用EventLog Analyzer进行日志取证分析
  • 10
    从下载到运行：MySQL 详细安装配置完整教程
  • 1
    在 MySQL 中使用 Distinct
    1422
  • 2
    在 MySQL 中使用 IS NULL
    914
  • 3
    MySQL——增量备份和全量备份
    123
  • 4
    Mysql80 密码忘记了怎么办
    176
  • 5
    MySQL——如何查看MySQL登录日志
    865
  • 6
    MySQL——删除重复数据
    101
  • 7
    Go语言中进行MySQL预处理和SQL注入防护
    332
  • 8
    MySQL——查看当前数据库中所有库中表的行数
    79
  • 9
    MySQL——大量的deleted进程导致磁盘100%
    86
  • 10
    MySQL——查看数据库大小
    134

    • 相关课程

    更多
  • MySQL企业常见架构与调优经验分享
  • 阿里云云原生数据仓库AnalyticDB MySQL版 使用教程
  • MySQL实战进阶
  • 阿里云数据库产品家族及特性
  • 数据库及SQL/MySQL基础
  • 云数据库MySQL快速入门

    • 相关电子书

    更多
  • PolarDB MySQL引擎重磅功能及产品能力盛大发布
  • 阿里云MySQL云数据库产品体系介绍
  • One Box： 解读事务与分析一体化数据库 HybridDB for MySQL

    • 推荐镜像

    更多
  • mysql
    • 下一篇
    2025云栖大会，阿里云百炼邀请您的参与和见证