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)