mysql5.7 中启用MTS后error log中大量Note日志分析

mysql5.7,启用基于logical_clock的多线程复制,发现error日志增长很快,查看日志发现大量关于多线程复制的Note级别日志。

2018-07-03T03:22:01.638371+08:00 8941 [Note] Multi-threaded slave statistics for channel '': seconds elapsed = 298; events assigned = 3043329; worker queues filled over ove
rrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 725810947700 waited (count) when Workers occupied = 5346 wait
ed when Workers occupied = 0
2018-07-03T03:24:22.589147+08:00 8941 [Note] Multi-threaded slave statistics for channel '': seconds elapsed = 141; events assigned = 3044353; worker queues filled over ove
rrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 725810947700 waited (count) when Workers occupied = 5346 wait
ed when Workers occupied = 0
2018-07-03T03:27:00.554437+08:00 8941 [Note] Multi-threaded slave statistics for channel '': seconds elapsed = 158; events assigned = 3045377; worker queues filled over ove
rrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 725818557700 waited (count) when Workers occupied = 5346 wait
ed when Workers occupied = 0
2018-07-03T03:32:00.079699+08:00 8941 [Note] Multi-threaded slave statistics for channel '': seconds elapsed = 300; events assigned = 3047425; worker queues filled over ove
rrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 725846344900 waited (count) when Workers occupied = 5346 wait
ed when Workers occupied = 0
2018-07-03T03:34:04.567887+08:00 8941 [Note] Multi-threaded slave statistics for channel '': seconds elapsed = 124; events assigned = 3048449; worker queues filled over ove
rrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 725852036800 waited (count) when Workers occupied = 5346 wait
ed when Workers occupied = 0

通过日期可以看到,日志的打印频率大概在3分钟左右。error log是mysql 出现问题时的重要分析日志,大量的note日志可能很快就把重要日志信息埋没,给分析日志信息带来了不便。而且日志量随时间递增,还必须有rotate机制,不然占用大量磁盘空间。那么这个日志的打印频率能不能调低一些呢?

我看了下源码这块的实现(rpl_slave.cc 4800)

  *ptr_ev= NULL; // announcing the event is passed to w-worker
 
       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)
         {
           sql_print_information("Multi-threaded slave statistics%s: "
                                 "seconds elapsed = %lu; "
                                 "events assigned = %llu; "
                                 "worker queues filled over overrun level = %lu; "
                                 "waited due a Worker queue full = %lu; "
                                 "waited due the total size = %lu; "
                                 "waited at clock conflicts = %llu "
                                 "waited (count) when Workers occupied = %lu "
                                 "waited when Workers occupied = %llu",
                                 rli->get_for_channel_str(),
                                 static_cast<unsigned long>
                                 (my_now - rli->mts_last_online_stat),
                                 rli->mts_events_assigned,
                                 rli->mts_wq_overrun_cnt,
                                 rli->mts_wq_overfill_cnt,
                                 rli->wq_size_waits_cnt,
                                 rli->mts_total_wait_overlap,
                                 rli->mts_wq_no_underrun_cnt,
                                 rli->mts_total_wait_worker_avail);
           rli->mts_last_online_stat= my_now;

我们从两个if语句可以看到,这个信息的打印受三个条件的控制:

  1. rli->is_parallel_exec() 这是个inline函数,它判断是否在使用多线程复制
  2. rli->mts_events_assigned % 1024 == 1 多线程执行的event个数刚刚超过1024个。也就是说按evnet个数来算,每隔1024个event打印一次。
  3. 最后还有个时间限制:(my_now - rli->mts_last_online_stat) >=
    mts_online_stat_period,距离上一次统计超过既定的间隔mts_online_stat_period。这个变量是60*2 ,代码里写死了。
 /*
   Statistics go to the error log every # of seconds when --log-warnings > 1
 */
 const long mts_online_stat_period= 60 * 2;

由此可以判断,这个日志打印频率最少为2分钟,没法改了。但上面的代码注释中给了提示,当--log-warnings > 1时,这个统计间隔才生效,意味着可以通过修改日志打印级别来控制。

自mysql5.7.2,log-warnings被废弃,引用了新的变量log_error_verbosity。这个变量有三个值:1、2、3,默认是3. 他们的意义是:
1 -- Errors Only
2 -- Errors and warnings
3 -- Errors, warnings, and notes

我们可以修改这个变量为2 ,不再打印Note信息。

set global log_error_verbosity=2;

阅读更多

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,921评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 87,635评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,393评论 0 338
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,836评论 1 277
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,833评论 5 368
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,685评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,043评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,694评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 42,671评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,670评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,779评论 1 332
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,424评论 4 321
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,027评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,984评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,214评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,108评论 2 351
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,517评论 2 343

推荐阅读更多精彩内容