AI 助理
备案控制台
开发者社区 数据库 文章 正文

级联slave的延迟计算和query event exe time获取方法

2019-11-22 751
版权
版权声明：
本文内容由阿里云实名注册用户自发贡献，版权归原作者所有，阿里云开发者社区不拥有其著作权，亦不承担相应法律责任。具体规则请查看《 阿里云开发者社区用户服务协议》和 《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容，填写 侵权投诉表单进行举报，一经查实，本社区将立刻删除涉嫌侵权内容。
本文涉及的产品
RDS MySQL Serverless 基础系列，0.5-2RCU 50GB
推荐场景：
学生管理系统数据库设计 搭建个人博客
云数据库 RDS MySQL，集群系列 2核4GB
推荐场景：
搭建个人博客
RDS MySQL Serverless 高可用系列，价值2615元额度，1个月
简介： 一、级联时间计算方式比如A->B->C那么C的延迟是计算B还是A的。因为Event的中timestamp没变，但是C计算时间差值却是以B为准。如果时钟同步的情况下，其实基本可以考虑为A的。计算方法可以参考我的《深入理解MySQL主从原理》专栏逻辑如下：级联中的Event依然是主库的时间，因此其延迟还是相对主库而言。

一、级联时间计算方式

比如A->B->C那么C的延迟是计算B还是A的。因为Event的中timestamp没变，但是C计算时间差值却是以B为准。如果时钟同步的情况下，其实基本可以考虑为A的。计算方法可以参考我的《深入理解MySQL主从原理》专栏

