最近又遇到了双主的主库，备库只读，监控发现主库大量延迟的情况。这里用主库表示读写库，用备库表示只读库。存在问题在于主库的mi->rli->last_master_timestamp得不到更新，因为没有event进行修改，而这个值长期不更新，一般只有在从库binlog切换的时候才会更新。那么只要show slave status满足条件就会进入计算延迟环节且只要计算延迟就很高，但是关键是什么时候回满足条件，这是关键。
这里，主库会接受来自从库的event，也就是事物的event会回传，但是event会过滤掉，但是主库的pos是需要更新的，这包含IO线程和SQL线程都需要更新自身的POS，也就是主库的show slave status看到的POS，这些POS需要跟上从库的binlog位点。也就是在主库大概有3个任务需要完成
1、主库的IO线程会过滤掉从库回传的event，但是特殊的event不过滤
2、主库的IO线程会更新读取到的pos
3、主库的SQL线程会更新应用到的pos
那么IO线程更新和SQL线程更新是一个异步通知的过程，这是根本问题，很容易模拟，就是将SQL线程更新应用的pos线程给他停止掉这个时候show slave status就能出现主库延迟，其中我们watch mi->master_log_pos观察io线程更改pos，同时gdb 断点exec_relay_log_event，理论上就是不让SQL线程更新pos，然后io线程更新了pos，这个时候会进入延迟计算环节，开启gdb线程调试，如下，
- 断点
3 hw watchpoint keep y *((my_off_t *) 0x65364a8)
breakpoint already hit 2 times
4 hw watchpoint keep y *((my_off_t *) 0x65364a8)
5 breakpoint keep y 0x0000000001848850 in exec_relay_log_event(THD*, Relay_log_info*) at /opt/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:5161
- IO线程更新了pos watch mi->master_log_pos
Old value = 376
New value = 416
Hardware watchpoint 4: *((my_off_t *) 0x65364a8)
Old value = 376
New value = 416
Master_info::set_master_log_pos (this=0x65341f0, log_pos=416) at /opt/percona-server-locks-detail-5.7.22/sql/rpl_mi.h:312
312 }
(gdb) c
Continuing.
Hardware watchpoint 3: *((my_off_t *) 0x65364a8)
Old value = 416
New value = 447
Hardware watchpoint 4: *((my_off_t *) 0x65364a8)
Old value = 416
New value = 447
Master_info::set_master_log_pos (this=0x65341f0, log_pos=447) at /opt/percona-server-locks-detail-5.7.22/sql/rpl_mi.h:312
312 }
(gdb) c
Continuing.
- SQL线程不更新POS
(gdb) info threads
Id Target Id Frame
49 Thread 0x7fff385a3700 (LWP 9745) "mysqld" (running)
48 Thread 0x7fff385e5700 (LWP 9732) "mysqld" (running)
47 Thread 0x7fff50059700 (LWP 9731) "mysqld" (running)
46 Thread 0x7fff593f9700 (LWP 9730) "mysqld" (running)
45 Thread 0x7fff5943b700 (LWP 9729) "mysqld" (running)
44 Thread 0x7fff5947d700 (LWP 9728) "mysqld" exec_relay_log_event (thd=0x7ffed4000950, rli=0x653cda0) at /opt/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:5161
* 43 Thread 0x7fff594bf700 (LWP 9727) "mysqld" (running)
42 Thread 0x7fff59501700 (LWP 9674) "mysqld" (running)
41 Thread 0x7fff59543700 (LWP 9669) "mysqld" (running)
- show slave 计算延迟线程
(gdb) n
3836 max(0L, time_diff) : 0));
(gdb) p time_diff
$6 = 131
这里就是延迟的131秒
输出显示如下，
5df75650d7204add4b0bfc7358bf837.png
那么结合模拟的过程来看，实际上这种情况是不可避免的，并且，
- 如果库的事务越多压力越大主库出现延迟的可能性就越高
- 如果主库的压力越大主库出现延迟的可能性就越高
网友评论