有趣的 events_statements_current 表問題

什麼是events_statements_current表

在GreatSQL中，PFS下有一張記憶體表: events_statements_current，看到這個名稱"xxx_current"，小白如我可能會認為這張表中的資料就是當前系統的活躍(active)語句。該表的描述如下(有部分省略):

mysql> desc events_statements_current;
+-------------------------+------------------------------------------------+------+-----+---------+-------+
| Field                   | Type                                           | Null | Key | Default | Extra |
+-------------------------+------------------------------------------------+------+-----+---------+-------+
| THREAD_ID               | bigint unsigned                                | NO   | PRI | NULL    |       |
| EVENT_ID                | bigint unsigned                                | NO   | PRI | NULL    |       |
| END_EVENT_ID            | bigint unsigned                                | YES  |     | NULL    |       |
| EVENT_NAME              | varchar(128)                                   | NO   |     | NULL    |       |
| SOURCE                  | varchar(64)                                    | YES  |     | NULL    |       |
| TIMER_START             | bigint unsigned                                | YES  |     | NULL    |       |
| TIMER_END               | bigint unsigned                                | YES  |     | NULL    |       |
| TIMER_WAIT              | bigint unsigned                                | YES  |     | NULL    |       |
| LOCK_TIME               | bigint unsigned                                | NO   |     | NULL    |       |
| SQL_TEXT                | longtext                                       | YES  |     | NULL    |       |
| DIGEST                  | varchar(64)                                    | YES  |     | NULL    |       |
| DIGEST_TEXT             | longtext                                       | YES  |     | NULL    |       |
| CURRENT_SCHEMA          | varchar(64)                                    | YES  |     | NULL    |       |
...
| MYSQL_ERRNO             | int                                            | YES  |     | NULL    |       |
| RETURNED_SQLSTATE       | varchar(5)                                     | YES  |     | NULL    |       |
| MESSAGE_TEXT            | varchar(128)                                   | YES  |     | NULL    |       |
...
+-------------------------+------------------------------------------------+------+-----+---------+-------+
44 rows in set (0.01 sec)

直接使用當前語句表的問題

直接做個小實驗，終端1：

SELECT sleep(1);

終端2：

USE performance_schema;

-- 檢視最近使用者語句
SELECT s.thread_id, s.sql_text FROM events_statements_current s, threads t 
 WHERE s.thread_id = t.thread_id AND t.type = 'FOREGROUND';

輸出:

mysql> SELECT s.thread_id, s.sql_text FROM events_statements_current s, threads t WHERE s.thread_id = t.thread_id AND t.type = 'FOREGROUND';
+-----------+--------------------------------------------------------------------------------------------------------------------------------------+
| thread_id | sql_text                                                                                                                             |
+-----------+--------------------------------------------------------------------------------------------------------------------------------------+
|        58 | select sleep(1)                                                                                                                      |
|      1849 | SELECT s.thread_id, s.sql_text FROM events_statements_current s, threads t WHERE s.thread_id = t.thread_id AND t.type = 'FOREGROUND' |
+-----------+--------------------------------------------------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)

反覆執行上述語句，發現終端1當前執行的語句都是：SELECT sleep(1)，看起來有點像BUG呀 。

真的是這樣嗎? 來細看一下文件的定義：

The events_statements_current table contains current statement events. The table stores one row per thread showing the current status of the thread's most recent monitored statement event, so there is no system variable for configuring the table size.

發現了一些關鍵資訊: "showing the current status of the thread's most recent monitored statement event"，也就是說：儲存的是執行緒最近被檢測到的語句事件，並非當前正在處於執行狀態的語句

獲取當前活躍的語句方法

為了瞭解這個問題的解決方案，來看看具體實現的程式碼：

void pfs_end_statement_vc(PSI_statement_locker *locker, void *stmt_da) {
  PSI_statement_locker_state *state =
      reinterpret_cast<PSI_statement_locker_state *>(locker);
  ...
  if (state->m_discarded) {
    return;
  }

  ...
  // storage/perfschema/pfs.cc:6462 
  if (flags & STATE_FLAG_TIMED) {
    timer_end = get_statement_timer();
    wait_time = timer_end - state->m_timer_start;
  }
  ...
  
  if (flags & STATE_FLAG_THREAD) {
    ...
    if(flags & STATE_FLAG_EVENT) {
      ...
      // storage/perfschema/pfs.cc:6528
      pfs->m_timer_end = timer_end;
      pfs->m_cpu_time = cpu_time;
      pfs->m_end_event_id = thread->m_event_id;
      ...
    }
  }

說明，在語句執行結束的時候，PFS會更新記錄：

• m_timer_end 執行結束時間
• m_end_event_id 語句結束事件ID

繼續閱讀程式碼，發現除了在：pfs_start_statement_vc中對該值進行初始化外，修改該值的程式碼僅有這一處，基本可以得出結論：m_timer_end > 0 或 m_end_event_id >0 代表語句執行已經結束。

整個簡易工具測一下:

. ./setenv

FOR i IN $(seq 1 1000000)
DO
mysql -h127.0.0.1 -P3306 -uroot <<EOF
USE performance_schema;

-- 列印所有的進行中使用者SQL(除了自身)
SELECT s.* FROM events_statements_current s, threads t WHERE s.thread_id = t.thread_id AND t.type = 'FOREGROUND' AND sql_text like '%FOREGROUND%' = FALSE AND s.end_event_id IS NULL \G
EOF
    sleep 0.1 # 每0.1秒跑一下
DONE

執行結果:

*************************** 1. row ***************************
              THREAD_ID: 15082
               EVENT_ID: 127
           END_EVENT_ID: NULL
             EVENT_NAME: statement/sql/select
                 SOURCE: init_net_server_extension.cc:95
            TIMER_START: 19879433851621000
              TIMER_END: 19880288626029000
             TIMER_WAIT: 854774408000
              LOCK_TIME: 0
               SQL_TEXT: select sleep(1), 3
...

將工具SQL替換成

-- 移除原來的 s.end_event_id is NULL
SELECT s.* FROM events_statements_current s, threads t 
 WHERE s.thread_id = t.thread_id AND t.type = 'FOREGROUND' AND sql_text like '%FOREGROUND%' = FALSE AND s.timer_end = 0 \G

再次執行：

## 真的是啥也沒有啊，真的是啥也沒有啊，

再仔細看看文件 (https://dev.mysql.com/doc/refman/5.7/en/performance-schema-events-statements-current-table.html):

TIMER_START, TIMER_END, TIMER_WAIT

Timing information for the event. The unit for these values is picoseconds (trillionths of a second). 
The TIMER_START and TIMER_END values indicate when event timing started and ended. TIMER_WAIT is the event elapsed time (duration).

If an event has not finished, TIMER_END is the current timer value and TIMER_WAIT is the time elapsed so far (TIMER_END − TIMER_START).

重要資訊: 當事件沒有完成，TIMER_END會持續參考當前時間更新

與想象的很不一樣，無奈開啟原始碼，看看有什麼線索

//storage/perfschema/table_events_statements.cc:315(table_events_statements_common)
  if (m_row.m_end_event_id == 0) {
    timer_end = get_statement_timer();
  } else {
    timer_end = statement->m_timer_end;
  }

換句話說：執行未結束時，statement->m_timer_end的值確實是0，但是timer_end賦值用的是語句計時器的當前時間。

測試結論：events_statements_current可以用於描述當前活躍語句，活躍這個條件可以使用：END_EVENT_ID IS NULL來過濾。