千金良方:MySQL性能优化金字塔法则
上QQ阅读APP看本书,新人免费读10天
设备和账号都新为新人

6.3 查看最近的SQL语句执行信息

6.3.1 查看最近的TOP SQL语句

使用performance_schema中的语句当前事件记录表和语句事件历史记录表可以查询数据库中最近执行的一些SQL语句,以及与语句相关的信息。这里以events_statements_history表为例,查询结果按照语句完成时间倒序排序列。

mysql> select THREAD_ID, EVENT_NAME, SOURCE, sys.format_time(TIMER_WAIT), sys.format_time(LOCK_TIME), SQL_TEXT, CURRENT_SCHEMA, MESSAGE_TEXT, ROWS_AFFECTED, ROWS_SENT, ROWS_EXAMINED from events_statements_history where CURRENT_SCHEMA! = 'performance_schema' order by TIMER_WAIT desc limit 10\G
*************************** 1. row ***************************
                THREAD_ID: 114
              EVENT_NAME: statement/sql/update
                  SOURCE: socket_connection.cc:101
sys.format_time(TIMER_WAIT): 24.93 m
 sys.format_time(LOCK_TIME): 24.93 m
                SQL_TEXT: update sbtest1 set pad='xxx' where id=1
            CURRENT_SCHEMA: sbtest
            MESSAGE_TEXT: Rows matched: 0 Changed: 0 Warnings: 0
            ROWS_AFFECTED: 0
                ROWS_SENT: 0
            ROWS_EXAMINED: 0
*************************** 2. row ***************************
                THREAD_ID: 114
              EVENT_NAME: statement/sql/update
                  SOURCE: socket_connection.cc:101
sys.format_time(TIMER_WAIT): 7.84 m
 sys.format_time(LOCK_TIME): 7.84 m
                SQL_TEXT: update sbtest1 set pad='xxx' where id=1
            CURRENT_SCHEMA: sbtest
            MESSAGE_TEXT: Rows matched: 0 Changed: 0 Warnings: 0
            ROWS_AFFECTED: 0
                ROWS_SENT: 0
            ROWS_EXAMINED: 0
......
10 rows in set(0.00 sec)

按照通常优化慢SQL语句的原则,优先优化执行次数最多的语句,然后是执行时间最长的语句。以上查询结果并不是通常所说的TOP SQL语句,我们可以使用events_statements_summary_by_digest表来查询经过统计之后的TOP SQL语句。

mysql>select SCHEMA_NAME, DIGEST_TEXT, COUNT_STAR, sys.format_time(SUM_TIMER_WAIT)as sum_time, sys.format_time(MIN_TIMER_WAIT)as min_time, sys.format_time(AVG_TIMER_WAIT)as avg_time, sys.format_time(MAX_TIMER_WAIT) as  max_time, sys.format_time(SUM_LOCK_TIME) as  sum_lock_time, SUM_ROWS_AFFECTED, SUM_ROWS_SENT, SUM_ROWS_EXAMINED from events_statements_summary_by_digest where SCHEMA_NAME is not null order by COUNT_STAR desc limit 10\G
*************************** 1. row ***************************
      SCHEMA_NAME: sbtest
      DIGEST_TEXT: UPDATE `sbtest1` SET `pad` = ? WHERE `id` = ?
      COUNT_STAR: 10
        sum_time: 2.19 h
        min_time: 216.90 us
        avg_time: 13.15 m
        max_time: 1.50 h
    sum_lock_time: 2.04 h
SUM_ROWS_AFFECTED: 3
    SUM_ROWS_SENT: 0
SUM_ROWS_EXAMINED: 4
*************************** 2. row ***************************
      SCHEMA_NAME: sbtest
      DIGEST_TEXT: SHOW WARNINGS
      COUNT_STAR: 9
        sum_time: 397.62 us
        min_time: 16.50 us
        avg_time: 44.18 us
        max_time: 122.58 us
    sum_lock_time: 0 ps
SUM_ROWS_AFFECTED: 0
    SUM_ROWS_SENT: 0
