翼度科技»论坛 编程开发 mysql 查看内容

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

4

主题

4

帖子

12

积分

新手上路

Rank: 1

积分
12
问题

最近有好几个朋友问,如何将 performance_schema.events_statements_xxx 中的 TIMER 字段(主要是TIMER_START和TIMER_END)转换为日期时间。
因为 TIMER 字段的单位是皮秒(picosecond),所以很多童鞋会尝试直接转换,但转换后的结果并不对,看下面这个示例。
  1. mysql> select * from performance_schema.events_statements_current limit 1\G
  2. *************************** 1. row ***************************
  3.               THREAD_ID: 57
  4.                EVENT_ID: 13
  5.            END_EVENT_ID: 13
  6.              EVENT_NAME: statement/sql/commit
  7.                  SOURCE: log_event.cc:4825
  8.             TIMER_START: 3304047000000
  9.               TIMER_END: 3305287000000
  10.              TIMER_WAIT: 1240000000
  11.              ...
  12.        EXECUTION_ENGINE: PRIMARY
  13. 1 row in set (0.00 sec)

  14. # 因为1秒等于10^12皮秒,所以需要先除以 1000000000000。
  15. mysql> select from_unixtime(3304047000000/1000000000000);
  16. +--------------------------------------------+
  17. | from_unixtime(3304047000000/1000000000000) |
  18. +--------------------------------------------+
  19. | 1970-01-01 08:00:03.3040                   |
  20. +--------------------------------------------+
  21. 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来生成的。
  1. int table_events_statements_common::make_row_part_1(
  2.     PFS_events_statements *statement, sql_digest_storage *digest) {
  3.   ulonglong timer_end;
  4.   ...
  5.   m_normalizer->to_pico(statement->m_timer_start, timer_end,
  6.                         &m_row.m_timer_start, &m_row.m_timer_end,
  7.                         &m_row.m_timer_wait);
  8.   m_row.m_lock_time = statement->m_lock_time * MICROSEC_TO_PICOSEC;

  9.   m_row.m_name = klass->m_name.str();
  10.   m_row.m_name_length = klass->m_name.length();
  11.   ...
  12.   return 0;
  13. }

  14. void time_normalizer::to_pico(ulonglong start, ulonglong end,
  15.                               ulonglong *pico_start, ulonglong *pico_end,
  16.                               ulonglong *pico_wait) {
  17.   if (start == 0) {
  18.     *pico_start = 0;
  19.     *pico_end = 0;
  20.     *pico_wait = 0;
  21.   } else {
  22.     *pico_start = (start - m_v0) * m_factor;
  23.     if (end == 0) {
  24.       *pico_end = 0;
  25.       *pico_wait = 0;
  26.     } else {
  27.       *pico_end = (end - m_v0) * m_factor;
  28.       *pico_wait = (end - start) * m_factor;
  29.     }
  30.   }
  31. }
复制代码
函数中的 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 实际上就是在这两个函数中被赋值的。
  1. void pfs_start_statement_vc(PSI_statement_locker *locker, const char *db,
  2.                             uint db_len, const char *src_file, uint src_line) {
  3.   ...
  4.   if (flags & STATE_FLAG_TIMED) {
  5.     timer_start = get_statement_timer();
  6.     state->m_timer_start = timer_start;
  7.   }
  8.   ...
  9.     pfs->m_timer_start = timer_start;
  10.   ...
  11. }

  12. void pfs_end_statement_vc(PSI_statement_locker *locker, void *stmt_da) {
  13.   ...
  14.   if (flags & STATE_FLAG_TIMED) {
  15.     timer_end = get_statement_timer();
  16.     wait_time = timer_end - state->m_timer_start;
  17.   }
  18.   ...
  19.     pfs->m_timer_end = timer_end;
  20.   ...
  21. }
复制代码
可以看到,无论是语句开始时间(timer_start)还是结束时间(timer_end),调用的都是get_statement_timer()。
接下来,我们看看get_statement_timer()的具体实现。
  1. ulonglong inline get_statement_timer() { return USED_TIMER(); }

  2. # 如果有其它的计数器实现,只需更新宏定义即可。
  3. #define USED_TIMER my_timer_nanoseconds

  4. ulonglong my_timer_nanoseconds(void) {
  5.  ...
  6. #elif defined(HAVE_CLOCK_GETTIME) && defined(CLOCK_REALTIME)
  7.   {
  8.     struct timespec tp;
  9.     clock_gettime(CLOCK_REALTIME, &tp);
  10.     return (ulonglong)tp.tv_sec * 1000000000 + (ulonglong)tp.tv_nsec;
  11.   }
  12.  ...
  13. #else
  14.   return 0;
  15. #endif
  16. }
