從performance_schema中查看MySQL活動Session的詳細執行信息

本文出處：http://www.cnblogs.com/wy123/p/7851294.html 在做資料庫的異常診斷的時候，之前在SQL Server上的時候，最主要的參考信息之一就是去看當前的活動Session有哪些，這些活動Session分別在執行什麼語句，用的什麼執行方式（計劃），運行了多久 ...

本文出處：http://www.cnblogs.com/wy123/p/7851294.html

在做資料庫的異常診斷的時候，之前在SQL Server上的時候，最主要的參考信息之一就是去看當前的活動Session有哪些，
這些活動Session分別在執行什麼語句，用的什麼執行方式（計劃），運行了多久，等待資源是什麼
然後利用類似這些信息對問題的診斷提供依據。

在mysql中，雖然換了資料庫平臺，雖然有些東西不一樣，個人認為無非也就是類似這些指標
查看活動Session最常用的命令之一就是show processlist；
其結果中有一個time欄位，但這個欄位在某些情況下幫助不大，它並不是一個Session運行的時間，而是當前語句的運行時間
如果想到知道某個活動Session執行了多久，用show processlist是不夠的。

通過一個簡單的實例來說明類似請，如下是一個簡單的存儲過程

CREATE DEFINER=`root`@`%` PROCEDURE `test_long_run_sql`()
BEGIN
    -- 用 select sleep(10)來模擬長時間運行的過程或者SQL語句
    select sleep(10);
    select count(1) from a;
    
    select sleep(15);
    delete from test01;
END

當調用這個存儲過程的時候，從另外一個Session中執行show processlist
怎麼理解time欄位的含義，比如在存儲過程中有多個sql語句，每個語句運行的時候，都會重置show processlist中的time。
比如這個存儲過程一共會執行25秒秒，在執行select sleep(15);的時候，至少運行了10s，為什麼這裡的Time是3秒？
答案是，這個3秒是第三個sql語句的執行時間，而不是整個Session（存儲過程）的執行時間。

筆者之所以糾結這個問題，是剛接觸MySQL（比較老的5.6）的時候，就被這個問題上猜到過坑
測試環境中，因為一個bug導致一個存儲過程出現死迴圈，死迴圈的存儲過程跑了兩天，知道伺服器很忙，
但是用show processlist的時候，根本發現不了運行了很久的Session
因為迴圈的原因，執行的sql語句不一樣，Time不停地被重置，而且語句的源頭也無從發現（call 存儲過程的名稱），無法得知長時間的Session。

在mysql5.7之後，新的sys庫中有一個session的系統視圖，
這個視圖中就記錄了的信息就比較完整，不但記錄了當前語句的執行時間，而且還有Session級別的執行時間，
參考如下：一個statement_latency是Session級別的，一個statement_latency是語句級別的

這是sys系統庫中的session系統視圖的定義，發現他是從processlist查詢的

SELECT `processlist`.`thd_id` AS `thd_id`
        , `processlist`.`conn_id` AS `conn_id`
        , `processlist`.`user` AS `user`
        , `processlist`.`db` AS `db`
        , `processlist`.`command` AS `command`
        , `processlist`.`state` AS `state`
        , `processlist`.`time` AS `time`
        , `processlist`.`current_statement` AS `current_statement`
        , `processlist`.`statement_latency` AS `statement_latency`
        , `processlist`.`progress` AS `progress`
        , `processlist`.`lock_latency` AS `lock_latency`
        , `processlist`.`rows_examined` AS `rows_examined`
        , `processlist`.`rows_sent` AS `rows_sent`
        , `processlist`.`rows_affected` AS `rows_affected`
        , `processlist`.`tmp_tables` AS `tmp_tables`
        , `processlist`.`tmp_disk_tables` AS `tmp_disk_tables`
        , `processlist`.`full_scan` AS `full_scan`
        , `processlist`.`last_statement` AS `last_statement`
        , `processlist`.`last_statement_latency` AS `last_statement_latency`
        , `processlist`.`current_memory` AS `current_memory`
        , `processlist`.`last_wait` AS `last_wait`
        , `processlist`.`last_wait_latency` AS `last_wait_latency`
        , `processlist`.`source` AS `source`
        , `processlist`.`trx_latency` AS `trx_latency`
        , `processlist`.`trx_state` AS `trx_state`
        , `processlist`.`trx_autocommit` AS `trx_autocommit`
        , `processlist`.`pid` AS `pid`
        , `processlist`.`program_name` AS `program_name`
FROM `sys`.`processlist`
WHERE `processlist`.`conn_id` IS NOT NULL
    AND `processlist`.`command` <> 'Daemon'

繼續看processlist的定義

