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

MySQL案例-Semaphore wait与undo log

2017-07-28 3720
版权
版权声明：
本文内容由阿里云实名注册用户自发贡献，版权归原作者所有，阿里云开发者社区不拥有其著作权，亦不承担相应法律责任。具体规则请查看《 阿里云开发者社区用户服务协议》和 《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容，填写 侵权投诉表单进行举报，一经查实，本社区将立刻删除涉嫌侵权内容。
本文涉及的产品
云数据库 RDS MySQL，集群系列 2核4GB
推荐场景：
搭建个人博客
RDS MySQL Serverless 基础系列，0.5-2RCU 50GB
推荐场景：
学生管理系统数据库设计 搭建个人博客
云数据库 RDS PostgreSQL，集群系列 2核4GB
简介： -------------------------------------------------------------------------------------------------正文-----------------------------------...
-------------------------------------------------------------------------------------------------正文---------------------------------------------------------------------------------------------------------------
场景:
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
关键词：
undo日志服务
日志服务案例
云数据库 RDS MySQL 版案例
云数据库 RDS MySQL 版log
mysql日志服务
相关实践学习
如何在云端创建MySQL数据库
开始实验后，系统会自动创建一台自建MySQL的 源数据库 ECS 实例和一台 目标数据库 RDS。
全面了解阿里云能为你做什么
阿里云在全球各地部署高效节能的绿色数据中心，利用清洁计算为万物互联的新世界提供源源不断的能源动力，目前开服的区域包括中国（华北、华东、华南、香港）、新加坡、美国（美东、美西）、欧洲、中东、澳大利亚、日本。目前阿里云的产品涵盖弹性计算、数据库、存储与CDN、分析与搜索、云通信、网络、管理与监控、应用服务、互联网中间件、移动服务、视频服务等。通过本课程，来了解阿里云能够为你的业务带来哪些帮助     相关的阿里云产品：云服务器ECS 云服务器 ECS（Elastic Compute Service）是一种弹性可伸缩的计算服务，助您降低 IT 成本，提升运维效率，使您更专注于核心业务创新。产品详情: https://www.aliyun.com/product/ecs
wangwenan
目录
相关文章
尹正杰
|
24天前
|
Prometheus Cloud Native Go
Golang语言之Prometheus的日志模块使用案例
这篇文章是关于如何在Golang语言项目中使用Prometheus的日志模块的案例，包括源代码编写、编译和测试步骤。
尹正杰
23 3
Golang语言之Prometheus的日志模块使用案例
尹正杰
|
25天前
|
监控 关系型数据库 MySQL
zabbix agent集成percona监控MySQL的插件实战案例
这篇文章是关于如何使用Percona监控插件集成Zabbix agent来监控MySQL的实战案例。
尹正杰
29 2
zabbix agent集成percona监控MySQL的插件实战案例
最好zzz
|
3天前
|
存储 关系型数据库 MySQL
binlog、redolog、undo log底层原理及ACID特性实现分享
在数据库管理系统中，日志机制是确保数据一致性、完整性和可靠性的关键组件。MySQL数据库中的binlog、redolog和undolog作为其核心日志系统，各自扮演着不同但同样重要的角色。本文将深入探讨这三种日志的底层原理以及它们如何分别实现ACID（原子性、一致性、隔离性、持久性）特性的不同方面。
最好zzz
10 0
土木林森
|
28天前
|
API C# 开发框架
WPF与Web服务集成大揭秘：手把手教你调用RESTful API，客户端与服务器端优劣对比全解析！
【8月更文挑战第31天】在现代软件开发中，WPF 和 Web 服务各具特色。WPF 以其出色的界面展示能力受到欢迎，而 Web 服务则凭借跨平台和易维护性在互联网应用中占有一席之地。本文探讨了 WPF 如何通过 HttpClient 类调用 RESTful API，并展示了基于 ASP.NET Core 的 Web 服务如何实现同样的功能。通过对比分析，揭示了两者各自的优缺点：WPF 客户端直接处理数据，减轻服务器负担，但需处理网络异常；Web 服务则能利用服务器端功能如缓存和权限验证，但可能增加服务器负载。希望本文能帮助开发者根据具体需求选择合适的技术方案。
土木林森
65 0
土木林森
|
28天前
|
C# Windows 监控
WPF应用跨界成长秘籍：深度揭秘如何与Windows服务完美交互，扩展功能无界限！
【8月更文挑战第31天】WPF（Windows Presentation Foundation）是 .NET 框架下的图形界面技术，具有丰富的界面设计和灵活的客户端功能。在某些场景下，WPF 应用需与 Windows 服务交互以实现后台任务处理、系统监控等功能。本文探讨了两者交互的方法，并通过示例代码展示了如何扩展 WPF 应用的功能。首先介绍了 Windows 服务的基础知识，然后阐述了创建 Windows 服务、设计通信接口及 WPF 客户端调用服务的具体步骤。通过合理的交互设计，WPF 应用可获得更强的后台处理能力和系统级操作权限，提升应用的整体性能。
土木林森
63 0
土木林森
|
1月前
|
存储 关系型数据库 MySQL
深入MySQL：事务日志redo log详解与实践
【8月更文挑战第24天】在MySQL的InnoDB存储引擎中，为确保事务的持久性和数据一致性，采用了redo log（重做日志）机制。redo log记录了所有数据修改，在系统崩溃后可通过它恢复未完成的事务。它由内存中的redo log buffer和磁盘上的redo log file组成。事务修改先写入buffer，再异步刷新至磁盘，最后提交事务。若系统崩溃，InnoDB通过redo log重放已提交事务并利用undo log回滚未提交事务，确保数据完整。理解redo log工作流程有助于优化数据库性能和确保数据安全。
土木林森
174 0
土木林森
|
1月前
|
存储 SQL 关系型数据库
MySQL事务日志奥秘：undo log大揭秘，一文让你彻底解锁！
【8月更文挑战第24天】本文深入探讨了MySQL中undo log的关键作用及其在确保事务原子性和一致性方面的机制。MySQL通过记录事务前的数据状态，在需要时能回滚至初始状态。主要介绍InnoDB存储引擎下的undo log实现，包括undo segment和record的结构，而MyISAM则采用redo log保障持久性而非一致性。通过一个简单的SQL回滚示例，展示了undo log如何在实际操作中发挥作用，帮助读者更好地理解并运用MySQL事务管理功能。
土木林森
131 0
叫个什么名字
|
11天前
|
NoSQL 关系型数据库 MySQL
微服务架构下的数据库选择：MySQL、PostgreSQL 还是 NoSQL？
在微服务架构中，数据库的选择至关重要。不同类型的数据库适用于不同的需求和场景。在本文章中，我们将深入探讨传统的关系型数据库（如 MySQL 和 PostgreSQL）与现代 NoSQL 数据库的优劣势，并分析在微服务架构下的最佳实践。
叫个什么名字
77 9
小王老师呀
|
13天前
|
存储 SQL 关系型数据库
使用MySQL Workbench进行数据库备份
【9月更文挑战第13天】以下是使用MySQL Workbench进行数据库备份的步骤：启动软件后，通过“Database”菜单中的“管理连接”选项配置并选择要备份的数据库。随后，选择“数据导出”，确认导出的数据库及格式（推荐SQL格式），设置存储路径，点击“开始导出”。完成后，可在指定路径找到备份文件，建议定期备份并存储于安全位置。
小王老师呀
138 11
阿里云开发者
|
1月前
|
弹性计算 关系型数据库 数据库
手把手带你从自建 MySQL 迁移到云数据库，一步就能脱胎换骨
阿里云瑶池数据库来开课啦！自建数据库迁移至云数据库 RDS原来只要一步操作就能搞定！点击阅读原文完成实验就可获得一本日历哦～
阿里云开发者
60 0

