首页
学习
活动
专区
圈层
工具
发布
首页
学习
活动
专区
圈层
工具
MCP广场
社区首页 >专栏 >[MYSQL] error日志文件大量的Multi-threaded slave: Coordinator has waited磁盘占满了

[MYSQL] error日志文件大量的Multi-threaded slave: Coordinator has waited磁盘占满了

原创
作者头像
大大刺猬
发布2025-05-28 18:46:21
发布2025-05-28 18:46:21
17200
代码可运行
举报
文章被收录于专栏:大大刺猬大大刺猬
运行总次数:0
代码可运行

导读

有个系统的mysql.err日志中存在大量的如下信息:

代码语言:txt
复制
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

代码语言:c++
复制
// 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));

该参数需要重启复制进程才有效

代码语言:c++
复制
// 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;

对于日志打印的判断

代码语言:c++
复制
// 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;
  }
  1. 我们发现主要有2种情况,会进入日志打印判断逻辑: a: 不存在big_event, 并且new_pend_size大于rli->mts_pending_jobs_size_max b: 存在big_event, 并且rli->mts_pending_jobs_size不为0如果event大于rli->mts_pending_jobs_size_max, 则判定为大event

看起来比较绕, 简单来说就是: 如果不存在big_event,就看当前的(WQ)队列加上当前event是否达到16MB限制; 或者当前的event本身就大于16MB(且(WQ)队列不为空)

好像还是比较绕... 画图的花,大概如下逻辑

  1. 每等待10次,才打印一次日志, 也就是日志里面的计数应该有10的差值(这么设计估计是想减少日质量吧, 但实际情况还是爆了. 失算了?)

验证

既然触发条件我们已经知道了, 那我们可以模拟大事务或者调小slave_pending_jobs_size_max的值. 为了方便, 我们选择后者.

代码语言:sql
复制
-- 从库修改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, 随手搓了个

代码语言:python
代码运行次数:0
运行
复制
#!/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也确实没有该信息产生.

解决方法

既然原因找到了, 那么解决办法就简单了.

  1. 调大slave_pending_jobs_size_max, 毕竟8.0里面都直接默认128MB了.
  2. 让业务少点大事务, 尤其是大字段(有难度,毕竟目前只影响了日志文件)
  3. 反正是Note信息,直接修改log_error_verbosity=2 (不要Note级别的信息) 方法1,3都挺好用的(3不需要重启复制进程), 使用者可自行选择. 能叫得动开发的, 2也是不错的选择!

在此之前, 我们得先清理下error log(也可以配置定时任务清理, 以前也分享过相关脚本的), 可参考如下清理方法:

代码语言:shell
复制
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:

代码语言:shell
复制
gdb -p `pdiof mysqld`
gdb> break append_item_to_jobs
gdb> continue

# 主库触发大事务

gdb> info threads

然后根据这个thread_os_id去数据库里面查询即可

原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。

如有侵权,请联系 cloudcommunity@tencent.com 删除。

原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。

如有侵权,请联系 cloudcommunity@tencent.com 删除。

评论
登录后参与评论
0 条评论
热度
最新
推荐阅读
目录
  • 导读
  • 分析
  • 验证
  • 解决方法
  • 简单总结
领券
问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档