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

王柳 · 2024-2-15 00:40:00

马上注册，结交更多好友，享用更多功能，让你轻松玩转社区。

您需要登录才可以下载或查看，没有账号？立即注册

x

问题

最近有好几个朋友问，如何将 performance_schema.events_statements_xxx 中的 TIMER 字段（主要是TIMER_START和TIMER_END）转换为日期时间。
因为 TIMER 字段的单位是皮秒（picosecond），所以很多童鞋会尝试直接转换，但转换后的结果并不对，看下面这个示例。

mysql> select * from performance_schema.events_statements_current limit 1\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 1 row in set (0.00 sec) # 因为1秒等于10^12皮秒，所以需要先除以 1000000000000。 mysql> select from_unixtime(3304047000000/1000000000000); +--------------------------------------------+ | from_unixtime(3304047000000/1000000000000) | +--------------------------------------------+ | 1970-01-01 08:00:03.3040 | +--------------------------------------------+ 1 row in set (0.00 sec)

复制代码

下面会从源码角度分析 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来生成的。

int table_events_statements_common::make_row_part_1( PFS_events_statements *statement, sql_digest_storage *digest) { ulonglong timer_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(); ... return 0; } void time_normalizer::to_pico(ulonglong start, ulonglong end, 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 实际上就是在这两个函数中被赋值的。

void pfs_start_statement_vc(PSI_statement_locker *locker, const char *db, uint db_len, const char *src_file, uint src_line) { ... if (flags & STATE_FLAG_TIMED) { timer_start = get_statement_timer(); state->m_timer_start = timer_start; } ... pfs->m_timer_start = timer_start; ... } void pfs_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()的具体实现。

ulonglong inline get_statement_timer() { return USED_TIMER(); } # 如果有其它的计数器实现，只需更新宏定义即可。 #define USED_TIMER my_timer_nanoseconds ulonglong my_timer_nanoseconds(void) { ... #elif defined(HAVE_CLOCK_GETTIME) && defined(CLOCK_REALTIME) { struct timespec tp; clock_gettime(CLOCK_REALTIME, &tp); return (ulonglong)tp.tv_sec * 1000000000 + (ulonglong)tp.tv_nsec; } ... #else return 0; #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：将计数器值转换为皮秒的转换因子。

这两个变量是在实例启动时被赋值的。

void init_timers(void) { double pico_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> create database test; Query OK, 1 row affected (0.01 sec) mysql> create table test.t1(id int primary key, c1 datetime(6)); Query OK, 0 rows affected (0.05 sec) mysql> insert into test.t1 values(1, now(6)); Query OK, 1 row affected (0.02 sec) mysql> select * from test.t1; +----+----------------------------+ | id | c1 | +----+----------------------------+ | 1 | 2023-12-05 23:57:01.892242 | +----+----------------------------+ 1 row in set (0.01 sec) mysql> select * from performance_schema.events_statements_history where digest_text like '%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: insert into test.t1 values(1, now(6)) DIGEST: b2e0770f7505d35d2894321783fe92b7ebfbb908f687b98966efdc58d3386b3c DIGEST_TEXT: INSERT INTO `test` . `t1` VALUES ( ? , NOW (?) ) ... EXECUTION_ENGINE: PRIMARY 1 row in set (0.04 sec) mysql> select (unix_timestamp(now(6)) - variable_value) * 1000000000 into @mysql_start_time from performance_schema.global_status where variable_name = 'uptime'; Query OK, 1 row affected (0.02 sec) mysql> select sql_text, timer_start, from_unixtime((timer_start/1000 + @mysql_start_time)/1000000000) as formatted_time from performance_schema.events_statements_history where digest_text like '%insert%'; +---------------------------------------+----------------+----------------------------+ | sql_text | timer_start | formatted_time | +---------------------------------------+----------------+----------------------------+ | insert into test.t1 values(1, now(6)) | 24182166000000 | 2023-12-05 23:57:02.356767 | +---------------------------------------+----------------+----------------------------+ 1 row in set (0.01 sec)

复制代码

插入时间（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( const PFS_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]; } #define USED_TIMER_NAME TIMER_NAME_NANOSEC

复制代码

2. performance_schema 表的实现注释

storage/perfschema/pfs.cc文件中有一段注释。
这段注释非常重要，它介绍了 performance_schema 中的表是如何实现的。
以下是 events_statements_xxx 相关的注释。

... Implemented as: - [1] #pfs_start_statement_vc(), #pfs_end_statement_vc() (1a, 1b) is an aggregation by EVENT_NAME, (1c, 1d, 1e) is an aggregation by TIME, (1f) is an aggregation by DIGEST all of these are orthogonal, and implemented in #pfs_end_statement_vc(). - [2] #pfs_delete_thread_v1(), #aggregate_thread_statements() - [3] @c PFS_account::aggregate_statements() - [4] @c PFS_host::aggregate_statements() - [A] EVENTS_STATEMENTS_SUMMARY_BY_THREAD_BY_EVENT_NAME, @c table_esms_by_thread_by_event_name::make_row() ... - [H] EVENTS_STATEMENTS_HISTORY_LONG, @c table_events_statements_history_long::make_row() - [I] EVENTS_STATEMENTS_SUMMARY_BY_DIGEST @c table_esms_by_digest::make_row()

复制代码

3. 如何知道 TIMER 字段对应 m_row 中的哪些变量？

两者的对应关系实际上是在table_events_statements_common::read_row_values中定义的。

int table_events_statements_common::read_row_values(TABLE *table, unsigned char *buf, Field **fields, bool read_all) { Field *f; uint len; /* Set the null bits */ 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()) { case 0: /* THREAD_ID */ set_field_ulonglong(f, m_row.m_thread_internal_id); break; ... case 5: /* TIMER_START */ if (m_row.m_timer_start != 0) { set_field_ulonglong(f, m_row.m_timer_start); } else { f->set_null(); } break; case 6: /* TIMER_END */ if (m_row.m_timer_end != 0) { set_field_ulonglong(f, m_row.m_timer_end); } else { f->set_null(); } break; ...

复制代码

免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！

		自动登录	找回密码
密码			立即注册

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

马上注册，结交更多好友，享用更多功能，让你轻松玩转社区。

0 个回复

快速回复

楼主热帖

标签云

浏览过的版块