热门文章

最新文章

  • 1
    RDS for SQL server 空间问题排查汇总
  • 2
    MySQL的备份与还原
  • 3
    mysql的XA与innodb_support_xa
  • 4
    Error Code: 2006 - MySQL server has gone away
  • 5
    Ubuntu 20.04 + mysql 8.0.27 用户名和密码修改(非常实用)
  • 6
    MySQL数据库面试题4
  • 7
    mysql建库
  • 8
    MySQL 用户管理与权限管理
  • 9
    mysql 更改密码
  • 10
    Linux Shell脚本之利用mysqldump备份MySQL数据库（详细注解）
  • 1
    Springboot整合与使用log4j2日志框架【详解版】
    430
  • 2
    Golang深入浅出之-Go语言中的日志记录：log与logrus库
    164
  • 3
    智能日志分析器
    38
  • 4
    多源数据同步与自动化日志分析
    37
  • 5
    自动日志文件轮转
    32
  • 6
    自动化任务调度和日志记录
    48
  • 7
    【Go语言专栏】Go语言中的日志记录与监控
    108
  • 8
    DataWorks产品使用合集之在DataWorks中，如何通过PolarDB for MySQL来查看binlog日志
    102
  • 9
    DataWorks产品使用合集之DataWorks资源里python运行时候，查看中途打印日志如何解决
    52
  • 10
    PHP编写的电脑监控软件：用户登录日志记录与分析
    138

    • 相关课程

    更多
  • Linux MySQL服务器搭建与应用
  • 场景实践-基于阿里云Quick BI 对MOOC网站日志分析
  • MySQL完全自学手册
  • MySQL数据库入门学习
  • MySQL企业常见架构与调优经验分享
  • 云数据库MySQL版快速上手教程

    • 相关电子书

    更多
  • PostgresChina2018_赖思超_PostgreSQL10_hash索引的WAL日志修改版final
  • Kubernetes下日志实时采集、存储与计算实践
  • 日志数据采集与分析对接

    • 相关实验场景

    更多
  • MySQL引擎及架构优化
  • 基于EBS部署高性能的MySQL服务
  • 使用CloudLens管理SLS日志采集
  • 使用CloudLens采集PolarDB日志并进行审计分析
  • 使用CloudLens采集RDS日志并进行审计分析
  • 使用日志服务SLS进行OSS可观测分析

    • 推荐镜像

    更多
  • mysql
  • mariadb
  • postgresql
    • 下一篇
    使用OSS上传下载文件