作者:李锡超
一个爱笑的江苏苏宁银行 数据库工程师,主要负责数据库日常运维、自动化建设、DMP平台运维。擅长MySQL、Python、Oracle,爱好骑行、研究技术。
本文来源:原创投稿
*爱可生开源社区出品,原创内容未经授权不得随意使用,转载请联系小编并注明来源。
1. 问题现象:
9月15日,收到告警提示测试环境某系统的 MySQL MGR 集群存在异常。
日志内容如下:
代码语言:sql复制// 10.x.y.97 节点MySQL 错误日志提示节点 10.x.y.95 不可达:
2022-09-15T19:26:14.320181 08:00 0 "Warning" "MY-011493" "Repl" Plugin group_replication reported: "Member with address 10.x.y.95:3306 has become unreachable."
// 随后mgraliver(MGR 探针)日志提示进行了切换:
"2022-09-15 19:26:16" : Exception: Invalid primary_member_ip: or secondary_node_list:""10.x.y.96", "10.x.y.97"" .
"2022-09-15 19:26:16" : Exception: MGR is likely to be switching, Sleep 1 sec and continue .
"2022-09-15 19:27:01" : Exception: MGR running with WARN. ONLINE nodes Pri:10.x.y.96 Sec:10.x.y.97 diff from conf_node:10.x.y.95,10.x.y.96,10.x.y.97 .
即告警提示应用系统 MySQL MGR 发生了切换,由故障前的三节点 MGR 集群,切换为包括 Pri:10.x.y.96 Sec:10.x.y.97 两个节点集群。
2. 初步分析
收到告警后,通过分析MySQL错误日志、操作系统系统、监控日志等信息,发现操作系统的时间存在异常:
具体异常截图,如下图:
即:存在【Time has been changed 】异常。
结合mysql官方文档说明:其明确说明其故障检测基于时间:
1) 如果一个成员在 5 秒内没有收到另一个成员的消息,则怀疑该成员发生故障,并在自己的 Performance Schema 表 replication_group_members 中将该成员的状态列为 UNREACHABLE。
2) 如果怀疑持续超过 10 秒,则怀疑成员会尝试将其认为可疑成员有错误的观点传播给该组的其他成员。
具体参考:https://dev.mysql.com/doc/refman/8.0/en/group-replication-responses-failure.html
由此初步怀疑是操作系统的时间发生了跳变,触发MySQL MGR发生故障切换。
并将相关异常,反馈系统系统管理部相关老师进行进一步确认。
3. 根本原因
经过系统专家深入分析,确认其根本原因是由于问题时段服务器底层存在异常。
导致 19:27:13左右 虚拟机发生挂起(此时虚拟机的任何操作都不能进行,包括监控脚本、时间、MGR的心跳等)。
虚拟机挂起后,由于除故障节点外的其它两个节点无法与故障节点进行通信,因此认为该节点存在异常并将其驱逐。并最终产生如上告警信息。
至此,该问题得到最终确认。
4. 关于时间对MGR的影响
既然该问题最终确认是由于虚拟机挂起导致主节点被驱逐。那么如果不是挂起,只是虚拟机的时间发生跳变,那还会触发故障切换么??
为此,通过测试环境进行了测试,其测试结论为:
当MGR集群中一个节点时间发生变化后(比如突然快了1小时、慢了1小时),MGR集群的同步状态并不会因此受到影响。error_log 里面也未看到明显的报错!
即:MGR 节点的时间异常,并不会触发MGR发生故障切换。
那具体是什么机制呢??为此结合源码进行确认!!
5. 我们知道,源码中涉及节点间探测,主要包括如下函数(alive_task/detector_task):
函数总体调用关系:
代码语言:txt复制alive_task
task_now
may_be_dead
task_now
detector_task
check_global_node_set
DETECT
task_now
check_local_node_set
DETECT
task_now
// alive_task :
int alive_task(task_arg arg MY_ATTRIBUTE((unused))) {
while (!xcom_shutdown) {
..
// 超过0.5秒,广播我是 alive
f (server_active(site, get_nodeno(site)) < task_now() - 0.5) {
replace_pax_msg(&ep->i_p, pax_msg_new(alive_synode, site));
ep->i_p->op = i_am_alive_op;
send_to_all_site(site, ep->i_p, "alive_task");
}
...
{
double sec = task_now();
// 超过4秒没有心跳,询问你是否活着
if (i != get_nodeno(site) && may_be_dead(site->detected, i, sec)) {
replace_pax_msg(&ep->you_p, pax_msg_new(alive_synode, site));
ep->you_p->op = are_you_alive_op;
ep->you_p->a = new_app_data();
ep->you_p->a->app_key.group_id = ep->you_p->a->group_id =
get_group_id(site);
ep->you_p->a->body.c_t = xcom_boot_type;
init_node_list(1, &site->nodes.node_list_val[i],
&ep->you_p->a->body.app_u_u.nodes);
send_server_msg(site, i, ep->you_p);
}
}
TASK_DELAY(1.0);
}
}
// DETECT
#define DETECTOR_LIVE_TIMEOUT 5.0
// 判断心跳是否超时
#define DETECT(site, i)
(i == get_nodeno(site)) ||
(site->detected[i] DETECTOR_LIVE_TIMEOUT > task_now())
static void check_global_node_set(site_def *site, int *notify) {
u_int i;
u_int nodes = get_maxnodes(site);
site->global_node_count = 0;
for (i = 0; i < nodes && i < site->global_node_set.node_set_len; i ) {
int detect = DETECT(site, i);
if (site->global_node_set.node_set_val[i]) site->global_node_count ;
// 本次捕获的心跳状态,则表示有节点心跳突变: 无心跳->有心跳 有心跳->无心跳
if (site->global_node_set.node_set_val[i] != detect) {
// 需要通知全局状态发生变化
*notify = 1;
}
DBGOHK(FN; NDBG(i, u); NDBG(*notify, d));
}
}
static void check_local_node_set(site_def *site, int *notify) {
u_int i;
u_int nodes = get_maxnodes(site);
for (i = 0; i < nodes && i < site->global_node_set.node_set_len; i ) {
int detect = DETECT(site, i);
// 本次捕获的心跳状态,则表示有节点心跳突变: 无心跳->有心跳 有心跳->无心跳
if (site->local_node_set.node_set_val[i] != detect) {
site->local_node_set.node_set_val[i] = detect;
// 需要通知本地识别到可疑节点
*notify = 1;
}
DBGOHK(FN; NDBG(i, u); NDBG(*notify, d));
}
}
// detector_task
int detector_task(task_arg arg [[maybe_unused]]) {
while (!xcom_shutdown) {
{
site_def *x_site = get_executor_site_rw();
if (x_site && get_nodeno(x_site) != VOID_NODE_NO) {
if (x_site != last_x_site) {
reset_disjunct_servers(last_x_site, x_site);
}
update_detected(x_site);
if (x_site != last_x_site) {
last_x_site = x_site;
ep->notify = 1;
ep->local_notify = 1;
}
check_global_node_set(x_site, &ep->notify); //判断是否有节点心跳超时,需要发起全局view变更通知
update_global_count(x_site); //更新全局节点个数
/* Send xcom message if node has changed state */
if (ep->notify && iamtheleader(x_site) && enough_live_nodes(x_site)) {
ep->notify = 0;
send_my_view(x_site);//如果有节点心跳异常,且当前节点是0号主节点,且多数派的节点存活,
则发送视图变更通知,即驱逐心跳异常节点,并处理新节点加入或老节点退出
}
}
if (x_site && get_nodeno(x_site) != VOID_NODE_NO) {
update_global_count(x_site); //更新全局节点个数
check_local_node_set(x_site, &ep->local_notify);//判断是否有节点心跳超时,需要发起suspicion操作
if (ep->local_notify) {
ep->local_notify = 0;
deliver_view_msg(x_site); /* To application */ //驱逐心跳异常节点
}
}
}
TIMED_TASK_WAIT(&detector_wait, 1.0);
}
}
}
重点
通过阅读以上代码,可知函数 alive_task/detector_task 都通过 task_now() 获取当前时间,并进行判断是否超过对应的阈值。
那么进一步分析 task_now() 逻辑如下:
代码语言:txt复制task_now
xcom_init_clock
xcom_monotonic_seconds
seconds
static void xcom_init_clock(xcom_clock *clock) {
// 调用Linux 的 clock_gettime 函数,获取从系统启动时开始计时,以秒为单位(小于1秒以小数表示)。该时间不受系统影响,也不会被用户改变。
clock->monotonic_start = get_monotonic_time();
// 调用Linux 的 clock_gettime 函数,获取系统时间(如date),以秒为单位(小于1秒以小数表示)。该时间随着系统时间的改变而改变。
clock->real_start = get_real_time();
// 计算系统时间与启动计时的差值(offset)
clock->offset = clock->real_start - clock->monotonic_start;
// 通过差值 启动计时,得到时间。
xcom_monotonic_seconds(clock);
// 修改计算标记为1。此后,只要MGR正常运行,MGR节点所获取时间等于=此处获取的差值(offset) 启动计时。
// 因此,无论系统时间如何变化,MGR都将获取“正确”的时间。
// 具体逻辑见如下代码:
clock->done = 1;
}
static double xcom_monotonic_seconds(xcom_clock *clock) {
// 初始化时获取的差值(offset) 启动计时。
clock->now = get_monotonic_time() clock->offset;
return clock->now;
}
// 后续其它操作获取时间的函数:
double seconds() {
// 当第一步初始化后,!task_timer.done 始终未false
if (!task_timer.done) { ,
xcom_init_clock(&task_timer);
}
// 因此初始化之后调用seconds()返回 :xcom_monotonic_seconds(&task_timer)
return xcom_monotonic_seconds(&task_timer);
}
double task_now() {
// 当第一步初始化后,!task_timer.done 始终未false。
if (!task_timer.done) {
xcom_init_clock(&task_timer);
}
// 直接返回计算的 task_timer.now
return task_timer.now;
}
对于 task_timer.now,通过跟踪发现多个逻辑都在调用,部分位置参考,如下代码栈:
/*
group_replication.so!seconds() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:310)
group_replication.so!task_loop() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:1210)
group_replication.so!xcom_taskmain2(xcom_port listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_base.cc:1536)
group_replication.so!Gcs_xcom_proxy_impl::xcom_init(Gcs_xcom_proxy_impl * const this, xcom_port xcom_listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_proxy.cc:243)
group_replication.so!xcom_taskmain_startup(void * ptr) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_control_interface.cc:102)
pfs_spawn_thread(void * arg) (/source_code/mysql-8.0.27/storage/perfschema/pfs.cc:2946)
libpthread.so.0!start_thread (未知源:0)
libc.so.6!clone (未知源:0)
group_replication.so!seconds() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:310)
group_replication.so!alive_task(task_arg arg) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_detector.cc:452)
group_replication.so!task_loop() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:1158)
group_replication.so!xcom_taskmain2(xcom_port listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_base.cc:1536)
group_replication.so!Gcs_xcom_proxy_impl::xcom_init(Gcs_xcom_proxy_impl * const this, xcom_port xcom_listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_proxy.cc:243)
group_replication.so!xcom_taskmain_startup(void * ptr) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_control_interface.cc:102)
pfs_spawn_thread(void * arg) (/source_code/mysql-8.0.27/storage/perfschema/pfs.cc:2946)
libpthread.so.0!start_thread (未知源:0)
libc.so.6!clone (未知源:0)
group_replication.so!seconds() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:310)
group_replication.so!incoming_connection_task(task_arg arg) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_transport.cc:761)
group_replication.so!task_loop() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:1158)
group_replication.so!xcom_taskmain2(xcom_port listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_base.cc:1536)
group_replication.so!Gcs_xcom_proxy_impl::xcom_init(Gcs_xcom_proxy_impl * const this, xcom_port xcom_listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_proxy.cc:243)
group_replication.so!xcom_taskmain_startup(void * ptr) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_control_interface.cc:102)
pfs_spawn_thread(void * arg) (/source_code/mysql-8.0.27/storage/perfschema/pfs.cc:2946)
libpthread.so.0!start_thread (未知源:0)
libc.so.6!clone (未知源:0)
group_replication.so!seconds() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:310)
group_replication.so!cache_manager_task(task_arg arg) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_cache.cc:641)
group_replication.so!task_loop() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:1158)
group_replication.so!xcom_taskmain2(xcom_port listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_base.cc:1536)
group_replication.so!Gcs_xcom_proxy_impl::xcom_init(Gcs_xcom_proxy_impl * const this, xcom_port xcom_listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_proxy.cc:243)
group_replication.so!xcom_taskmain_startup(void * ptr) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_control_interface.cc:102)
pfs_spawn_thread(void * arg) (/source_code/mysql-8.0.27/storage/perfschema/pfs.cc:2946)
libpthread.so.0!start_thread (未知源:0)
libc.so.6!clone (未知源:0)
group_replication.so!seconds() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:310)
group_replication.so!get_xcom_message(pax_machine ** p, synode_no msgno, int n) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_base.cc:2909)
group_replication.so!executor_task(task_arg arg) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_base.cc:4382)
group_replication.so!task_loop() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:1158)
group_replication.so!xcom_taskmain2(xcom_port listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_base.cc:1536)
group_replication.so!Gcs_xcom_proxy_impl::xcom_init(Gcs_xcom_proxy_impl * const this, xcom_port xcom_listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_proxy.cc:243)
group_replication.so!xcom_taskmain_startup(void * ptr) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_control_interface.cc:102)
pfs_spawn_thread(void * arg) (/source_code/mysql-8.0.27/storage/perfschema/pfs.cc:2946)
libpthread.so.0!start_thread (未知源:0)
libc.so.6!clone (未知源:0)
group_replication.so!seconds() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:310)
group_replication.so!tcp_reaper_task(task_arg arg) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_transport.cc:1773)
group_replication.so!task_loop() (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/task.cc:1158)
group_replication.so!xcom_taskmain2(xcom_port listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_base.cc:1536)
group_replication.so!Gcs_xcom_proxy_impl::xcom_init(Gcs_xcom_proxy_impl * const this, xcom_port xcom_listen_port) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_proxy.cc:243)
group_replication.so!xcom_taskmain_startup(void * ptr) (/source_code/mysql-8.0.27/plugin/group_replication/libmysqlgcs/src/bindings/xcom/gcs_xcom_control_interface.cc:102)
pfs_spawn_thread(void * arg) (/source_code/mysql-8.0.27/storage/perfschema/pfs.cc:2946)
libpthread.so.0!start_thread (未知源:0)
libc.so.6!clone (未知源:0)
*/
6. debug 验证记录
代码语言:txt复制/*
[Switching to Thread 0x7fff4e7fc700 (LWP 21685)]
1: {*site->servers[0], *site->servers[1], *site->servers[2], sec} = <error: array elements must all be the same size>
-exec print {*site->servers[0], *site->servers[1], *site->servers[2], sec}
array elements must all be the same size
[New Thread 0x7fff4dffb700 (LWP 21717)]
[Thread 0x7fff4dffb700 (LWP 21717) exited]
[Switching to Thread 0x7ffff7ee7a00 (LWP 21476)]
[Switching to Thread 0x7fff4e7fc700 (LWP 21685)]
1: {*site->servers[0], *site->servers[1], *site->servers[2], sec} = <error: array elements must all be the same size>
-exec display {*site->servers[0], *site->servers[1], *site->servers[2]}
2: {*site->servers[0], *site->servers[1], *site->servers[2]} = {{garbage = 0, refcnt = 4, srv = 0x7fff42558400 "10.211.55.14", port = 33302, con = 0x7fff42556f40, active = 1664038872.1307986, detected = 1664038872.7222638, outgoing = {data = {type = 0, suc = 0x7fff42558640, pred = 0x7fff42558640}, queue = {type = 0, suc = 0x7fff425686a0, pred = 0x7fff425686a0}}, sender = 0x7fff425686a0, reply_handler = 0x7fff4256c5c0, out_buf = {start = 0, n = 0, buf = "