复制代码
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:将计数器值转换为皮秒的转换因子。
这两个变量是在实例启动时被赋值的。
  1. void init_timers(void) {
  2.   double pico_frequency = 1.0e12;
  3.   ...
  4.   my_timer_init(&pfs_timer_info);
  5.   ...
  6.   cycle_v0 = my_timer_cycles();
  7.   nanosec_v0 = my_timer_nanoseconds(); # 获取系统当前时间,以纳秒表示。
  8.   ...
  9.   if (pfs_timer_info.nanoseconds.frequency > 0) {
  10.     nanosec_to_pico =
  11.         lrint(pico_frequency / (double)pfs_timer_info.nanoseconds.frequency);
  12.   } else {
  13.     nanosec_to_pico = 0;
  14.   }
  15.   ...
  16.   to_pico_data[TIMER_NAME_NANOSEC].m_v0 = nanosec_v0;
  17.   to_pico_data[TIMER_NAME_NANOSEC].m_factor = nanosec_to_pico;
  18.   ...
  19. }
复制代码
可以看到,nanosec_v0 调用的函数,实际上同 m_timer_start、m_timer_end 一样,都是my_timer_nanoseconds。
nanosec_to_pico 是将纳秒转换为皮秒的转换因子,等于 1.0e12/1.0e9 = 1000。
案例

基于上面的分析,我们总结下 TIMER_START 的计算公式。
  1. TIMER_START = (语句执行时的系统时间(单位纳秒)- 实例启动时的系统时间(单位纳秒))* 1000
复制代码
所以,如果要获取语句执行时的系统时间,可将 TIMER_START 除以 1000,然后再加上实例启动时的系统时间。
而实例启动时的系统时间,可通过当前时间(now)减去Uptime这个状态变量来实现。
下面我们通过一个具体的案例来验证下。
  1. mysql> create database test;
  2. Query OK, 1 row affected (0.01 sec)

  3. mysql> create table test.t1(id int primary key, c1 datetime(6));
  4. Query OK, 0 rows affected (0.05 sec)

  5. mysql> insert into test.t1 values(1, now(6));
  6. Query OK, 1 row affected (0.02 sec)

  7. mysql> select * from test.t1;
  8. +----+----------------------------+
  9. | id | c1                         |
  10. +----+----------------------------+
  11. |  1 | 2023-12-05 23:57:01.892242 |
  12. +----+----------------------------+
  13. 1 row in set (0.01 sec)

  14. mysql> select * from performance_schema.events_statements_history where digest_text like '%insert%'\G
  15. *************************** 1. row ***************************
  16.               THREAD_ID: 69
  17.                EVENT_ID: 8
  18.            END_EVENT_ID: 9
  19.              EVENT_NAME: statement/sql/insert
  20.                  SOURCE: init_net_server_extension.cc:97
  21.             TIMER_START: 24182166000000
  22.               TIMER_END: 24208896000000
  23.              TIMER_WAIT: 26730000000
  24.               LOCK_TIME: 254000000
  25.                SQL_TEXT: insert into test.t1 values(1, now(6))
  26.                  DIGEST: b2e0770f7505d35d2894321783fe92b7ebfbb908f687b98966efdc58d3386b3c
  27.             DIGEST_TEXT: INSERT INTO `test` . `t1` VALUES ( ? , NOW (?) )
  28.             ...
  29.        EXECUTION_ENGINE: PRIMARY
  30. 1 row in set (0.04 sec)

  31. mysql> select (unix_timestamp(now(6)) - variable_value) * 1000000000 into @mysql_start_time from performance_schema.global_status where variable_name = 'uptime';
  32. Query OK, 1 row affected (0.02 sec)

  33. 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%';
  34. +---------------------------------------+----------------+----------------------------+
  35. | sql_text                              | timer_start    | formatted_time             |
  36. +---------------------------------------+----------------+----------------------------+
  37. | insert into test.t1 values(1, now(6)) | 24182166000000 | 2023-12-05 23:57:02.356767 |
  38. +---------------------------------------+----------------+----------------------------+
  39. 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。
  1. to_pico_data[TIMER_NAME_CYCLE].m_v0 = cycle_v0;
  2. to_pico_data[TIMER_NAME_CYCLE].m_factor = cycle_to_pico;

  3. to_pico_data[TIMER_NAME_NANOSEC].m_v0 = nanosec_v0;
  4. to_pico_data[TIMER_NAME_NANOSEC].m_factor = nanosec_to_pico;

  5. to_pico_data[TIMER_NAME_MICROSEC].m_v0 = microsec_v0;
  6. to_pico_data[TIMER_NAME_MICROSEC].m_factor = microsec_to_pico;

  7. to_pico_data[TIMER_NAME_MILLISEC].m_v0 = millisec_v0;
  8. 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]。
  1. table_events_statements_common::table_events_statements_common(
  2.     const PFS_engine_table_share *share, void *pos)
  3.     : PFS_engine_table(share, pos) {
  4.   m_normalizer = time_normalizer::get_statement();
  5. }

  6. time_normalizer *time_normalizer::get_statement() {
  7.   return &to_pico_data[USED_TIMER_NAME];
  8. }

  9. #define USED_TIMER_NAME TIMER_NAME_NANOSEC