SUM_ROWS_EXAMINED: 0
......
*************************** 5. row ***************************
      SCHEMA_NAME: sbtest
      DIGEST_TEXT: SELECT * FROM `sbtest1` LIMIT ?
      COUNT_STAR: 5
        sum_time: 138.93 ms
        min_time: 145.77 us
        avg_time: 27.79 ms
        max_time: 112.29 ms
    sum_lock_time: 95.53 ms
SUM_ROWS_AFFECTED: 0
    SUM_ROWS_SENT: 104
SUM_ROWS_EXAMINED: 104
......
10 rows in set(0.00 sec)

提示:events_statements_summary_by_digest表中记录的SQL语句文本并不完整,在默认情况下只截取了1024字节,并且也是使用这1024字节的SQL语句文本进行hash计算的,把hashcode相同的累计计算在一起。performance_schema提供的数据只能算作慢日志分析的一个补充,如果需要完整的SQL语句文本,还得依赖慢查询日志分析。

6.3.2 查看最近执行失败的SQL语句

曾经有同事问,使用代码对数据库的某些操作(比如:使用Python的ORM模块操作数据库)报出语法错误,但是代码并没有记录SQL语句文本的功能,在MySQL数据库层能否查看到具体的SQL语句文本,看看是否哪里写错了?这个时候,大多数人首先想到的就是去查看错误日志。很遗憾,对于SQL语句的语法错误,错误日志并不会记录。如果你没有完全了解performance_schema,那么很可能就会回复说:在MySQL层面也并没有记录语法错误的信息。

实际上,在performance_schema的语句事件记录表中针对每一条语句的执行状态都记录了较为详细的信息,例如:events_statements_表和events_statements_summary_by_digest表(events_statements_表记录了语句所有的执行错误信息,而events_statements_summary_by_digest表只记录了语句在执行过程中发生错误的语句记录统计信息,不记录具体的错误类型,例如:不记录语法错误类的信息)。下面分别演示如何使用这两个表查询语句发生错误的语句信息。

首先,我们模拟一条语法错误的SQL语句,使用events_statements_history_long表或者events_statements_history表查询发生语法错误的SQL语句,开启一个会话(会话1)。

