分布式 | 从 dble 日志分析到 MySQL 源码学习
作者:袁琳铸
爱可生 DBLE 团队开发成员,主要负责 DBLE 需求开发,故障排查和社区问题解答。
本文来源:原创投稿
*爱可生开源社区出品,原创内容未经授权不得随意使用,转载请联系小编并注明来源。
背景
在客户的生产环境中,dble.log 时常出现 no handler 日志。虽然没有影响客户业务的正常使用,但是需要调查下这个日志打印的原因是什么以及什么样的场景才会打印该日志。
分析
首先对 dble 和 mysql 的日志进行分析,看看能不能从日志中找到可用信息
dble日志
日志中有 no handler 日志和 dble 收到 mysql 发送的 fin 包打印的 stream closed by peer 的日志,并无其他异常。
2022-09-02 03:25:23.450 INFO [0-backendWorker] (com.actiontech.dble.net.response.DefaultResponseHandler.closeNoHandler(DefaultResponseHandler.java:116)) - no handler bind in this service MySQLResponseService[isExecuting = false attachment = null autocommitSynced = true isolationSynced = true xaStatus = 0 isDDL = false complexQuery = false] with response handler [null] with rrs = [null] with connection BackendConnection[id = 342 host = 10.186.62.41 port = 3312 localPort = 51886 mysqlId = 677 db config = dbInstance[name=M1,disabled=false,maxCon=1000,minCon=10]
2022-09-02 03:25:23.450 INFO [0-backendWorker] (com.actiontech.dble.net.connection.BackendConnection.close(BackendConnection.java:125)) - connection id 342 mysqlId 677 close for reason no handler
2022-09-02 03:25:23.450 INFO [1-NIOBackendRW] (com.actiontech.dble.net.service.AbstractService.beforeInsertServiceTask(AbstractService.java:170)) - prepare close for conn.conn id 342,reason [stream closed by peer]
2022-09-02 03:25:23.450 INFO [0-backendWorker] (com.actiontech.dble.net.connection.AbstractConnection.closeImmediatelyInner(AbstractConnection.java:169)) - connection id close for reason [no handler] with connection BackendConnection[id = 342 host = 10.186.62.41 port = 3312 localPort = 51886 mysqlId = 677 db config = dbInstance[name=M1,disabled=false,maxCon=1000,minCon=10]
mysql 日志
存在连接超时而关闭连接的日志,并无其他异常
2022-09-02T03:25:23.375174Z 672 [Note] [MY-013730] [Server] 'wait_timeout' period of 20 seconds was exceeded for `root`@`%`. The idle time since last command was too long.
2022-09-02T03:25:23.375252Z 677 [Note] [MY-010914] [Server] Aborted connection 677 to db: 'unconnected' user: 'root' host: '10.186.62.148' (The client was disconnected by the server because of inactivity.).
dble 相关逻辑
下发语句
- dble 收到客户端发送的语句
- dble 从连接池中选择处理语句的连接
- 根据语句类型 dble 选择合适的 responseHandler(responseHandler 用来- 处理 mysql 发送的报文,空闲连接的 responseHandler 为 null)
- 下发语句到 mysql
处理 mysql 报文
- dble 接收 mysql 发送的报文
- dble 的 connection 使用下发语句时设置的 responseHandler 处理该报文(找到 responseHandler 的情况下这里结束)
- dble 的 connection 无法找到 responseHandler ,无法处理该报文,打印 no handler 日志
后端连接 close 处理
- dble 收到 fin 包或者检测到该连接存在异常
- 打印连接 close 相关信息(close 原因,被关闭的连接的信息)
- 清空连接绑定的内容(比如 responseHandler ,service 等信息)
- 设置该连接不可用
- 从连接池中移除该连接
理论情况下只有 dble 执行语句的的后端连接进行 close 处理,dble 依旧在使用这个被 close 的后端连接处理 mysql 发送的数据才会出现 no handler 日志,从日志中可以发现 dble 先处理 no handler 日志关闭连接,然后才收到了 mysql 发送的 fin 包,这与 dble 的逻辑不符(不应该先打印 no handler 日志),这是需要排查的疑惑点。然后开始翻阅 dble 的源码看看能不能用肉眼 debug 出一个符合日志打印的场景和对日志中的疑惑点进行解释,经过翻来覆去的 review 没有发现可能场景也无法解释 dble 日志中的现象。
这时候可以换个方式,借助 arthas 去客户环境中看看打印日志时 dble 的调用链和当时 dble 后端 connection 的信息,然后在尝试分析问题。
arthas 分析
- arthas 命令
stack com.actiontech.dble.net.response.DefaultResponseHandler closeNoHandler -n 1000 >> closeNoHandler_stack.log
watch com.actiontech.dble.net.response.DefaultResponseHandler closeNoHandler '{params,returnObj,throwExp,target}' -n 1000 -x 3 -b >> closeNoHandler.log
- 从 closeNoHandler_stack.log 可以看到 dble 收到了 mysql 传过来的 error 报文,调用了 error 方法,然后再调用 closeNohander 方法打印了 no handler 日志
- 从 closeNoHandler.log 中可以看到是一个空闲连接收到了 mysql 发送的 error 报文
dble 中 responseHandler = null 只有两种可能1.执行 sql 语句的 connection 执行 close 后会把 responseHandler 置为 null 2.空闲连接的 responseHandler 默认为 null ,因为 connection 执行 close 会在日志中会打印 close 相关日志,而 dble 日志中没有打印所以排除可能1
结合上述日志分析,看起来是 mysql 因为连接超时关闭该连接,这时候 dble 不仅收到 mysql 发送的 fin 包还收到了 mysql 发送的 error 报文,然后 dble 处理 error 报文打印了 no handler 日志。使用和客户相同的 mysql 版本(8.0.25)按照猜想进行尝试。
实验
- mysql 设置超时时间
mysql> set global interactive_timeout=20;
Query OK, 0 rows affected (0.00 sec)
- 在 MySQL 服务器上开始抓包
tcpdump port 3312 -w time_wait.cap
- 启动 dble ,然后等待连接池中的连接超时,停止抓包
- dble 日志中检索打印 no handler 日志的后端连接,查看 mysqlid(本实验中为667)和 localPort(本实验中为51886)
- 拿着 mysqlid 在 mysql error log 中检索,确认为因为连接超时 mysql 主动关闭了该连接
- 使用 tcp.port == 51886 在抓包文件中过滤信息
wireshark 分析抓包文件
从抓包内容中可以看到 mysql 的连接超时后,mysql 先向客户端(dble)发送了一个 error 报文然后在发送一个 fin 包,符合我们的猜想
这里就忍不住想看看这个抓包结果中的 Server Greeting Error 4031 是什么然后在 mysql 文档中找到了相关信息
- Error 4031 报文详细信息
- 发现是在 mysql8.0.24 中加入的,然后去 mysql 的 8.0.24 Release Notes 查看是否有详细说明。可以看到 Release Notes 中提到了因为 wait_timeout 闭的连接 mysql 在关闭该连接之前会先向客户端发送一个包含关闭该连接的详细原因的报文
- 再看看具体代码处理
源码简要说明
- pr 提交之前的逻辑(红色部分和灰色部分)
- 直接向客户端发送 last_errno 的内容(这里向客户端发送的是 psh 包,不是 mysql 协议的报文)
- net->last_errno 置为 ER_NET_WAIT_ERROR
- 使用 LogErr 方法将 ER_NET_WAIT_ERROR 的内容写入 error log
- 连接等 write 日志和发送数据结束后关闭
- pr 提交之后的逻辑(绿色部分和灰色部分)
- net->last_errno 置为 ER_CLIENT_INTERACTION_TIMEOUT
- 使用 LogErr 方法将 ER_NET_WAIT_ERROR 的内容写入 error log
- 向客户端发送 last_errno 的内容(Error 4031)
- 连接等 write 日志和发送数据结束后关闭
结论
mysql8.0.24 及其之后的版本在因为 mysql 连接超时的情况下会向客户端先发送一个 error 报文在关闭连接 。如果 mysql 关闭的是 dble 连接池中的空闲连接,dble 的空闲连接会处理这个报文,由于空闲连接不存在 responseHandler(responseHandler 是 dble 用来处理 mysql 发送的报文,所以只有执行语句的连接才会有 responseHandler ,空闲连接默认 responseHandler 为 null),所以 dble 就直接打印了 no handler 日志,这是一个正常现象,当然对连接超时的 error 报文 dble 会在之后进行调整。
参考
https://arthas.aliyun.com/doc/
https://dev.mysql.com/doc/relnotes/mysql/8.0/en/news-8-0-24.html
https://dev.mysql.com/doc/mysql-errors/8.0/en/server-error-reference.html
https://github.com/mysql/mysql-server/commit/14508bbb1790697c28659dd051fbc855cd3b5da9
相关文章
- mysql慢查询日志默认在哪里_MySQL 慢查询日志[通俗易懂]
- MySQL批量更新大数据:高效实现(mysql批量更新大数据)
- MYSQL 后台自动启动的优势(mysql后台启动)
- MySQL修改路径:完成你的任务(mysql修改路径)
- MongoDB与MySQL比较:开启数据库开发的新纪元(mongodb和mysql)
- MySQL执行日志分析——揭开程序运行背后的秘密(mysql执行日志)
- MySQL 二进制日志:管理与安全(mysql二进制日志)
- 备份MySQL二进制数据备份:实施万无一失(mysql二进制数据)
- MySQL数据读取速度缓慢的原因及解决方法(mysql读取数据慢)
- 深入解析:MySQL二进制日志分析方法探究(mysql二进制日志分析)
- Mysql表:查看日志记录(mysql表日志)
- 备份MySQL 数据库快速打包备份(mysql打包)
- 分析MySQL数据库日志分析:深入研究和解决问题(mysql数据库的日志)
- 调整MySQL中索引优先级的最佳方法(mysql索引优先级)
- MySQL日志审计下的安全性督导(mysql日志审计)
- 里查看MySQL的告警日志:一个指南(mysql的告警日志在哪)
- MySQL: 开启日志记录功能的步骤指南(mysql开启日志)
- 日志MySQL查看二进制日志文件的步骤(mysql查看二进制)
- 用MySQL比较生日,轻松实现日期查询和排序功能(mysql比较生日)
- MySQL故障解决:深入审查错误日志(mysql 错误日志)
- MySQL数据库快速崩溃恢复指南(mysql 崩溃恢复)
- MySQL外键添加简易指南(mysql如何添加外键)
- Java编程实现MySQL数据库连接(java连mysql数据库)
- MySQL数据库中的主键与外键了解其作用和区别(mysql中 主键与外键)
- 6天玩转MySQL源码,尽览数据库开发新视界(6天玩转mysql源码)
- 57 MySQL 默认密码更改简单易行(5.7mysql默认密码)
- 利用AWS拉取MySQL日志,轻松掌控数据安全(aws拉取mysql日志)
- MySQL源码下载指南快速获得高质量数据库工具(mysql下载源码)