Description:
When a running thread is killed via MAX_EXECUTION_TIME, (the global variable, session variable, or the optimizer hint), a 'statement/sql/select' event is captured in "performance_schema.events_statements_history". The event looks like this (non-relevant columns omitted):
event_name: statement/sql/select
sql_text: NULL
digest_text: SELECT /*+ MAX_EXECUTION_TIME (?) */ * FROM `t1`
message_text: Query execution was interrupted, maximum statement execution time exceeded
mysql_errno: 3024
All is as expected, expect for the "sql_text" column, which is NULL.
The documentation (https://dev.mysql.com/doc/refman/8.0/en/performance-schema-events-statements-current-table...) for "sql_text" states: "For a command not associated with an SQL statement, the value is NULL." However, it is my understanding the 'statement/sql/select' event (such as that described above) is "...associated with an SQL statement" and should therefore have a non-NULL value for "sql_text".
How to repeat:
Create a minimal test table:
create table t1 (id int(11) not null auto_increment, name varchar(255) not null, primary key (id)) engine=InnoDB default charset=utf8;
Add enough records to the test table to cause the query to be killed via MAX_EXECUTION_TIME:
/* Here we create 8192 records (enough to take longer than 1ms to "select *")*/
insert into t1 (name) value ('name');
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
insert into t1 (name) (select name from t1);
Query the table with a MAX_EXECUTION_TIME optimizer hint set to 1ms:
select /*+ max_execution_time(1) */ * from t1;
ERROR 3024 (HY000): Query execution was interrupted, maximum statement execution time exceeded
Query the 'performance_schema.events_statements_history' table to inspect "sql_text":
select event_name,sql_text,digest_text,message_text,mysql_errno from performance_schema.events_statements_history where mysql_errno = 3024 limit 1\G
*************************** 1. row ***************************
event_name: statement/sql/select
sql_text: NULL
digest_text: SELECT /*+ MAX_EXECUTION_TIME (?) */ * FROM `t1`
message_text: Query execution was interrupted, maximum statement execution time exceeded
mysql_errno: 3024
1 row in set (0.00 sec)
Suggested fix:
From a462e443b518b74d461ea7019a8dd72b459c50e3 Mon Sep 17 00:00:00 2001
From: Thomas Countz <thomascountz@gmail.com>
Date: Mon, 19 Sep 2022 11:55:40 +0000
Subject: [PATCH] do not reset_query_for_display() after thread kill
---
sql/sql_parse.cc | 1 -
1 file changed, 1 deletion(-)
diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc
index 25c55e5fd3e..0079b5b1c5c 100644
--- a/sql/sql_parse.cc
+++ b/sql/sql_parse.cc
@@ -4816,7 +4816,6 @@ finish:
*/
if (thd->killed == THD::KILL_QUERY || thd->killed == THD::KILL_TIMEOUT) {
thd->killed = THD::NOT_KILLED;
- thd->reset_query_for_display();
}
}
--
2.37.3
My colleague, KJ Tsanaktsidis, was able to identify this line as the culprit for setting "sql_text" to NULL. Unfortunately, I'm not currently setup to develop mysql_server, but by looking at git history, it's my understanding that the reset_query_for_display() call was necessary to close Bug#20712046: SHOW PROCESSLIST AND PERFORMANCE_SCHEMA TABLES DO NOT MASK PASSWORD FROM QUERY. I can't seem to find any additional information about Bug#20712046.
Description: When a running thread is killed via MAX_EXECUTION_TIME, (the global variable, session variable, or the optimizer hint), a 'statement/sql/select' event is captured in "performance_schema.events_statements_history". The event looks like this (non-relevant columns omitted): event_name: statement/sql/select sql_text: NULL digest_text: SELECT /*+ MAX_EXECUTION_TIME (?) */ * FROM `t1` message_text: Query execution was interrupted, maximum statement execution time exceeded mysql_errno: 3024 All is as expected, expect for the "sql_text" column, which is NULL. The documentation (https://dev.mysql.com/doc/refman/8.0/en/performance-schema-events-statements-current-table...) for "sql_text" states: "For a command not associated with an SQL statement, the value is NULL." However, it is my understanding the 'statement/sql/select' event (such as that described above) is "...associated with an SQL statement" and should therefore have a non-NULL value for "sql_text". How to repeat: Create a minimal test table: create table t1 (id int(11) not null auto_increment, name varchar(255) not null, primary key (id)) engine=InnoDB default charset=utf8; Add enough records to the test table to cause the query to be killed via MAX_EXECUTION_TIME: /* Here we create 8192 records (enough to take longer than 1ms to "select *")*/ insert into t1 (name) value ('name'); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); insert into t1 (name) (select name from t1); Query the table with a MAX_EXECUTION_TIME optimizer hint set to 1ms: select /*+ max_execution_time(1) */ * from t1; ERROR 3024 (HY000): Query execution was interrupted, maximum statement execution time exceeded Query the 'performance_schema.events_statements_history' table to inspect "sql_text": select event_name,sql_text,digest_text,message_text,mysql_errno from performance_schema.events_statements_history where mysql_errno = 3024 limit 1\G *************************** 1. row *************************** event_name: statement/sql/select sql_text: NULL digest_text: SELECT /*+ MAX_EXECUTION_TIME (?) */ * FROM `t1` message_text: Query execution was interrupted, maximum statement execution time exceeded mysql_errno: 3024 1 row in set (0.00 sec) Suggested fix: From a462e443b518b74d461ea7019a8dd72b459c50e3 Mon Sep 17 00:00:00 2001 From: Thomas Countz <thomascountz@gmail.com> Date: Mon, 19 Sep 2022 11:55:40 +0000 Subject: [PATCH] do not reset_query_for_display() after thread kill --- sql/sql_parse.cc | 1 - 1 file changed, 1 deletion(-) diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 25c55e5fd3e..0079b5b1c5c 100644 --- a/sql/sql_parse.cc +++ b/sql/sql_parse.cc @@ -4816,7 +4816,6 @@ finish: */ if (thd->killed == THD::KILL_QUERY || thd->killed == THD::KILL_TIMEOUT) { thd->killed = THD::NOT_KILLED; - thd->reset_query_for_display(); } } -- 2.37.3 My colleague, KJ Tsanaktsidis, was able to identify this line as the culprit for setting "sql_text" to NULL. Unfortunately, I'm not currently setup to develop mysql_server, but by looking at git history, it's my understanding that the reset_query_for_display() call was necessary to close Bug#20712046: SHOW PROCESSLIST AND PERFORMANCE_SCHEMA TABLES DO NOT MASK PASSWORD FROM QUERY. I can't seem to find any additional information about Bug#20712046.