如何将 performance_schema 中的 TIMER 字段转换为日期时间

问题

最近有好几个朋友问，如何将 performance_schema.events_statements_xxx 中的 TIMER 字段（主要是TIMER_START和TIMER_END）转换为日期时间。

因为 TIMER 字段的单位是皮秒（picosecond），所以很多童鞋会尝试直接转换，但转换后的结果并不对，看下面这个示例。

mysql>select*fromperformance_schema.events_statements_currentlimit1\G
***************************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。

为什么会有误差呢？

1. Uptime这个状态变量的单位是秒。
2. 语句的开始时间（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_history_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;
...