MySQL: 慢查询记录返回行数不全分析和最近遇到的几个BUG

一、慢查询记录返回行数不全分析

现象和测试方式（5.7版本）

现象很简单，就是慢查询中，一个语句正常要发送几十万的数据，异常的异常才几百条，这种显现怎么出现的。测试使用mysql客户端，使用测试语句，其中表mytest大约10000行数据：

mysql> select sleep(1),repeat('a',1000) from  testpp.mytest;

这个语句也就是每次休眠1秒返回一条数据，模拟处理数据慢的情况，然后在开始执行的时候就kill -9 mysqld客户端模拟客户端异常或者断开网络模拟网络异常也行。

分析

如果语句执行开始了，每次返回的行数，并不是直接发送出去，而是会缓存到net buffer，然后一次性发送结果到socket buffer，直到发送才通过scoket通道到协议层的时候才知道连接断开了。

但是发送行Rows_sent这个统计值会每次写入到net buffer一行就会增加1,即便写入到的net buffer。如果一个语句执行慢，要返回1000条数据，每条1k左右，当语句执行开始的时候断开了连接，但是mysqld还在每次要返回一行数据到net buffer大约1K，那么大约16行数据的时候才会填满net buffer，但是send rows大约为16行，但是到了17行的时候可能net buffer满了需要通过写socket来发送数据，发现socket异常则语句执行失败，会话结束。那么慢查询看到的就是16行数据，而不是1000条数据。从debug来看，每次写入到net buffer的数据确认为1K左右如下：

通过net buffer写入到scoket应该是写入到了socket buffer第一次并没有报错，如下res返回值没有错误码为正常：

MySQL: 慢查询记录返回行数不全分析和最近遇到的几个BUG — image.png

但是协议层发送数据的时候报错了，等到第二次填满net buffer的时候准备发送数据的时候就发现socket已经异常了，这个可能需要抓下包确认一下。所以可能16行要乘以2，也就是32行左右，当然慢查询记录16行数据还是32行数据并不重要，反正没有记录10000行数据，也就是没有记录全部的。测试也是这样的如下：

总的来讲，如果连接出现异常，慢查询的Rows_sent 为当前执行后发送了多少行数据，而不一定全部发送完成了。那么简单总结一下前面那个简单的语句，流程为：

innodb扫描一行数据，返回给mysql层，扫描行数+1
mysql层对这行数据施加sleep 1秒，并且作用repeat函数
这行数据发送到net buffer，完成后发送行数+1
如果net buffer满就实际发送出去，发送到scoket的发送缓冲区，然后TCP协议层去处理

以此循环知道10000行数据执行完成。那么实际上对于复杂的语句，肯定中间过程是很慢的可能得到第一行需要发送的数据就很久，那么这个时候如果网络异常或者客户端异常（比如自己crash了），可能就出现这种情况。当然还需要观察日志是否有类似的报错：

2023-01-16T09:20:54.982459Z 12 [Note] Aborted connection 12 to db: 'unconnected' user: 'root' host: '192.168.1.64' (Got an error writing communication packets)

断点和代码：

这里实际上涉及到MySQL协议层了，我们需要断点在net_write_buff上，这里可以观察到net buffer实际上就是st_net.buffer，也就是数据包会缓存的地方，这里面可以清晰的看到，如果超过buffer的长度才调用底层的发送接口，如下：

left_length= (ulong) (net->buff_end - net->write_pos); //net buffer剩余大小

  if (len > left_length) //packet 大小大于了 net buffer剩余大小
  {
    if (net->write_pos != net->buff)
    {
      /* Fill up already used packet and write it */
      memcpy(net->write_pos, packet, left_length);
      if (net_write_packet(net, net->buff,
                           (size_t) (net->write_pos - net->buff) + left_length)) //底层发送
        return 1;
      net->write_pos= net->buff;
      packet+= left_length;
      len-= left_length;
    }

而net_write_packet就是底层发送的接口。而增加Rows_sent就比较简单了就是函数THD::inc_sent_row_count了。如果整体debug在net_write_packet和THD::inc_sent_row_count函数上的话，能够发现，多次THD::inc_sent_row_count才会调用一次net_write_packet，因为有buffer嘛。

二、最近遇到的一些BUG

这里只是简单记录一下，没有做深入分析。

2.1 insert undo BUG

8.0.21 使用 create table A select B 后，当B表越来越大，insert undo 如果到达truncate设置大小，有机会触发crash BUG。虽然insert undo比较小，值记录了主键，但是insert undo 并不是purge线程清理的而是session线程自己清理的。本BUG因为insert undo 可能由于purge线程truncate后导致本session在清理的时候找不page。BUG如下：

查看bug，有如下：

    Bug#33162828: INNODB: Assertion failure: ut0ut.cc:552 thread 140294520874752

    Problem:
    Server crashes when an undo tablespace is truncated while
    an active transaction is using it.

    Solution:
    Do not mark the transaction as complete until all the cleanup is done.

修复版本为8.0.27

InnoDB: Truncation of an undo tablespace during use by an active transaction raised an assertion failure. The transaction was prematurely marked as complete, permitting the truncation operation. (Bug #33162828)

2.2 MTS 并发hang死BUG

https://bugs.mysql.com/bug.php?id=103636

这个BUG 8.0.28 修复，看起来是MTS 和参数slave_preserve_commit_order有关，而Commit_order_manager类作为管理从库提交顺序的数据结构，其中在处理的时候某个局部变量为unsigned int，应该使用类型unsigned long long，导致了唤醒不了woker线程的BUG。

这个BUG由印风提交并且修复。