从performance_schema中查看MySQL活动Session的详细执行信息

服务器

浏览数:238

2019-7-8

本文出处: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的系统视图(前提是要打开performance_schema),
这个视图中就记录了的信息就比较完整,不但记录了当前语句的执行时间,而且还有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的重要依据
否则,如果连数据库当前在跑什么语句,语句发起的源头在哪里,跑了多久都弄不清楚,优化和诊断无从谈起。

 

作者:MSSQL123