SELECT `pps`.`THREAD_ID` AS `thd_id`
    ,`pps`.`PROCESSLIST_ID` AS `conn_id`
    , if(`pps`.`NAME` = 'thread/sql/one_connection', concat(`pps`.`PROCESSLIST_USER`, '@', `pps`.`PROCESSLIST_HOST`), replace(`pps`.`NAME`, 'thread/', '')) AS `user`
    , `pps`.`PROCESSLIST_DB` AS `db`
    , `pps`.`PROCESSLIST_COMMAND` AS `command`, `pps`.`PROCESSLIST_STATE` AS `state`
    ,`pps`.`PROCESSLIST_TIME` AS `time`
    , `sys`.`format_statement`(`pps`.`PROCESSLIST_INFO`) AS `current_statement`
    , if(isnull(`esc`.`END_EVENT_ID`), `sys`.`format_time`(`esc`.`TIMER_WAIT`), NULL) AS `statement_latency`
    , if(isnull(`esc`.`END_EVENT_ID`), round(100 * (`estc`.`WORK_COMPLETED` / `estc`.`WORK_ESTIMATED`), 2), NULL) AS `progress`
    , `sys`.`format_time`(`esc`.`LOCK_TIME`) AS `lock_latency`, `esc`.`ROWS_EXAMINED` AS `rows_examined`
    , `esc`.`ROWS_SENT` AS `rows_sent`
    , `esc`.`ROWS_AFFECTED` AS `rows_affected`
    , `esc`.`CREATED_TMP_TABLES` AS `tmp_tables`
    , `esc`.`CREATED_TMP_DISK_TABLES` AS `tmp_disk_tables`
    , if(`esc`.`NO_GOOD_INDEX_USED` > 0 OR `esc`.`NO_INDEX_USED` > 0, 'YES', 'NO') AS `full_scan`
    , if(`esc`.`END_EVENT_ID` IS NOT NULL, `sys`.`format_statement`(`esc`.`SQL_TEXT`), NULL) AS `last_statement`
    , if(`esc`.`END_EVENT_ID` IS NOT NULL, `sys`.`format_time`(`esc`.`TIMER_WAIT`), NULL) AS `last_statement_latency`
    , `sys`.`format_bytes`(`mem`.`current_allocated`) AS `current_memory`
    , `ewc`.`EVENT_NAME` AS `last_wait`
    , if(isnull(`ewc`.`END_EVENT_ID`)
        AND `ewc`.`EVENT_NAME` IS NOT NULL, 'Still Waiting', `sys`.`format_time`(`ewc`.`TIMER_WAIT`)) AS `last_wait_latency`
    , `ewc`.`SOURCE` AS `source`, `sys`.`format_time`(`etc`.`TIMER_WAIT`) AS `trx_latency`, `etc`.`STATE` AS `trx_state`
    , `etc`.`AUTOCOMMIT` AS `trx_autocommit`
    , `conattr_pid`.`ATTR_VALUE` AS `pid`
    , `conattr_progname`.`ATTR_VALUE` AS `program_name`
FROM `performance_schema`.`threads` `pps`
    LEFT JOIN `performance_schema`.`events_waits_current` `ewc` ON `pps`.`THREAD_ID` = `ewc`.`THREAD_ID`
    LEFT JOIN `performance_schema`.`events_stages_current` `estc` ON `pps`.`THREAD_ID` = `estc`.`THREAD_ID`
    LEFT JOIN `performance_schema`.`events_statements_current` `esc` ON `pps`.`THREAD_ID` = `esc`.`THREAD_ID`
    LEFT JOIN `performance_schema`.`events_transactions_current` `etc` ON `pps`.`THREAD_ID` = `etc`.`THREAD_ID`
    LEFT JOIN `sys`.`x$memory_by_thread_by_current_bytes` `mem` ON `pps`.`THREAD_ID` = `mem`.`thread_id`
    LEFT JOIN `performance_schema`.`session_connect_attrs` `conattr_pid`
    ON `conattr_pid`.`PROCESSLIST_ID` = `pps`.`PROCESSLIST_ID`
        AND `conattr_pid`.`ATTR_NAME` = '_pid'
    LEFT JOIN `performance_schema`.`session_connect_attrs` `conattr_progname`
    ON `conattr_progname`.`PROCESSLIST_ID` = `pps`.`PROCESSLIST_ID`
        AND `conattr_progname`.`ATTR_NAME` = 'program_name'
ORDER BY `pps`.`PROCESSLIST_TIME` DESC, `last_wait_latency` DESC

從中可以發現statement_latency，也即語句或者是session的執行時間，
是從`performance_schema`.`events_statements_current`這個系統表中取得的
也即`performance_schema`.`events_statements_current`中的timer_wait欄位

來觀察`performance_schema`.`events_statements_current` 中的信息，還是比較豐富的
1，不難發現，session級別的運行時間和語句級別的運行時間，在thread_id相同的情況下，event_id是不同的，這也是用以區分session和語句的sql語句的
2，從event_name可以看到，前者是call procedure，後者是procedure中的具體的語句
3，sql_text中就是真正的sql語句了，清楚地知道當前在執行什麼語句

實話講，一直不喜歡用MySQL封裝的一些命令，比如show variables;show status;等等
並不是說這些命令不好，如果能夠直接從系統表中查出來，知道這些封裝之後的命令的數據是從哪裡來的。
弄清楚了來源，可能會根據自己的需要，得到更多想要的東西。

在其他資料庫中，都有豐富的系統表可供查詢，MySQL的performance_schema提供了同樣類似的內容，利用好這個庫中的信息可以帶來很大的幫助。
在做異常診斷的時候，弄清楚活動Session的以及其執行的源頭，當前執行的語句，執行的時間等等這些信息，是做trouble shooting的重要依據
否則，如果連資料庫當前在跑什麼語句，語句發起的源頭在哪裡，跑了多久都弄不清楚，優化和診斷無從談起。