KTA2LA6$`_9Z0B2~P)FULPL.png

逻辑如下：

级联中的Event依然是主库的时间，因此其延迟还是相对主库而言。
虽然apply_event_and_update_pos函数中由设置为当前时间thd->set_time()
但是最终设置还是在Query_log_event::do_apply_event和Query_log_event::do_apply_event中的
的
THD::set_time (this=0x7ffe74007da0, t=0x7ffe74007828)

因为只有做了数据库修改才会触发记录Event的工作

设个设置就是设置为event header的timestamp，因此还是级联中记录的Event的时间还是
主库的时间，计算延迟就是相对主库的时间。



栈帧

#0  THD::set_time (this=0x7ffe74007da0, t=0x7ffe7493c4d0) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
#1  0x00000000018459ab in Query_log_event::do_apply_event (this=0x7ffe7493c3b0, rli=0x676be60, query_arg=0x7ffe740061dc "BEGIN", q_len_arg=5)
    at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:4714
#2  0x0000000001845287 in Query_log_event::do_apply_event (this=0x7ffe7493c3b0, rli=0x676be60)
    at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:4567
#3  0x00000000018420d4 in Log_event::apply_event (this=0x7ffe7493c3b0, rli=0x676be60) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:3570
#4  0x00000000018bc078 in apply_event_and_update_pos (ptr_ev=0x7fffec094830, thd=0x7ffe74007da0, rli=0x676be60)
    at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:4766
#5  0x00000000018bd773 in exec_relay_log_event (thd=0x7ffe74007da0, rli=0x676be60) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:5300
#6  0x00000000018c46e4 in handle_slave_sql (arg=0x6675d30) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:7543
#7  0x0000000001945620 in pfs_spawn_thread (arg=0x7ffe7c02c6c0) at /root/mysqlall/percona-server-locks-detail-5.7.22/storage/perfschema/pfs.cc:2190
#8  0x00007ffff7bc6aa1 in start_thread () from /lib64/libpthread.so.0
#9  0x00007ffff6719bcd in clone () from /lib64/libc.so.6


#0  THD::set_time (this=0x7ffe74007da0, t=0x7ffe7493c4d0) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
#1  0x00000000018459ab in Query_log_event::do_apply_event (this=0x7ffe7493c3b0, rli=0x676be60, query_arg=0x7ffe740061dc "BEGIN", q_len_arg=5)
    at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:4714
#2  0x0000000001845287 in Query_log_event::do_apply_event (this=0x7ffe7493c3b0, rli=0x676be60)
    at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:4567
#3  0x00000000018420d4 in Log_event::apply_event (this=0x7ffe7493c3b0, rli=0x676be60) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:3570
#4  0x00000000018bc078 in apply_event_and_update_pos (ptr_ev=0x7fffec094830, thd=0x7ffe74007da0, rli=0x676be60)
    at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:4766
#5  0x00000000018bd773 in exec_relay_log_event (thd=0x7ffe74007da0, rli=0x676be60) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:5300
#6  0x00000000018c46e4 in handle_slave_sql (arg=0x6675d30) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:7543
#7  0x0000000001945620 in pfs_spawn_thread (arg=0x7ffe7c02c6c0) at /root/mysqlall/percona-server-locks-detail-5.7.22/storage/perfschema/pfs.cc:2190
#8  0x00007ffff7bc6aa1 in start_thread () from /lib64/libpthread.so.0
#9  0x00007ffff6719bcd in clone () from /lib64/libc.so.6


query map event在修改的第一条数据 记录时间 这个时间肯定是Log_event::apply_event的时间，
GTID自然是在最后commit的时候 ,XID EVENT也是正确的主库时间。

实际上第一个THD::set_time(header->timestamp)后user_time 就正确，下面的逻辑不会设置为当前时间。

inline void set_time()
  {
    start_utime= utime_after_lock= my_micro_time();
    if (user_time.tv_sec || user_time.tv_usec)
    {
      start_time= user_time;
    }
    else
      my_micro_time_to_timeval(start_utime, &start_time);

#ifdef HAVE_PSI_THREAD_INTERFACE
    PSI_THREAD_CALL(set_thread_start_time)(start_time.tv_sec);
#endif
  }


但是主库dispatch_command的时候不会设置user_time user_time为0，因此设置为当前时间。

#0  THD::set_time (this=0x7ffedc0009c0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/sql_class.h:3514
#1  0x00000000015c5fe8 in dispatch_command (thd=0x7ffedc0009c0, com_data=0x7fffec5bdd70, command=COM_QUERY)
    at /mysqldata/percona-server-locks-detail-5.7.22/sql/sql_parse.cc:1247
#2  0x00000000015c58ff in do_command (thd=0x7ffedc0009c0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/sql_parse.cc:1021
#3  0x000000000170e578 in handle_connection (arg=0x67d01a0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/conn_handler/connection_handler_per_thread.cc:312
#4  0x0000000001945538 in pfs_spawn_thread (arg=0x67c9dc0) at /mysqldata/percona-server-locks-detail-5.7.22/storage/perfschema/pfs.cc:2190
#5  0x00007ffff7bcfaa1 in start_thread () from /lib64/libpthread.so.0
#6  0x00007ffff6b37c4d in clone () from /lib64/libc.so.6

二、header中的timestamp和query_event的exe time计算方式

common_header：中的时间来自 命令发起的时间。下面是其初始化  
  
Log_event::Log_event(THD* thd_arg, uint16 flags_arg,
                     enum_event_cache_type cache_type_arg,
                     enum_event_logging_type logging_type_arg,
                     Log_event_header *header, Log_event_footer *footer)
  : is_valid_param(false), temp_buf(0), exec_time(0),
    event_cache_type(cache_type_arg), event_logging_type(logging_type_arg),
    crc(0), common_header(header), common_footer(footer), thd(thd_arg)
{
  server_id= thd->server_id;
  common_header->unmasked_server_id= server_id;
  common_header->when= thd->start_time;
  common_header->log_pos= 0;
  common_header->flags= flags_arg;
}
 
dispatch_command调用时间


Query_log_event::Query_log_event(THD* thd_arg, const char* query_arg,
                 size_t query_length, bool using_trans,
                 bool immediate, bool suppress_use,
                                 int errcode, bool ignore_cmd_internals)

: binary_log::Query_event(query_arg,
                          thd_arg->catalog().str,
                          thd_arg->db().str,
                          query_length,
                          thd_arg->thread_id(),
                          thd_arg->variables.sql_mode,
                          thd_arg->variables.auto_increment_increment,
                          thd_arg->variables.auto_increment_offset,
                          thd_arg->variables.lc_time_names->number,
                          (ulonglong)thd_arg->table_map_for_update,
                          errcode,
                          thd_arg->db().str ? strlen(thd_arg->db().str) : 0,
                          thd_arg->catalog().str ? strlen(thd_arg->catalog().str) : 0),
  Log_event(thd_arg,
            (thd_arg->thread_specific_used ? LOG_EVENT_THREAD_SPECIFIC_F :
             0) |
            (suppress_use ? LOG_EVENT_SUPPRESS_USE_F : 0),
            using_trans ? Log_event::EVENT_TRANSACTIONAL_CACHE :
                          Log_event::EVENT_STMT_CACHE,
            Log_event::EVENT_NORMAL_LOGGING,
            header(), footer()),
  data_buf(0)
{
  DBUG_EXECUTE_IF("debug_lock_before_query_log_event",
                  DBUG_SYNC_POINT("debug_lock.before_query_log_event", 10););

  /* save the original thread id; we already know the server id */
  slave_proxy_id= thd_arg->variables.pseudo_thread_id;
  if (query != 0)
    is_valid_param= true;
  /*
  exec_time calculation has changed to use the same method that is used
  to fill out "thd_arg->start_time"
  */

  struct timeval end_time;
  ulonglong micro_end_time= my_micro_time();//这里获取时间 query event
  my_micro_time_to_timeval(micro_end_time, &end_time);

  exec_time= end_time.tv_sec - thd_arg->start_time.tv_sec;//这里计算时间
文章标签：
云数据库 RDS MySQL 版
SQL
关系型数据库
MySQL
数据库
相关实践学习
如何快速连接云数据库RDS MySQL
本场景介绍如何通过阿里云数据管理服务DMS快速连接云数据库RDS MySQL，然后进行数据表的CRUD操作。
全面了解阿里云能为你做什么
阿里云在全球各地部署高效节能的绿色数据中心，利用清洁计算为万物互联的新世界提供源源不断的能源动力，目前开服的区域包括中国（华北、华东、华南、香港）、新加坡、美国（美东、美西）、欧洲、中东、澳大利亚、日本。目前阿里云的产品涵盖弹性计算、数据库、存储与CDN、分析与搜索、云通信、网络、管理与监控、应用服务、互联网中间件、移动服务、视频服务等。通过本课程，来了解阿里云能够为你的业务带来哪些帮助     相关的阿里云产品：云服务器ECS 云服务器 ECS（Elastic Compute Service）是一种弹性可伸缩的计算服务，助您降低 IT 成本，提升运维效率，使您更专注于核心业务创新。产品详情: https://www.aliyun.com/product/ecs
重庆八怪
目录
相关文章
ai科技VX_kelaile520
|
NoSQL API 语音技术
Freeswitch如何接收 RECORD_STOP 和 RECORD_START事件
Freeswitch如何接收 RECORD_STOP 和 RECORD_START事件
ai科技VX_kelaile520
361 0
非著名运维
|
SQL 监控 关系型数据库
Mysql主从同步报错解决：Error executing row event: Table zabbix.history-..
Mysql主从同步报错解决：Error executing row event: Table zabbix.history-..
非著名运维
326 0
xaubllxwtvaqiu
|
关系型数据库 MySQL
MySQL:关于RR模式下insert..select sending data状态说明
MySQL:关于RR模式下insert..select sending data状态说明
xaubllxwtvaqiu
132 0
范大脚脚
|
SQL 存储 数据库
SQL Server 合并复制遇到identity range check报错的解决
范大脚脚
1586 0
嗯哼9925
PLSQL中的RECORD小例子
嗯哼9925
1174 0
技术mix呢
SET XACT_ABORT各种用法及显示结果
技术mix呢
1454 0
余二五
|
关系型数据库 MySQL Linux
重复执行show innodb status的方法
余二五
989 0
科技小能手
|
SQL 存储 数据库
使用sp_cycle_errorlog循环SQL Server错误日志
科技小能手
1370 0
科技小能手
|
SQL 存储
查询SQL Server Index上次Rebuild时间
科技小能手
1101 0
技术小胖子
|
关系型数据库 MySQL 存储
[MySQL Status] Queries,Questions,read/s区别,Com_Commit和handle_commit
技术小胖子
3198 0