MySQL：Multi-threaded slave stati

一、问题来源

这个问题如下：

image.png

朋友也分析了binlog发现并没有大事务的存在，且从库压力很小很小。下面我们稍微再来分析一下。

二、以往的说明

• “Waiting for dependent transaction to commit”

由于协调线程判定本事务由于last commit大于current_lwm因此不能并行回放，协调线程处于等待，大事务会加剧这种情况。

• “Waiting for slave workers to process their queues”

由于没有空闲的工作线程，协调线程会等待。这种情况说明理论上的并行度是理想的，但是可能是参数slave_parallel_workers设置不够。当然设置工作线程的个数应该和服务器的配置和负载相结合考虑，因为第29节我们会看到线程是CPU调度最小的单位。

• “Waiting for Slave Worker queue”

由于工作线程的任务队列已满，协调线程会等待。这种情况前面说过是由于一个事务包含了过多的Event并且工作线程应用Event的速度赶不上协调线程分配Event的速度，导致了积压并且超过了16384个Event。

另外实际上还有一种等待如下：
“Waiting for Slave Workers to free pending events”：由所谓的‘big event’造成的，什么是‘big event’呢，源码中描述为：event size is greater than slave_pending_jobs_size_max but less than slave_max_allowed_packet。我个人认为出现的可能性不大，因此没做过多考虑。可以在函数append_item_to_jobs中找到答案。

我们下面对应日志中的输出进行详细解释，如下：

指标	解释
seconds elapsed	整个分配过程消耗的时间，单位秒，超过120秒会出现这个日志。
events assigned	本工作线程分配的Event数量。
worker queues filled over overrun level	本工作线程任务队列中Event个数大于90%的次数。当前硬编码大于14746。
waited due a Worker queue full	本工作线程任务队列已满的次数。当前硬编码大于16384。和前面第三点对应。
waited due the total size	‘big event’的出现的次数。
waited at clock conflicts	由于不能并行回放，协调线程等待的时间，单位纳秒。和前面第一点对应。
waited (count) when Workers occupied	由于没有空闲的工作线程而等待的次数。对应前面第二点。
waited when Workers occupied	由于没有空闲的工作线程而等待的时间。对应前面第二点。

三、特殊场景说明

我们这里看到waited at clock conflict比较大，这是一个累计值，来自rli.mts_total_wait_overlap，单位为纳秒，但是由于是累计值可参考性并不是那么强，只能做一个整体的把控。具体的简化代码如下：

    set_timespec_nsec(&ts[0], 0);//设置开始时间

    thd->ENTER_COND(&rli->logical_clock_cond, &rli->mts_gaq_LOCK,
                    &stage_worker_waiting_for_commit_parent, &old_stage); 
    do
    {
      mysql_cond_wait(&rli->logical_clock_cond, &rli->mts_gaq_LOCK);
    }
    while ((!rli->info_thd->killed && !is_error) &&
           !clock_leq(last_committed_arg, estimate_lwm_timestamp()));//一直等待直到last_commit<= estimate_lwm_timestamp
    thd->EXIT_COND(&old_stage);
    set_timespec_nsec(&ts[1], 0);//设置结束时间
    my_atomic_add64(&rli->mts_total_wait_overlap, diff_timespec(&ts[1], &ts[0])); //相减得到等待市场，加入到rli->mts_total_wait_overlap中

而超过120秒，实际上这里做了简化，更加精确的含义为，如果协调线程1024个event分配的时间大于了120秒则会出现这个警告。那么问题来了，说明时候协调线程的分配1024个event会大于120秒呢？那么显然有2种情况

• 从库worker线程压力较大，也就是以往的说明中描述的这些情况。
• 还有一种特殊的情况就是本来库的压力就很小，在120秒内没有1024个event生成。

我们知道一个常规的小事务通常为 gitd event、query event、map event、dml event、xid event 5 个组成，那么1024event大概就是205个事务，换句话说如果主库压力过小，2分钟之内连205个事务都没有也会触发这个警告。

简单看看判断标准也是非常的简单：

      if (rli->is_parallel_exec() && rli->mts_events_assigned % 1024 == 1) //这里就是进入判断的前提条件
      {
        time_t my_now= my_time(0);

        if ((my_now - rli->mts_last_online_stat) >=
            mts_online_stat_period)//大于2分钟

这可以说是两种极端，出现这个日志报告，要么是压力太大（忙死）、要么是压力太小（闲死）。

四、测试

测试很简单，我们就在主库慢慢的执行200来个事务一定会超过2分钟，那么从库的MTS当每分配到1024个event的时候必然进入判定流程，日志输出如下：

2021-03-15T08:38:23.676061Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 62849ms. The settings might not be optimal. (flushed=0, during the time.)
2021-03-15T08:38:23.696028Z 15 [Note] Multi-threaded slave statistics for channel '': seconds elapsed = 870; events assigned = 2049; worker queues filled over overrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 0 waited (count) when Workers occupied = 0 waited when Workers occupied = 0
4872              rli->mts_last_online_stat= my_now;
(gdb) 
4880      set_timespec_nsec(&rli->ts_exec[1], 0);
(gdb) c
Continuing.

Breakpoint 6, apply_event_and_update_pos (ptr_ev=0x7fffd71ac880, thd=0x7fffcc000ab0, rli=0x7fff9002ef20) at /opt/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:4850
4850            if ((my_now - rli->mts_last_online_stat) >=
(gdb) n
4871                                    rli->mts_total_wait_worker_avail);
(gdb) p my_now
$10 = 1615799283
(gdb) p rli->mts_last_online_stat
$11 = 1615797440
(gdb) n
4864                                    (my_now - rli->mts_last_online_stat),
(gdb) n
4871                                    rli->mts_total_wait_worker_avail);
(gdb) n
4862                                    rli->get_for_channel_str(),
(gdb) n
4871                                    rli->mts_total_wait_worker_avail);
(gdb) n
2021-03-15T09:08:21.325551Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 17962ms. The settings might not be optimal. (flushed=0, during the time.)
2021-03-15T09:08:21.327019Z 15 [Note] Multi-threaded slave statistics for channel '': seconds elapsed = 1843; events assigned = 3073; worker queues filled over overrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 14903300 waited (count) when Workers occupied = 0 waited when Workers occupied = 0
4872              rli->mts_last_online_stat= my_now;

这个日志中我们发现有两个[Note] Multi-threaded slave statistics for channel '':的日志，而3073 - 2049也等于1024，也可以看到有一次的econds elapsed为1843，这是因为我中间去干其他活去了，主库很久都没动，这典型的属于闲死。
可以看到我们闲死的结论得到证明。当然是闲死还是忙死，还是根据从库woker线程的压力进行判断，忙死的情况下这种日志报告还是有一定参考意义的。但是闲死的情况下就没有什么意义了忽略就是了。