问题
最近有好几个朋友问,如何将 performance_schema.events_statements_xxx 中的 TIMER 字段(主要是TIMER_START和TIMER_END)转换为日期时间。
因为 TIMER 字段的单位是皮秒(picosecond),所以很多童鞋会尝试直接转换,但转换后的结果并不对,看下面这个示例。
mysql>select*fromperformance_schema.events_statements_currentlimit1G
***************************1.row***************************
THREAD_ID:57
EVENT_ID:13
END_EVENT_ID:13
EVENT_NAME:statement/sql/commit
SOURCE:log_event.cc:4825
TIMER_START:3304047000000
TIMER_END:3305287000000
TIMER_WAIT:1240000000
...
EXECUTION_ENGINE:PRIMARY
1rowinset(0.00sec)
#因为1秒等于10^12皮秒,所以需要先除以 1000000000000。
mysql>selectfrom_unixtime(3304047000000/1000000000000);
+--------------------------------------------+
|from_unixtime(3304047000000/1000000000000)|
+--------------------------------------------+
|1970-01-0108:00:03.3040|
+--------------------------------------------+
1rowinset(0.00sec)
下面会从源码角度分析 TIMER 字段的生成逻辑。
对源码分析不感兴趣的童鞋,可直接跳到后面的案例部分看结论。
TIMER 字段的生成逻辑
当我们查询 events_statements_xxx 表时,会调用对应的 make_row() 函数来生成行数据。
如 events_statements_current 表,对应的生成函数是table_events_statements_current::make_row()
。
make_row 会调用 make_row_part_1 和 make_row_part_2 来生成数据。
TIMER_START、TIMER_END 实际上就是table_events_statements_common::make_row_part_1
调用to_pico
来生成的。
inttable_events_statements_common::make_row_part_1(
PFS_events_statements*statement,sql_digest_storage*digest){
ulonglongtimer_end;
...
m_normalizer->to_pico(statement->m_timer_start,timer_end,
&m_row.m_timer_start,&m_row.m_timer_end,
&m_row.m_timer_wait);
m_row.m_lock_time=statement->m_lock_time*MICROSEC_TO_PICOSEC;
m_row.m_name=klass->m_name.str();
m_row.m_name_length=klass->m_name.length();
...
return0;
}
voidtime_normalizer::to_pico(ulonglongstart,ulonglongend,
ulonglong*pico_start,ulonglong*pico_end,
ulonglong*pico_wait){
if(start==0){
*pico_start=0;
*pico_end=0;
*pico_wait=0;
}else{
*pico_start=(start-m_v0)*m_factor;
if(end==0){
*pico_end=0;
*pico_wait=0;
}else{
*pico_end=(end-m_v0)*m_factor;
*pico_wait=(end-start)*m_factor;
}
}
}
函数中的 start 和 end 分别对应语句的开始时间(m_timer_start)和结束时间(m_timer_end)。
如果 start,end 不为 0,则 pico_start = (start – m_v0) * m_factor,pico_end = (end – m_v0) * m_factor。
pico_start、pico_end 即我们在 events_statements_current 中看到的 TIMER_START 和 TIMER_END。
m_timer_start 和 m_timer_end 的实现逻辑
如果 performance_schema.setup_instruments 中 statement 相关的采集项开启了(默认开启),则语句在开始和结束时会分别调用pfs_start_statement_vc()
和pfs_end_statement_vc()
这两个函数。
m_timer_start 和 m_timer_end 实际上就是在这两个函数中被赋值的。
voidpfs_start_statement_vc(PSI_statement_locker*locker,constchar*db,
uintdb_len,constchar*src_file,uintsrc_line){
...
if(flags&STATE_FLAG_TIMED){
timer_start=get_statement_timer();
state->m_timer_start=timer_start;
}
...
pfs->m_timer_start=timer_start;
...
}
voidpfs_end_statement_vc(PSI_statement_locker*locker,void*stmt_da){
...
if(flags&STATE_FLAG_TIMED){
timer_end=get_statement_timer();
wait_time=timer_end-state->m_timer_start;
}
...
pfs->m_timer_end=timer_end;
...
}
可以看到,无论是语句开始时间(timer_start)还是结束时间(timer_end),调用的都是get_statement_timer()
。
接下来,我们看看get_statement_timer()
的具体实现。
ulonglonginlineget_statement_timer(){returnUSED_TIMER();}
#如果有其它的计数器实现,只需更新宏定义即可。
#defineUSED_TIMERmy_timer_nanoseconds
ulonglongmy_timer_nanoseconds(void){
...
#elifdefined(HAVE_CLOCK_GETTIME)&&defined(CLOCK_REALTIME)
{
structtimespectp;
clock_gettime(CLOCK_REALTIME,&tp);
return(ulonglong)tp.tv_sec*1000000000+(ulonglong)tp.tv_nsec;
}
...
#else
return0;
#endif
}
get_statement_timer()
调用的是 USED_TIMER(),而 USED_TIMER 只不过是个宏定义,实际调用的还是my_timer_nanoseconds
。
my_timer_nanoseconds
是一个计时器函数,用于获取系统当前时间,并将其转换为纳秒级别的时间戳。不同的系统,会使用不同的方法来获取。
对于 linux 系统,它会首先调用clock_gettime
函数获取系统当前时间,然后再将其转换为纳秒。
所以,语句的开始时间(m_timer_start)和结束时间(m_timer_end)取的都是系统当前时间。
m_v0 和 m_factor 的实现逻辑
m_v0和m_factor是结构体 time_normalizer 中的两个变量。其中,
- m_v0:实例的启动时间(计数器值)。
- m_factor:将计数器值转换为皮秒的转换因子。
这两个变量是在实例启动时被赋值的。
voidinit_timers(void){
doublepico_frequency=1.0e12;
...
my_timer_init(&pfs_timer_info);
...
cycle_v0=my_timer_cycles();
nanosec_v0= my_timer_nanoseconds();#获取系统当前时间,以纳秒表示。
...
if(pfs_timer_info.nanoseconds.frequency>0){
nanosec_to_pico=
lrint(pico_frequency/(double)pfs_timer_info.nanoseconds.frequency);
}else{
nanosec_to_pico=0;
}
...
to_pico_data[TIMER_NAME_NANOSEC].m_v0=nanosec_v0;
to_pico_data[TIMER_NAME_NANOSEC].m_factor=nanosec_to_pico;
...
}
可以看到,nanosec_v0 调用的函数,实际上同 m_timer_start、m_timer_end 一样,都是my_timer_nanoseconds
。
nanosec_to_pico 是将纳秒转换为皮秒的转换因子,等于 1.0e12/1.0e9 = 1000。
案例
基于上面的分析,我们总结下 TIMER_START 的计算公式。
TIMER_START=(语句执行时的系统时间(单位纳秒)-实例启动时的系统时间(单位纳秒))*1000
所以,如果要获取语句执行时的系统时间,可将 TIMER_START 除以 1000,然后再加上实例启动时的系统时间。
而实例启动时的系统时间,可通过当前时间(now)减去Uptime
这个状态变量来实现。
下面我们通过一个具体的案例来验证下。
mysql>createdatabasetest;
QueryOK,1rowaffected(0.01sec)
mysql>createtabletest.t1(idintprimarykey,c1datetime(6));
QueryOK,0rowsaffected(0.05sec)
mysql>insertintotest.t1values(1,now(6));
QueryOK,1rowaffected(0.02sec)
mysql>select*fromtest.t1;
+----+----------------------------+
|id|c1|
+----+----------------------------+
|1|2023-12-0523:57:01.892242|
+----+----------------------------+
1rowinset(0.01sec)
mysql>select*fromperformance_schema.events_statements_historywheredigest_textlike'%insert%'G
***************************1.row***************************
THREAD_ID:69
EVENT_ID:8
END_EVENT_ID:9
EVENT_NAME:statement/sql/insert
SOURCE:init_net_server_extension.cc:97
TIMER_START:24182166000000
TIMER_END:24208896000000
TIMER_WAIT:26730000000
LOCK_TIME:254000000
SQL_TEXT:insertintotest.t1values(1,now(6))
DIGEST:b2e0770f7505d35d2894321783fe92b7ebfbb908f687b98966efdc58d3386b3c
DIGEST_TEXT:INSERTINTO`test`.`t1`VALUES(?,NOW(?))
...
EXECUTION_ENGINE:PRIMARY
1rowinset(0.04sec)
mysql>select(unix_timestamp(now(6))-variable_value)*1000000000into@mysql_start_timefromperformance_schema.global_statuswherevariable_name='uptime';
QueryOK,1rowaffected(0.02sec)
mysql>selectsql_text,timer_start,from_unixtime((timer_start/1000+@mysql_start_time)/1000000000)asformatted_timefromperformance_schema.events_statements_historywheredigest_textlike'%insert%';
+---------------------------------------+----------------+----------------------------+
|sql_text|timer_start|formatted_time|
+---------------------------------------+----------------+----------------------------+
|insertintotest.t1values(1,now(6))|24182166000000|2023-12-0523:57:02.356767|
+---------------------------------------+----------------+----------------------------+
1rowinset(0.01sec)
插入时间(2023-12-05 23:57:01.892242)和 formatted_time(2023-12-05 23:57:02.356767)基本吻合,相差不到 0.5s。
为什么会有误差呢?
-
Uptime
这个状态变量的单位是秒。 - 语句的开始时间(m_timer_start)要比语句中的 now(6) 这个时间早。
细节补充
为了可读性,上面其实忽略了很多细节,这里简单记录下。
1. to_pico_data
to_pico_data是个数组,这个数组包含了多个 time_normalizer 类型的元素。
实例启动,在调用init_timers
函数时,实际上还会将以微秒、毫秒为单位的系统时间分别赋值给to_pico_data[TIMER_NAME_MICROSEC].m_v0
、to_pico_data[TIMER_NAME_MILLISEC].m_v0
。
to_pico_data[TIMER服务器托管网_NAME_CYCLE].m_v0=cycle_v0;
to_pico_data[TIMER_NAME_CYCLE].m_factor=cycle_to_pico;
to_pico_data[TIMER_NAME_NANOSEC].m_v0=nanosec_v0;
to_pico_data[TIMER_NAME_NANOSEC].m_factor=nanosec_to_pico;
to_pico_data[TIMER_NAME_MICROSEC].m_v0=microsec_v0;
to_pico_data[TIMER_NAME_MICROSEC].m_factor=microsec_to_pico;
to_pico_data[TIMER_NAME_MILLISEC].m_v0=millisec_v0;
to_pico_data[TIMER_NAME_MILLISEC].m_factor=millisec_to_pico;
既然有这么多个 m_v0,怎么知道time_normalizer::to_pico
函数取的是哪一个呢?
实际上,events_statements_xxx 系列表的实现中,有个基类table_events_statements_common
。
该类的构造函数里面会基于time_normalizer::get_statement()
来初始化 m_normalizer,
而time_normalizer::get_statement()
实际上返回的就是to_pico_data[TIMER_NAME_NANOSEC]
。
table_events_statements_common::table_events_statements_common(
constPFS_engine_table_share*share,void*pos)
:PFS_engine_table(share,pos){
m_normalizer=time_normalizer::get_statement();
}
time_normalizer*time_normalizer::get_statement(){
return&to_pico_data[USED_TIMER_NAME];
}
#defineUSED_TIMER_NAMETIMER_NAME_NANOSEC
2. performance_schema 表的实现注释
storage/perfschema/pfs.cc
文件中有一段注释。
这段注释非常重要,它介绍了 performance_schema 中的表是如何实现的。
以下是 events_statements_xxx 相关的注释。
...
Implementedas:
-[1]#pfs_start_statement_vc(),#pfs_end_statement_vc()
(1a,1b)isanaggregationbyEVENT_NAME,
(1c,1d,1e)isanaggregationbyTIME,
(1f)isanaggregationbyDIGEST
alloftheseareorthogonal,
andimplementedin#pfs_end_statement_vc().
-[2]#pfs_delete_thread_v1(),#aggregate_thread_statements()
-[3]@cPFS_account::aggregate_statements()
-[4]@cPFS_host::aggregate_statements()
-[A]EVENTS_STATEMENTS_SUMMARY_BY_THREAD_BY_EVENT_NAME,
@ctable_esms_by_thread_by_event_name::make_row()
...
-[H]EVENTS_STATEMENTS_HISTORY_LONG,
@ctable_events_statements_hist服务器托管网ory_long::make_row()
-[I]EVENTS_STATEMENTS_SUMMARY_BY_DIGEST
@ctable_esms_by_digest::make_row()
3. 如何知道 TIMER 字段对应 m_row 中的哪些变量?
两者的对应关系实际上是在table_events_statements_common::read_row_values
中定义的。
inttable_events_statements_common::read_row_values(TABLE*table,
unsignedchar*buf,
Field**fields,
boolread_all){
Field*f;
uintlen;
/*Setthenullbits*/
assert(table->s->null_bytes==3);
buf[0]=0;
buf[1]=0;
buf[2]=0;
for(;(f=*fields);fields++){
if(read_all||bitmap_is_set(table->read_set,f->field_index())){
switch(f->field_index()){
case0:/*THREAD_ID*/
set_field_ulonglong(f,m_row.m_thread_internal_id);
break;
...
case5:/*TIMER_START*/
if(m_row.m_timer_start!=0){
set_field_ulonglong(f,m_row.m_timer_start);
}else{
f->set_null();
}
break;
case6:/*TIMER_END*/
if(m_row.m_timer_end!=0){
set_field_ulonglong(f,m_row.m_timer_end);
}else{
f->set_null();
}
break;
...
服务器托管,北京服务器托管,服务器租用 http://www.fwqtg.net
机房租用,北京机房租用,IDC机房托管, http://www.fwqtg.net
相关推荐: elasticsearch(ES)分布式搜索引擎03——(RestClient查询文档,ES旅游案例实战)
目录 3.RestClient查询文档 3.1.快速入门 3.1.1.发起查询请求 3.1.2.解析响应 3.1.3.完整代码 3.1.4.小结 3.2.match查询 3.3.精确查询 3.4.布尔查询 3.5.排序、分页 3.6.高亮 3.6.1.高亮请求…