级联slave中延迟计算和query event exe time获取方法的示例分析

一、级联时间计算方式

逻辑如下：

级联中的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的工作设个设置就是设置为eventheader的timestamp，因此还是级联中记录的Event的时间还是主库的时间，计算延迟就是相对主库的时间。栈帧#0THD::set_time(this=0x7ffe74007da0,t=0x7ffe7493c4d0)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526#10x00000000018459abinQuery_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#20x0000000001845287inQuery_log_event::do_apply_event(this=0x7ffe7493c3b0,rli=0x676be60)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:4567#30x00000000018420d4inLog_event::apply_event(this=0x7ffe7493c3b0,rli=0x676be60)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:3570#40x00000000018bc078inapply_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#50x00000000018bd773inexec_relay_log_event(thd=0x7ffe74007da0,rli=0x676be60)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:5300#60x00000000018c46e4inhandle_slave_sql(arg=0x6675d30)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:7543#70x0000000001945620inpfs_spawn_thread(arg=0x7ffe7c02c6c0)at/root/mysqlall/percona-server-locks-detail-5.7.22/storage/perfschema/pfs.cc:2190#80x00007ffff7bc6aa1instart_thread()from/lib64/libpthread.so.0#90x00007ffff6719bcdinclone()from/lib64/libc.so.6#0THD::set_time(this=0x7ffe74007da0,t=0x7ffe7493c4d0)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526#10x00000000018459abinQuery_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#20x0000000001845287inQuery_log_event::do_apply_event(this=0x7ffe7493c3b0,rli=0x676be60)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:4567#30x00000000018420d4inLog_event::apply_event(this=0x7ffe7493c3b0,rli=0x676be60)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:3570#40x00000000018bc078inapply_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#50x00000000018bd773inexec_relay_log_event(thd=0x7ffe74007da0,rli=0x676be60)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:5300#60x00000000018c46e4inhandle_slave_sql(arg=0x6675d30)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/rpl_slave.cc:7543#70x0000000001945620inpfs_spawn_thread(arg=0x7ffe7c02c6c0)at/root/mysqlall/percona-server-locks-detail-5.7.22/storage/perfschema/pfs.cc:2190#80x00007ffff7bc6aa1instart_thread()from/lib64/libpthread.so.0#90x00007ffff6719bcdinclone()from/lib64/libc.so.6querymapevent在修改的第一条数据记录时间这个时间肯定是Log_event::apply_event的时间，GTID自然是在最后commit的时候,XIDEVENT也是正确的主库时间。实际上第一个THD::set_time(header->timestamp)后user_time就正确，下面的逻辑不会设置为当前时间。inlinevoidset_time(){start_utime=utime_after_lock=my_micro_time();if(user_time.tv_sec||user_time.tv_usec){start_time=user_time;}elsemy_micro_time_to_timeval(start_utime,&start_time);#ifdefHAVE_PSI_THREAD_INTERFACEPSI_THREAD_CALL(set_thread_start_time)(start_time.tv_sec);#endif}但是主库dispatch_command的时候不会设置user_timeuser_time为0，因此设置为当前时间。#0THD::set_time(this=0x7ffedc0009c0)at/mysqldata/percona-server-locks-detail-5.7.22/sql/sql_class.h:3514#10x00000000015c5fe8indispatch_command(thd=0x7ffedc0009c0,com_data=0x7fffec5bdd70,command=COM_QUERY)at/mysqldata/percona-server-locks-detail-5.7.22/sql/sql_parse.cc:1247#20x00000000015c58ffindo_command(thd=0x7ffedc0009c0)at/mysqldata/percona-server-locks-detail-5.7.22/sql/sql_parse.cc:1021#30x000000000170e578inhandle_connection(arg=0x67d01a0)at/mysqldata/percona-server-locks-detail-5.7.22/sql/conn_handler/connection_handler_per_thread.cc:312#40x0000000001945538inpfs_spawn_thread(arg=0x67c9dc0)at/mysqldata/percona-server-locks-detail-5.7.22/storage/perfschema/pfs.cc:2190#50x00007ffff7bcfaa1instart_thread()from/lib64/libpthread.so.0#60x00007ffff6b37c4dinclone()from/lib64/libc.so.6

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

common_header：中的时间来自命令发起的时间。下面是其初始化Log_event::Log_event(THD*thd_arg,uint16flags_arg,enum_event_cache_typecache_type_arg,enum_event_logging_typelogging_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,constchar*query_arg,size_tquery_length,boolusing_trans,boolimmediate,boolsuppress_use,interrcode,boolignore_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););/*savetheoriginalthreadid;wealreadyknowtheserverid*/slave_proxy_id=thd_arg->variables.pseudo_thread_id;if(query!=0)is_valid_param=true;/*exec_timecalculationhaschangedtousethesamemethodthatisusedtofillout"thd_arg->start_time"*/structtimevalend_time;ulonglongmicro_end_time=my_micro_time();//这里获取时间queryeventmy_micro_time_to_timeval(micro_end_time,&end_time);exec_time=end_time.tv_sec-thd_arg->start_time.tv_sec;//这里计算时间