一、问题来源

这个问题如下：

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中找到答案。

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

三、特殊场景说明

我们这里看到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线程的压力进行判断，忙死的情况下这种日志报告还是有一定参考意义的。但是闲死的情况下就没有什么意义了忽略就是了。