复制代码
2. performance_schema 表的实现注释

storage/perfschema/pfs.cc文件中有一段注释。
这段注释非常重要,它介绍了 performance_schema 中的表是如何实现的。
以下是 events_statements_xxx 相关的注释。
  1.  ... 
  2.  Implemented as:
  3.   - [1] #pfs_start_statement_vc(), #pfs_end_statement_vc()
  4.        (1a, 1b) is an aggregation by EVENT_NAME,
  5.         (1c, 1d, 1e) is an aggregation by TIME,
  6.         (1f) is an aggregation by DIGEST
  7.         all of these are orthogonal,
  8.         and implemented in #pfs_end_statement_vc().
  9.   - [2] #pfs_delete_thread_v1(), #aggregate_thread_statements()
  10.   - [3] @c PFS_account::aggregate_statements()
  11.   - [4] @c PFS_host::aggregate_statements()
  12.   - [A] EVENTS_STATEMENTS_SUMMARY_BY_THREAD_BY_EVENT_NAME,
  13.         @c table_esms_by_thread_by_event_name::make_row()
  14.   ...
  15.   - [H] EVENTS_STATEMENTS_HISTORY_LONG,
  16.         @c table_events_statements_history_long::make_row()
  17.   - [I] EVENTS_STATEMENTS_SUMMARY_BY_DIGEST
  18.         @c table_esms_by_digest::make_row()
复制代码
3. 如何知道 TIMER 字段对应 m_row 中的哪些变量?

两者的对应关系实际上是在table_events_statements_common::read_row_values中定义的。
  1. int table_events_statements_common::read_row_values(TABLE *table,
  2.                                                     unsigned char *buf,
  3.                                                     Field **fields,
  4.                                                     bool read_all) {
  5.   Field *f;
  6.   uint len;

  7.   /* Set the null bits */
  8.   assert(table->s->null_bytes == 3);
  9.   buf[0] = 0;
  10.   buf[1] = 0;
  11.   buf[2] = 0;

  12.   for (; (f = *fields); fields++) {
  13.     if (read_all || bitmap_is_set(table->read_set, f->field_index())) {
  14.       switch (f->field_index()) {
  15.         case 0: /* THREAD_ID */
  16.           set_field_ulonglong(f, m_row.m_thread_internal_id);
  17.           break;
  18.         ...
  19.         case 5: /* TIMER_START */
  20.           if (m_row.m_timer_start != 0) {
  21.             set_field_ulonglong(f, m_row.m_timer_start);
  22.           } else {
  23.             f->set_null();
  24.           }
  25.           break;
  26.         case 6: /* TIMER_END */
  27.           if (m_row.m_timer_end != 0) {
  28.             set_field_ulonglong(f, m_row.m_timer_end);
  29.           } else {
  30.             f->set_null();
  31.           }
  32.           break;
  33.           ...
复制代码
来源:https://www.cnblogs.com/ivictor/p/17896928.html
免责声明:由于采集信息均来自互联网,如果侵犯了您的权益,请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容,谢谢合作!

举报 回复 使用道具