mysql> select * from;
ERROR 1064(42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1

然后,查询events_statements_history表中错误号为1064的记录,开启另一个会话(会话2)。

mysql> use performance_schema
Database changed
mysql>select THREAD_ID, EVENT_NAME, SOURCE, sys.format_time(TIMER_WAIT)as exec_time, sys. format_time (LOCK_TIME)as lock_time, SQL_TEXT, CURRENT_SCHEMA, MESSAGE_TEXT, ROWS_AFFECTED, ROWS_SENT, ROWS_EXAMINED, MYSQL_ERRNO  from  events_statements_history  where  MYSQL_ERRNO=1064\G
*************************** 1. row ***************************
    THREAD_ID: 119
    EVENT_NAME: statement/sql/error
      SOURCE: socket_connection.cc:101
    exec_time: 71.72 us
    lock_time: 0 ps
      SQL_TEXT: select * from
CURRENT_SCHEMA: sbtest
    MESSAGE_TEXT: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use
  ROWS_AFFECTED: 0
      ROWS_SENT: 0
  ROWS_EXAMINED: 0
    MYSQL_ERRNO: 1064
1 row in set(0.01 sec)

可能你不知道错误号是多少,可以查询发生错误次数不为0的语句记录,在里边找到MESSAGE_TEXT字段,提示信息为语法错误的就是它了。

mysql > select THREAD_ID, EVENT_NAME, SOURCE, sys.format_time(TIMER_WAIT)as exec_time, sys.format_time(LOCK_TIME) as  lock_time, SQL_TEXT,  CURRENT_SCHEMA, MESSAGE_TEXT, ROWS_AFFECTED, ROWS_SENT, ROWS_EXAMINED, MYSQL_ERRNO, errors from events_statements_history where errors>0\G
*************************** 1. row ***************************
    THREAD_ID: 119
    EVENT_NAME: statement/sql/error
      SOURCE: socket_connection.cc:101
    exec_time: 71.72 us
    lock_time: 0 ps
      SQL_TEXT: select * from
CURRENT_SCHEMA: sbtest
  MESSAGE_TEXT: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use
 ROWS_AFFECTED: 0
    ROWS_SENT: 0
 ROWS_EXAMINED: 0
  MYSQL_ERRNO: 1064
      errors: 1
1 row in set(0.00 sec)

接下来,使用events_statements_summary_by_digest表查询发生语句执行错误的SQL语句记录。首先,我们在会话1中制造一两条执行一定会发生错误的语句。

mysql> select * ;
ERROR 1096(HY000): No tables used
mysql> select * from sbtest4 where id between 100 and 2000 and xx=1;
ERROR 1054(42S22): Unknown column 'xx' in 'where clause'

然后,在events_statements_summary_by_digest表中查询发生错误次数大于0的记录,在会话2中执行。

mysql>  select  SCHEMA_NAME,  DIGEST_TEXT, COUNT_STAR,  sys.format_time(AVG_TIMER_WAIT) as avg_time, sys.format_time(MAX_TIMER_WAIT) as  max_time, sys.format_time(SUM_LOCK_TIME) as sum_lock_time, SUM_ERRORS, FIRST_SEEN, LAST_SEEN  from  events_statements_summary_by_digest where SUM_ERRORS! =0\G
*************************** 1. row ***************************
......
*************************** 10. row ***************************
  SCHEMA_NAME: sbtest
  DIGEST_TEXT: SELECT *   # 这里就是第一条执行错误的语句
    COUNT_STAR: 1
    avg_time: 55.14 us
    max_time: 55.14 us
sum_lock_time: 0 ps
    SUM_ERRORS: 1
    FIRST_SEEN: 2018-06-25 17:40:57
    LAST_SEEN: 2018-06-25 17:40:57
*************************** 11. row ***************************
  SCHEMA_NAME: sbtest
  DIGEST_TEXT: SELECT * FROM `sbtest4` WHERE `id` BETWEEN ? AND ? AND `xx` = ?   # 这里就是第二条执行错误的语句
  COUNT_STAR: 1
    avg_time: 101.68 us
    max_time: 101.68 us
sum_lock_time: 0 ps
  SUM_ERRORS: 1
  FIRST_SEEN: 2018-06-25 17:41:03
    LAST_SEEN: 2018-06-25 17:41:03
11 rows in set(0.00 sec)

提示:前面说过,在events_statements_summary_by_digest表中不记录具体的错误信息,只做错误语句统计。所以,如果需要查询具体的错误信息(例如:具体的错误代码、具体的错误提示信息以及具体的错误SQL语句文本等),还需要查询events_statements_history表或者events_statements_history_long表。

mysql> select THREAD_ID, EVENT_NAME, SOURCE, sys.format_time(TIMER_WAIT)as exec_time, sys.format_time(LOCK_TIME)as lock_time, SQL_TEXT, CURRENT_SCHEMA, MESSAGE_TEXT, ROWS_AFFECTED, ROWS_SENT, ROWS_EXAMINED, MYSQL_ERRNO from events_statements_history where MYSQL_ERRNO! =0\G
*************************** 1. row ***************************
......
*************************** 2. row ***************************
    THREAD_ID: 119
    EVENT_NAME: statement/sql/select
      SOURCE: socket_connection.cc:101
    exec_time: 55.14 us
    lock_time: 0 ps
      SQL_TEXT: select *
CURRENT_SCHEMA: sbtest
  MESSAGE_TEXT: No tables used
 ROWS_AFFECTED: 0
    ROWS_SENT: 0
 ROWS_EXAMINED: 0
  MYSQL_ERRNO: 1096
*************************** 3. row ***************************
    THREAD_ID: 119
    EVENT_NAME: statement/sql/select
      SOURCE: socket_connection.cc:101
    exec_time: 101.68 us
    lock_time: 0 ps
      SQL_TEXT: select * from sbtest4 where id between 100 and 2000 and xx=1
CURRENT_SCHEMA: sbtest
  MESSAGE_TEXT: Unknown column 'xx' in 'where clause'
 ROWS_AFFECTED: 0
    ROWS_SENT: 0
 ROWS_EXAMINED: 0
  MYSQL_ERRNO: 1054
3 rows in set(0.00 sec)