乐趣区

关于mysql:分布式-从-dble-日志分析到-MySQL-源码学习

jiezi

作者：袁琳铸

爱可生 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/rel…

https://dev.mysql.com/doc/mys…

https://github.com/mysql/mysq…

退出移动版