有个系统的mysql.err日志中存在大量的如下信息:
2025-05-28T17:36:06.790418+08:00 34 [Note] Multi-threaded slave: Coordinator has waited 4881 times hitting slave_pending_jobs_size_max; current event size = 8205.
2025-05-28T17:36:06.797475+08:00 34 [Note] Multi-threaded slave: Coordinator has waited 4891 times hitting slave_pending_jobs_size_max; current event size = 8205.
2025-05-28T17:36:06.804947+08:00 34 [Note] Multi-threaded slave: Coordinator has waited 4901 times hitting slave_pending_jobs_size_max; current event size = 8205.
量有多大呢? 几十GB, 这样会导致: 1. error日志看起来不方便了 2. 磁盘不够了....
虽然这个是Note
级别的信息, 但还是需要分析下, 毕竟量太大了. 从描述信息来看是:
多复制线程(MTS): Coordinator(sql线程的协调者,其实就是sql线程自己) 已经等了4881次(每次都命中了slave_pending_jobs_size_max); 当前的event size是8205字节.
这里提到了一个参数: slave_pending_jobs_size_max, 该参数是MTS场景下才生效的; 其含义是一个队列(worker queues)的大小, 默认16MB(5.7),对1024字节取整.
8.0默认是128MB
那么这个队列是干啥的呢? 其实不难猜: Coordinator解析event然后放到WQ(worker queue),然后worker线程去消费. 这样多线程就能并发的完成回放了.
然后我们结合源码来验证下猜想:
定义opt_mts_pending_jobs_size_max, 该值默认16MB,块大小1024(对1024字节取整), 范围是1024-16E
// sql/sys_vars.cc
static Sys_var_ulonglong Sys_mts_pending_jobs_size_max(
"slave_pending_jobs_size_max",
"Max size of Slave Worker queues holding yet not applied events."
"The least possible value must be not less than the master side "
"max_allowed_packet.",
GLOBAL_VAR(opt_mts_pending_jobs_size_max), CMD_LINE(REQUIRED_ARG),
VALID_RANGE(1024, (ulonglong)~(intptr)0), DEFAULT(16 * 1024*1024),
BLOCK_SIZE(1024), ON_CHECK(0));
该参数需要重启复制进程才有效
// sql/rpl_slave.cc
// length of WQ is actually constant though can be made configurable
rli->mts_slave_worker_queue_len_max= mts_slave_worker_queue_len_max;
rli->mts_pending_jobs_size= 0;
rli->mts_pending_jobs_size_max= ::opt_mts_pending_jobs_size_max; // 这个参数
rli->mts_wq_underrun_w_id= MTS_WORKER_UNDEF;
rli->mts_wq_excess_cnt= 0;
rli->mts_wq_overrun_cnt= 0;
rli->mts_wq_oversize= FALSE;
rli->mts_coordinator_basic_nap= mts_coordinator_basic_nap;
rli->mts_worker_underrun_level= mts_worker_underrun_level;
rli->curr_group_seen_begin= rli->curr_group_seen_gtid= false;
rli->curr_group_isolated= FALSE;
rli->checkpoint_seqno= 0;
rli->mts_last_online_stat= my_time(0);
rli->mts_group_status= Relay_log_info::MTS_NOT_IN_GROUP;
对于日志打印的判断
// sql/rpl_rli_pdb.cc
size_t ev_size= job_item->data->common_header->data_written;
new_pend_size= rli->mts_pending_jobs_size + ev_size;
bool big_event= (ev_size > rli->mts_pending_jobs_size_max);
while ( (!big_event && new_pend_size > rli->mts_pending_jobs_size_max)
|| (big_event && rli->mts_pending_jobs_size != 0 ))
{
rli->mts_wq_oversize= TRUE;
rli->wq_size_waits_cnt++; // waiting due to the total size
thd->ENTER_COND(&rli->pending_jobs_cond, &rli->pending_jobs_lock,
&stage_slave_waiting_worker_to_free_events, &old_stage);
mysql_cond_wait(&rli->pending_jobs_cond, &rli->pending_jobs_lock);
mysql_mutex_unlock(&rli->pending_jobs_lock);
thd->EXIT_COND(&old_stage);
if (thd->killed)
return true;
if (rli->wq_size_waits_cnt % 10 == 1)
sql_print_information("Multi-threaded slave: Coordinator has waited "
"%lu times hitting slave_pending_jobs_size_max; "
"current event size = %zu.",
rli->wq_size_waits_cnt, ev_size);
mysql_mutex_lock(&rli->pending_jobs_lock);
new_pend_size= rli->mts_pending_jobs_size + ev_size;
}
看起来比较绕, 简单来说就是: 如果不存在big_event,就看当前的(WQ)队列加上当前event是否达到16MB限制; 或者当前的event本身就大于16MB(且(WQ)队列不为空)
好像还是比较绕... 画图的花,大概如下逻辑
既然触发条件我们已经知道了, 那我们可以模拟大事务或者调小slave_pending_jobs_size_max
的值. 为了方便, 我们选择后者.
-- 从库修改slave_pending_jobs_size_max=1024并重启复制进程
set global slave_pending_jobs_size_max=1024;
stop slave;
start slave;
-- 主库随便来点超过1024字节的event
delete from sbtest5 limit 10000;
当然我们还可以解析下binlog,先确认event是否大于1024, 随手搓了个
#!/usr/bin/env python
import struct
import time
import sys
import os
def print_event_info(filename):
f = open(filename,'rb')
if f.read(4) != b'\xfebin':
f.seek(0,0)
filesize = os.path.getsize(filename)
last_offset = f.tell()
current_offset = f.tell()
while True:
last_offset = current_offset
t = struct.unpack('<LBLLLH',f.read(19))
current_offset = t[4]
print(f'TIME:{time.strftime("%Y%m%d %H:%M:%S", time.localtime(t[0]))} TYPE:{t[1]} SERVER_ID:{t[2]} SIZE:{t[3]} LOG_POS:{t[4]} FLAGS:{t[5]} OFFSET:{last_offset} --> {current_offset}')
if t[4] >= filesize:
break
f.seek(t[4],0)
f.close()
if len(sys.argv) != 2:
print(f'USAGE: python {sys.argv[0]} mysql-bin.0000x')
sys.exit(1)
filename = sys.argv[1]
if not os.path.exists(filename):
print(f"{filename} not exists")
sys.exit(2)
print_event_info(filename)
我们发现有很多8205字节的event, 那是我们的那条delete语句被拆分为多个event了(就是怕你回放得慢, 提前预判了一手, 但防不住大字段...)
sql语句与event是一对多的关系, event是数据行也是一对多的关系. 所以不能靠event来推测sql数量/数据行数
然后我们去查看下从库的日志, 发现了如下信息
确实出现了大量的[Note] Multi-threaded slave: Coordinator has waited 5001 times hitting slave_pending_jobs_size_max; current event size = 8205
并且和我们解析的binlog是对得上的. 而且也是间隔10次打印一下. 证明我们的猜测是对的.
实际上查看了日志时间和Binlog产生时间, 也是完全吻合的; 而且没得大量日志产生的时候, error log也确实没有该信息产生.
既然原因找到了, 那么解决办法就简单了.
在此之前, 我们得先清理下error log(也可以配置定时任务清理, 以前也分享过相关脚本的), 可参考如下清理方法:
mysql -e "flush error logs"
mv mysql.err mysql.err.to_rm
mysql -e "flush error logs"
rm mysql.err.to_rm
虽然mysql在各个地方都考虑了error log的大小问题, 但还是防不住业务的大事务, 于是索性直接将slave_pending_jobs_size_max默认值调大了
大事务导致的日志狂刷, 清理日志即可,屏蔽Note信息均可. 目前的影响只发现磁盘占用较大.
关于怎么确定Coordinator是sql线程的, 可以使用gdb:
gdb -p `pdiof mysqld`
gdb> break append_item_to_jobs
gdb> continue
# 主库触发大事务
gdb> info threads
然后根据这个thread_os_id去数据库里面查询即可
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。