Description:
While checking if a killed query will be logged in the slow query log, noticed the following behavior.
Log_output = FILE:
------------------
While query is getting executed, used the following commands to kill the query/thread after long_query_time.
1. KILL thread_id → writes to slow query log
2. KILL QUERY thread_id → writes to slow query log
Log_output = TABLE:
---------------------
While query is getting executed, used the following commands to kill the query/thread after long_query_time.
1. KILL thread_id → DOESN'T WRITE to slow query log
2. KILL QUERY thread_id → writes to slow query log
From the observations, we can see that there is inconsistency in writing the killed query to slow query logs. The behavior is dependent on log_output variable and whether thread is killed or the query alone is killed.
Ideally, the behavior should be consistent irrespective of the log_output value. However, based on my tests, when log_output is set to TABLE and if I kill the thread after long_query_time, MySQL is not writing to slow log table.
How to repeat:
-------- LOG_OUTPUT = FILE --------
####### Scenario 1 - LOG_OUTPUT = FILE & using KILL QUERY ########
mysql> Select @@log_output,@@slow_query_log,@@long_query_time;
+--------------+------------------+-------------------+
| @@log_output | @@slow_query_log | @@long_query_time |
+--------------+------------------+-------------------+
| FILE | 1 | 10.000000 |
+--------------+------------------+-------------------+
1 row in set (0.00 sec)
Session 1:
---------
root@ip-172-31-26-131:/usr/local/mysql/bin# ./mysql -uroot -pqwertyuiop
Warning: Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.6.45-debug-log Source distribution
Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> select sleep(20);
Session 2:
----------
( After 14 sec )
mysql> kill query 2;
Query OK, 0 rows affected (0.00 sec)
Then Session 1 output:
---------------------
mysql> select sleep(20);
+-----------+
| sleep(20) |
+-----------+
| 1 |
+-----------+
1 row in set (14.65 sec)
Checked slow query log file:
---------------------------
root@ip-172-31-26-131:/usr/local/mysql/data# tail -10 ip-172-31-26-131-slow.log
Tcp port: 0 Unix socket: (null)
Time Id Command Argument
/usr/local/mysql/bin/mysqld, Version: 5.6.45-debug-log (Source distribution). started with:
Tcp port: 0 Unix socket: (null)
Time Id Command Argument
# Time: 191213 13:55:25
# User@Host: root[root] @ localhost [] Id: 2
# Query_time: 14.646756 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1576245325;
select sleep(20);
####### Scenario 2 - LOG_OUTPUT = FILE && using KILL ########
mysql> Select @@log_output,@@slow_query_log,@@long_query_time;
+--------------+------------------+-------------------+
| @@log_output | @@slow_query_log | @@long_query_time |
+--------------+------------------+-------------------+
| FILE | 1 | 10.000000 |
+--------------+------------------+-------------------+
1 row in set (0.01 sec)
Session 1:
---------
root@ip-172-31-26-131:/usr/local/mysql/bin# ./mysql -uroot -pqwertyuiop
Warning: Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 4
Server version: 5.6.45-debug-log Source distribution
Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> select sleep(20);
Session 2: [ ##### USED KILL INSTEAD OF KILL QUERY ######]
----------
( After around 15 sec )
mysql> kill 4;
Query OK, 0 rows affected (0.00 sec)
Then Session 1 output:
---------------------
mysql> select sleep(20);
ERROR 2013 (HY000): Lost connection to MySQL server during query
Checked slow query log file: [ There is a new entry in the slow query log ]
---------------------------
root@ip-172-31-26-131:/usr/local/mysql/data# tail -15 ip-172-31-26-131-slow.log
Time Id Command Argument
# Time: 191213 13:55:25
# User@Host: root[root] @ localhost [] Id: 2
# Query_time: 14.646756 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1576245325;
select sleep(20);
# Time: 191213 14:02:50
# User@Host: root[root] @ localhost [] Id: 4
# Query_time: 16.270255 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1576245770;
select sleep(20);
-------- LOG_OUTPUT = TABLE --------
####### Scenario 3 - LOG_OUTPUT = TABLE && using KILL QUERY ########
mysql> Select @@log_output,@@slow_query_log,@@long_query_time;
+--------------+------------------+-------------------+
| @@log_output | @@slow_query_log | @@long_query_time |
+--------------+------------------+-------------------+
| TABLE | 1 | 10.000000 |
+--------------+------------------+-------------------+
1 row in set (0.01 sec)
Session 1:
---------
root@ip-172-31-26-131:/usr/local/mysql/bin# ./mysql -uroot -pqwertyuiop
Warning: Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 4
Server version: 5.6.45-debug-log Source distribution
Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> select sleep(20);
Session 2:
----------
( After around 15 sec )
mysql> kill query 4;
Query OK, 0 rows affected (0.00 sec)
Then Session 1 output:
---------------------
mysql> select sleep(20);
+-----------+
| sleep(20) |
+-----------+
| 1 |
+-----------+
1 row in set (15.65 sec)
Checked mysql.slow_log table [ ### THE ABOVE QUERY IS LOGGED TO SLOW_LOG TABLE ### ]
----------------------------
mysql> select * from mysql.slow_log\G
*************************** 1. row ***************************
start_time: 2019-12-13 13:46:00
user_host: root[root] @ localhost []
query_time: 00:00:15
lock_time: 00:00:00
rows_sent: 1
rows_examined: 0
db: db99
last_insert_id: 0
insert_id: 0
server_id: 0
sql_text: select sleep(20)
thread_id: 4
1 row in set (42.85 sec)
####### Scenario 4 - LOG_OUTPUT = TABLE && using KILL ########
mysql> Select @@log_output,@@slow_query_log,@@long_query_time;
+--------------+------------------+-------------------+
| @@log_output | @@slow_query_log | @@long_query_time |
+--------------+------------------+-------------------+
| TABLE | 1 | 10.000000 |
+--------------+------------------+-------------------+
1 row in set (0.01 sec)
Session 1:
---------
mysql> select sleep(20);
Session 2: [ ##### USED KILL INSTEAD OF KILL QUERY ######]
----------
( After around 15 sec )
mysql> kill 4;
Query OK, 0 rows affected (0.00 sec)
Then Session 1 output:
---------------------
mysql> select sleep(20);
ERROR 2013 (HY000): Lost connection to MySQL server during query
Checked mysql.slow_log table [ ##### THE ABOVE QUERY IS NOT LOGGED. BELOW IS THE PREVIOUS SCENARIO ENTRY #####]
----------------------------
mysql> select * from mysql.slow_log\G
*************************** 1. row ***************************
start_time: 2019-12-13 13:46:00
user_host: root[root] @ localhost []
query_time: 00:00:15
lock_time: 00:00:00
rows_sent: 1
rows_examined: 0
db: db99
last_insert_id: 0
insert_id: 0
server_id: 0
sql_text: select sleep(20)
thread_id: 4
1 row in set (0.00 sec)
=============================================================
On checking the trace, noticed that, when log_output=TABLE, MySQL uses open_table(...) function in /root/mysql-server/sql/sql_base.cc to open the mysql.slow_log table.
The function open_table(...) returns true when opening table fails. On success, it returns false.
This function has the below condition
if (!(flags & MYSQL_OPEN_IGNORE_KILLED) && thd->killed)
DBUG_RETURN(TRUE);
In the case where thread was killed and when log_output=TABLE, this condition is passed and it's returning true. Due to this, an entry in the slow_log table is missing.
The same is working when I kill query alone and not thread as the above condition is failed.
Also, since there was no such condition when log_output=FILE, it worked in the all the scenarios.
-------------------------------------------------------------------------------------------------------------
Below is the debug test:
=================
LOG_OUTPUT = TABLE and KILL command:
------------------------------------
Thread 23 "mysqld" hit Breakpoint 7, open_table (thd=0x555557e01130, table_list=0x7fffce192c10, ot_ctx=0x7fffce1927f0)
at /root/mysql-server/sql/sql_base.cc:2662
2662 {
(gdb) n
2666 char *alias= table_list->alias;
(gdb) n
2667 uint flags= ot_ctx->get_flags();
(gdb) n
2673 DBUG_ENTER("open_table");
(gdb) n
2681 DBUG_ASSERT(!table_list->table);
(gdb) p table_list->table
$6 = (TABLE *) 0x0
(gdb) n
2684 if (check_stack_overrun(thd, STACK_MIN_SIZE_FOR_OPEN, (uchar *)&alias))
(gdb) n
2687 if (!(flags & MYSQL_OPEN_IGNORE_KILLED) && thd->killed)
(gdb) p flags
$7 = 2075
(gdb) p 2075 & 0x4000
$8 = 0
(gdb) p thd->killed
$9 = THD::KILL_CONNECTION
(gdb) n
2688 DBUG_RETURN(TRUE);
(gdb) bt
#0 open_table (thd=0x555557e01130, table_list=0x7fffce192c10, ot_ctx=0x7fffce1927f0)
at /root/mysql-server/sql/sql_base.cc:2688
#1 0x0000555555b0b5b9 in open_ltable (thd=0x555557e01130, table_list=0x7fffce192c10,
lock_type=TL_WRITE_CONCURRENT_INSERT, lock_flags=2075) at /root/mysql-server/sql/sql_base.cc:5724
#2 0x0000555555b14c65 in open_log_table (thd=0x555557e01130, one_table=0x7fffce192c10, backup=0x7fffce1929a0)
at /root/mysql-server/sql/sql_base.cc:9584
#3 0x0000555555aa26ec in Log_to_csv_event_handler::log_slow (this=0x5555575d2ea0, thd=0x555557e01130,
current_time=1576772288, query_start_arg=1576772259, user_host=0x7fffce193230 "root[root] @ localhost []",
user_host_len=25, query_utime=29070411, lock_utime=0, is_command=false,
sql_text=0x7fffa0005270 "select sleep(300)", sql_text_len=17) at /root/mysql-server/sql/log.cc:582
#4 0x0000555555aa3e36 in LOGGER::slow_log_print (this=0x555556bc45e0 <logger>, thd=0x555557e01130,
query=0x7fffa0005270 "select sleep(300)", query_length=17) at /root/mysql-server/sql/log.cc:1091
#5 0x0000555555aa717b in slow_log_print (thd=0x555557e01130, query=0x7fffa0005270 "select sleep(300)",
query_length=17) at /root/mysql-server/sql/log.cc:2163
#6 0x0000555555b76bc2 in log_slow_do (thd=0x555557e01130) at /root/mysql-server/sql/sql_parse.cc:1943
#7 0x0000555555b76c45 in log_slow_statement (thd=0x555557e01130) at /root/mysql-server/sql/sql_parse.cc:1967
#8 0x0000555555b76729 in dispatch_command (command=COM_QUERY, thd=0x555557e01130, packet=0x555557e8b021 "",
packet_length=17) at /root/mysql-server/sql/sql_parse.cc:1835
#9 0x0000555555b74138 in do_command (thd=0x555557e01130) at /root/mysql-server/sql/sql_parse.cc:1064
#10 0x0000555555b398c6 in do_handle_one_connection (thd_arg=0x555557e01130)
at /root/mysql-server/sql/sql_connect.cc:982
#11 0x0000555555b39614 in handle_one_connection (arg=0x555557e01130) at /root/mysql-server/sql/sql_connect.cc:899
#12 0x00005555561ee149 in pfs_spawn_thread (arg=0x555557e04ba0) at /root/mysql-server/storage/perfschema/pfs.cc:1861
#13 0x00007ffff77816db in start_thread (arg=0x7fffce194700) at pthread_create.c:463
#14 0x00007ffff6b6b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
LOG_OUTPUT = TABLE and KILL QUERY command:
------------------------------------------
(gdb) n
2666 char *alias= table_list->alias;
(gdb) n
2667 uint flags= ot_ctx->get_flags();
(gdb) n
2673 DBUG_ENTER("open_table");
(gdb) n
2681 DBUG_ASSERT(!table_list->table);
(gdb) n
2684 if (check_stack_overrun(thd, STACK_MIN_SIZE_FOR_OPEN, (uchar *)&alias))
(gdb) n
2687 if (!(flags & MYSQL_OPEN_IGNORE_KILLED) && thd->killed)
(gdb) n
2696 if (table_list->mdl_request.type >= MDL_SHARED_WRITE &&
(gdb) p flags
$1 = 2075
(gdb) p flags & 0x4000
$2 = 0
(gdb) p thd->killed
$3 = THD::NOT_KILLED
(gdb) n
2697 thd->tx_read_only &&
(gdb) n
2696 if (table_list->mdl_request.type >= MDL_SHARED_WRITE &&
(gdb) n
2704 key_length= get_table_def_key(table_list, &key);
(gdb) n
2713 if (thd->locked_tables_mode &&
(gdb) n
2830 if (! (flags & MYSQL_OPEN_HAS_MDL_LOCK))
(gdb) n
2854 if (table_list->mdl_request.type >= MDL_SHARED_WRITE &&
(gdb) bt
#0 open_table (thd=0x555557e022e0, table_list=0x7fffce192c10, ot_ctx=0x7fffce1927f0)
at /root/mysql-server/sql/sql_base.cc:2662
#1 0x0000555555b0b5b9 in open_ltable (thd=0x555557e022e0, table_list=0x7fffce192c10,
lock_type=TL_WRITE_CONCURRENT_INSERT, lock_flags=2075) at /root/mysql-server/sql/sql_base.cc:5724
#2 0x0000555555b14c65 in open_log_table (thd=0x555557e022e0, one_table=0x7fffce192c10, backup=0x7fffce1929a0)
at /root/mysql-server/sql/sql_base.cc:9584
#3 0x0000555555aa26ec in Log_to_csv_event_handler::log_slow (this=0x5555575c0fb0, thd=0x555557e022e0,
current_time=1576773626, query_start_arg=1576773606, user_host=0x7fffce193230 "root[root] @ localhost []",
user_host_len=25, query_utime=20479839, lock_utime=0, is_command=false,
sql_text=0x7fffa0005270 "select sleep(300)", sql_text_len=17) at /root/mysql-server/sql/log.cc:582
#4 0x0000555555aa3e36 in LOGGER::slow_log_print (this=0x555556bc45e0 <logger>, thd=0x555557e022e0,
query=0x7fffa0005270 "select sleep(300)", query_length=17) at /root/mysql-server/sql/log.cc:1091
#5 0x0000555555aa717b in slow_log_print (thd=0x555557e022e0, query=0x7fffa0005270 "select sleep(300)",
query_length=17) at /root/mysql-server/sql/log.cc:2163
#6 0x0000555555b76bc2 in log_slow_do (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1943
#7 0x0000555555b76c45 in log_slow_statement (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1967
#8 0x0000555555b76729 in dispatch_command (command=COM_QUERY, thd=0x555557e022e0, packet=0x555557e9b181 "",
packet_length=17) at /root/mysql-server/sql/sql_parse.cc:1835
#9 0x0000555555b74138 in do_command (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1064
#10 0x0000555555b398c6 in do_handle_one_connection (thd_arg=0x555557e022e0)
at /root/mysql-server/sql/sql_connect.cc:982
#11 0x0000555555b39614 in handle_one_connection (arg=0x555557e022e0) at /root/mysql-server/sql/sql_connect.cc:899
#12 0x00005555561ee149 in pfs_spawn_thread (arg=0x5555575d4a80) at /root/mysql-server/storage/perfschema/pfs.cc:1861
#13 0x00007ffff77816db in start_thread (arg=0x7fffce194700) at pthread_create.c:463
#14 0x00007ffff6b6b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
FOR LOG_OUTPUT = FILE, THERE IS NO SUCH CONDITION. SO, ITS WRITING TO SLOW QUERY LOG IN ALL THE SCENARIOS
#########################################################################################################
LOG_OUTPUT = FILE and KILL command:
-----------------------------------
(gdb) bt
#0 inline_mysql_file_write (src_file=0x5555563cbb28 "/root/mysql-server/mysys/mf_iocache.c", src_line=1792, file=14,
buffer=0x555557654dd0 "# Time: 191219 16:33:26\n# User@Host: root[root] @ localhost [] Id: 1\n# Query_time: 44.445251 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0\nSET timestamp=1576773206;\nselect sleep(300);\n ",
count=195, flags=20) at /root/mysql-server/include/mysql/psi/mysql_file.h:1133
#1 0x0000555555e4e61e in my_b_flush_io_cache (info=0x555556cc7390, need_append_buffer_lock=0)
at /root/mysql-server/mysys/mf_iocache.c:1791
#2 0x0000555555aa6ef6 in MYSQL_QUERY_LOG::write (this=0x555556cc7040, thd=0x555557e022e0, current_time=1576773206,
query_start_arg=1576773161, user_host=0x7fffce193230 "root[root] @ localhost []", user_host_len=25,
query_utime=44445251, lock_utime=0, is_command=false, sql_text=0x7fffa0005270 "select sleep(300)",
sql_text_len=17) at /root/mysql-server/sql/log.cc:2108
#3 0x0000555555aa333d in Log_to_file_event_handler::log_slow (this=0x555556cc6b70, thd=0x555557e022e0,
current_time=1576773206, query_start_arg=1576773161, user_host=0x7fffce193230 "root[root] @ localhost []",
user_host_len=25, query_utime=44445251, lock_utime=0, is_command=false,
sql_text=0x7fffa0005270 "select sleep(300)", sql_text_len=17) at /root/mysql-server/sql/log.cc:789
#4 0x0000555555aa3e36 in LOGGER::slow_log_print (this=0x555556bc45e0 <logger>, thd=0x555557e022e0,
query=0x7fffa0005270 "select sleep(300)", query_length=17) at /root/mysql-server/sql/log.cc:1091
#5 0x0000555555aa717b in slow_log_print (thd=0x555557e022e0, query=0x7fffa0005270 "select sleep(300)",
query_length=17) at /root/mysql-server/sql/log.cc:2163
#6 0x0000555555b76bc2 in log_slow_do (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1943
#7 0x0000555555b76c45 in log_slow_statement (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1967
#8 0x0000555555b76729 in dispatch_command (command=COM_QUERY, thd=0x555557e022e0, packet=0x555557e8f501 "",
packet_length=17) at /root/mysql-server/sql/sql_parse.cc:1835
#9 0x0000555555b74138 in do_command (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1064
#10 0x0000555555b398c6 in do_handle_one_connection (thd_arg=0x555557e022e0)
at /root/mysql-server/sql/sql_connect.cc:982
#11 0x0000555555b39614 in handle_one_connection (arg=0x555557e022e0) at /root/mysql-server/sql/sql_connect.cc:899
#12 0x00005555561ee149 in pfs_spawn_thread (arg=0x5555575d4a80) at /root/mysql-server/storage/perfschema/pfs.cc:1861
#13 0x00007ffff77816db in start_thread (arg=0x7fffce194700) at pthread_create.c:463
#14 0x00007ffff6b6b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Suggested fix:
May be we can use a separate function which allows to open the slow_log table or make some changes to the existing condition to exclude slow_log table.
Description: While checking if a killed query will be logged in the slow query log, noticed the following behavior. Log_output = FILE: ------------------ While query is getting executed, used the following commands to kill the query/thread after long_query_time. 1. KILL thread_id → writes to slow query log 2. KILL QUERY thread_id → writes to slow query log Log_output = TABLE: --------------------- While query is getting executed, used the following commands to kill the query/thread after long_query_time. 1. KILL thread_id → DOESN'T WRITE to slow query log 2. KILL QUERY thread_id → writes to slow query log From the observations, we can see that there is inconsistency in writing the killed query to slow query logs. The behavior is dependent on log_output variable and whether thread is killed or the query alone is killed. Ideally, the behavior should be consistent irrespective of the log_output value. However, based on my tests, when log_output is set to TABLE and if I kill the thread after long_query_time, MySQL is not writing to slow log table. How to repeat: -------- LOG_OUTPUT = FILE -------- ####### Scenario 1 - LOG_OUTPUT = FILE & using KILL QUERY ######## mysql> Select @@log_output,@@slow_query_log,@@long_query_time; +--------------+------------------+-------------------+ | @@log_output | @@slow_query_log | @@long_query_time | +--------------+------------------+-------------------+ | FILE | 1 | 10.000000 | +--------------+------------------+-------------------+ 1 row in set (0.00 sec) Session 1: --------- root@ip-172-31-26-131:/usr/local/mysql/bin# ./mysql -uroot -pqwertyuiop Warning: Using a password on the command line interface can be insecure. Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 2 Server version: 5.6.45-debug-log Source distribution Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> select sleep(20); Session 2: ---------- ( After 14 sec ) mysql> kill query 2; Query OK, 0 rows affected (0.00 sec) Then Session 1 output: --------------------- mysql> select sleep(20); +-----------+ | sleep(20) | +-----------+ | 1 | +-----------+ 1 row in set (14.65 sec) Checked slow query log file: --------------------------- root@ip-172-31-26-131:/usr/local/mysql/data# tail -10 ip-172-31-26-131-slow.log Tcp port: 0 Unix socket: (null) Time Id Command Argument /usr/local/mysql/bin/mysqld, Version: 5.6.45-debug-log (Source distribution). started with: Tcp port: 0 Unix socket: (null) Time Id Command Argument # Time: 191213 13:55:25 # User@Host: root[root] @ localhost [] Id: 2 # Query_time: 14.646756 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1576245325; select sleep(20); ####### Scenario 2 - LOG_OUTPUT = FILE && using KILL ######## mysql> Select @@log_output,@@slow_query_log,@@long_query_time; +--------------+------------------+-------------------+ | @@log_output | @@slow_query_log | @@long_query_time | +--------------+------------------+-------------------+ | FILE | 1 | 10.000000 | +--------------+------------------+-------------------+ 1 row in set (0.01 sec) Session 1: --------- root@ip-172-31-26-131:/usr/local/mysql/bin# ./mysql -uroot -pqwertyuiop Warning: Using a password on the command line interface can be insecure. Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 4 Server version: 5.6.45-debug-log Source distribution Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> select sleep(20); Session 2: [ ##### USED KILL INSTEAD OF KILL QUERY ######] ---------- ( After around 15 sec ) mysql> kill 4; Query OK, 0 rows affected (0.00 sec) Then Session 1 output: --------------------- mysql> select sleep(20); ERROR 2013 (HY000): Lost connection to MySQL server during query Checked slow query log file: [ There is a new entry in the slow query log ] --------------------------- root@ip-172-31-26-131:/usr/local/mysql/data# tail -15 ip-172-31-26-131-slow.log Time Id Command Argument # Time: 191213 13:55:25 # User@Host: root[root] @ localhost [] Id: 2 # Query_time: 14.646756 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1576245325; select sleep(20); # Time: 191213 14:02:50 # User@Host: root[root] @ localhost [] Id: 4 # Query_time: 16.270255 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1576245770; select sleep(20); -------- LOG_OUTPUT = TABLE -------- ####### Scenario 3 - LOG_OUTPUT = TABLE && using KILL QUERY ######## mysql> Select @@log_output,@@slow_query_log,@@long_query_time; +--------------+------------------+-------------------+ | @@log_output | @@slow_query_log | @@long_query_time | +--------------+------------------+-------------------+ | TABLE | 1 | 10.000000 | +--------------+------------------+-------------------+ 1 row in set (0.01 sec) Session 1: --------- root@ip-172-31-26-131:/usr/local/mysql/bin# ./mysql -uroot -pqwertyuiop Warning: Using a password on the command line interface can be insecure. Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 4 Server version: 5.6.45-debug-log Source distribution Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> select sleep(20); Session 2: ---------- ( After around 15 sec ) mysql> kill query 4; Query OK, 0 rows affected (0.00 sec) Then Session 1 output: --------------------- mysql> select sleep(20); +-----------+ | sleep(20) | +-----------+ | 1 | +-----------+ 1 row in set (15.65 sec) Checked mysql.slow_log table [ ### THE ABOVE QUERY IS LOGGED TO SLOW_LOG TABLE ### ] ---------------------------- mysql> select * from mysql.slow_log\G *************************** 1. row *************************** start_time: 2019-12-13 13:46:00 user_host: root[root] @ localhost [] query_time: 00:00:15 lock_time: 00:00:00 rows_sent: 1 rows_examined: 0 db: db99 last_insert_id: 0 insert_id: 0 server_id: 0 sql_text: select sleep(20) thread_id: 4 1 row in set (42.85 sec) ####### Scenario 4 - LOG_OUTPUT = TABLE && using KILL ######## mysql> Select @@log_output,@@slow_query_log,@@long_query_time; +--------------+------------------+-------------------+ | @@log_output | @@slow_query_log | @@long_query_time | +--------------+------------------+-------------------+ | TABLE | 1 | 10.000000 | +--------------+------------------+-------------------+ 1 row in set (0.01 sec) Session 1: --------- mysql> select sleep(20); Session 2: [ ##### USED KILL INSTEAD OF KILL QUERY ######] ---------- ( After around 15 sec ) mysql> kill 4; Query OK, 0 rows affected (0.00 sec) Then Session 1 output: --------------------- mysql> select sleep(20); ERROR 2013 (HY000): Lost connection to MySQL server during query Checked mysql.slow_log table [ ##### THE ABOVE QUERY IS NOT LOGGED. BELOW IS THE PREVIOUS SCENARIO ENTRY #####] ---------------------------- mysql> select * from mysql.slow_log\G *************************** 1. row *************************** start_time: 2019-12-13 13:46:00 user_host: root[root] @ localhost [] query_time: 00:00:15 lock_time: 00:00:00 rows_sent: 1 rows_examined: 0 db: db99 last_insert_id: 0 insert_id: 0 server_id: 0 sql_text: select sleep(20) thread_id: 4 1 row in set (0.00 sec) ============================================================= On checking the trace, noticed that, when log_output=TABLE, MySQL uses open_table(...) function in /root/mysql-server/sql/sql_base.cc to open the mysql.slow_log table. The function open_table(...) returns true when opening table fails. On success, it returns false. This function has the below condition if (!(flags & MYSQL_OPEN_IGNORE_KILLED) && thd->killed) DBUG_RETURN(TRUE); In the case where thread was killed and when log_output=TABLE, this condition is passed and it's returning true. Due to this, an entry in the slow_log table is missing. The same is working when I kill query alone and not thread as the above condition is failed. Also, since there was no such condition when log_output=FILE, it worked in the all the scenarios. ------------------------------------------------------------------------------------------------------------- Below is the debug test: ================= LOG_OUTPUT = TABLE and KILL command: ------------------------------------ Thread 23 "mysqld" hit Breakpoint 7, open_table (thd=0x555557e01130, table_list=0x7fffce192c10, ot_ctx=0x7fffce1927f0) at /root/mysql-server/sql/sql_base.cc:2662 2662 { (gdb) n 2666 char *alias= table_list->alias; (gdb) n 2667 uint flags= ot_ctx->get_flags(); (gdb) n 2673 DBUG_ENTER("open_table"); (gdb) n 2681 DBUG_ASSERT(!table_list->table); (gdb) p table_list->table $6 = (TABLE *) 0x0 (gdb) n 2684 if (check_stack_overrun(thd, STACK_MIN_SIZE_FOR_OPEN, (uchar *)&alias)) (gdb) n 2687 if (!(flags & MYSQL_OPEN_IGNORE_KILLED) && thd->killed) (gdb) p flags $7 = 2075 (gdb) p 2075 & 0x4000 $8 = 0 (gdb) p thd->killed $9 = THD::KILL_CONNECTION (gdb) n 2688 DBUG_RETURN(TRUE); (gdb) bt #0 open_table (thd=0x555557e01130, table_list=0x7fffce192c10, ot_ctx=0x7fffce1927f0) at /root/mysql-server/sql/sql_base.cc:2688 #1 0x0000555555b0b5b9 in open_ltable (thd=0x555557e01130, table_list=0x7fffce192c10, lock_type=TL_WRITE_CONCURRENT_INSERT, lock_flags=2075) at /root/mysql-server/sql/sql_base.cc:5724 #2 0x0000555555b14c65 in open_log_table (thd=0x555557e01130, one_table=0x7fffce192c10, backup=0x7fffce1929a0) at /root/mysql-server/sql/sql_base.cc:9584 #3 0x0000555555aa26ec in Log_to_csv_event_handler::log_slow (this=0x5555575d2ea0, thd=0x555557e01130, current_time=1576772288, query_start_arg=1576772259, user_host=0x7fffce193230 "root[root] @ localhost []", user_host_len=25, query_utime=29070411, lock_utime=0, is_command=false, sql_text=0x7fffa0005270 "select sleep(300)", sql_text_len=17) at /root/mysql-server/sql/log.cc:582 #4 0x0000555555aa3e36 in LOGGER::slow_log_print (this=0x555556bc45e0 <logger>, thd=0x555557e01130, query=0x7fffa0005270 "select sleep(300)", query_length=17) at /root/mysql-server/sql/log.cc:1091 #5 0x0000555555aa717b in slow_log_print (thd=0x555557e01130, query=0x7fffa0005270 "select sleep(300)", query_length=17) at /root/mysql-server/sql/log.cc:2163 #6 0x0000555555b76bc2 in log_slow_do (thd=0x555557e01130) at /root/mysql-server/sql/sql_parse.cc:1943 #7 0x0000555555b76c45 in log_slow_statement (thd=0x555557e01130) at /root/mysql-server/sql/sql_parse.cc:1967 #8 0x0000555555b76729 in dispatch_command (command=COM_QUERY, thd=0x555557e01130, packet=0x555557e8b021 "", packet_length=17) at /root/mysql-server/sql/sql_parse.cc:1835 #9 0x0000555555b74138 in do_command (thd=0x555557e01130) at /root/mysql-server/sql/sql_parse.cc:1064 #10 0x0000555555b398c6 in do_handle_one_connection (thd_arg=0x555557e01130) at /root/mysql-server/sql/sql_connect.cc:982 #11 0x0000555555b39614 in handle_one_connection (arg=0x555557e01130) at /root/mysql-server/sql/sql_connect.cc:899 #12 0x00005555561ee149 in pfs_spawn_thread (arg=0x555557e04ba0) at /root/mysql-server/storage/perfschema/pfs.cc:1861 #13 0x00007ffff77816db in start_thread (arg=0x7fffce194700) at pthread_create.c:463 #14 0x00007ffff6b6b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 LOG_OUTPUT = TABLE and KILL QUERY command: ------------------------------------------ (gdb) n 2666 char *alias= table_list->alias; (gdb) n 2667 uint flags= ot_ctx->get_flags(); (gdb) n 2673 DBUG_ENTER("open_table"); (gdb) n 2681 DBUG_ASSERT(!table_list->table); (gdb) n 2684 if (check_stack_overrun(thd, STACK_MIN_SIZE_FOR_OPEN, (uchar *)&alias)) (gdb) n 2687 if (!(flags & MYSQL_OPEN_IGNORE_KILLED) && thd->killed) (gdb) n 2696 if (table_list->mdl_request.type >= MDL_SHARED_WRITE && (gdb) p flags $1 = 2075 (gdb) p flags & 0x4000 $2 = 0 (gdb) p thd->killed $3 = THD::NOT_KILLED (gdb) n 2697 thd->tx_read_only && (gdb) n 2696 if (table_list->mdl_request.type >= MDL_SHARED_WRITE && (gdb) n 2704 key_length= get_table_def_key(table_list, &key); (gdb) n 2713 if (thd->locked_tables_mode && (gdb) n 2830 if (! (flags & MYSQL_OPEN_HAS_MDL_LOCK)) (gdb) n 2854 if (table_list->mdl_request.type >= MDL_SHARED_WRITE && (gdb) bt #0 open_table (thd=0x555557e022e0, table_list=0x7fffce192c10, ot_ctx=0x7fffce1927f0) at /root/mysql-server/sql/sql_base.cc:2662 #1 0x0000555555b0b5b9 in open_ltable (thd=0x555557e022e0, table_list=0x7fffce192c10, lock_type=TL_WRITE_CONCURRENT_INSERT, lock_flags=2075) at /root/mysql-server/sql/sql_base.cc:5724 #2 0x0000555555b14c65 in open_log_table (thd=0x555557e022e0, one_table=0x7fffce192c10, backup=0x7fffce1929a0) at /root/mysql-server/sql/sql_base.cc:9584 #3 0x0000555555aa26ec in Log_to_csv_event_handler::log_slow (this=0x5555575c0fb0, thd=0x555557e022e0, current_time=1576773626, query_start_arg=1576773606, user_host=0x7fffce193230 "root[root] @ localhost []", user_host_len=25, query_utime=20479839, lock_utime=0, is_command=false, sql_text=0x7fffa0005270 "select sleep(300)", sql_text_len=17) at /root/mysql-server/sql/log.cc:582 #4 0x0000555555aa3e36 in LOGGER::slow_log_print (this=0x555556bc45e0 <logger>, thd=0x555557e022e0, query=0x7fffa0005270 "select sleep(300)", query_length=17) at /root/mysql-server/sql/log.cc:1091 #5 0x0000555555aa717b in slow_log_print (thd=0x555557e022e0, query=0x7fffa0005270 "select sleep(300)", query_length=17) at /root/mysql-server/sql/log.cc:2163 #6 0x0000555555b76bc2 in log_slow_do (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1943 #7 0x0000555555b76c45 in log_slow_statement (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1967 #8 0x0000555555b76729 in dispatch_command (command=COM_QUERY, thd=0x555557e022e0, packet=0x555557e9b181 "", packet_length=17) at /root/mysql-server/sql/sql_parse.cc:1835 #9 0x0000555555b74138 in do_command (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1064 #10 0x0000555555b398c6 in do_handle_one_connection (thd_arg=0x555557e022e0) at /root/mysql-server/sql/sql_connect.cc:982 #11 0x0000555555b39614 in handle_one_connection (arg=0x555557e022e0) at /root/mysql-server/sql/sql_connect.cc:899 #12 0x00005555561ee149 in pfs_spawn_thread (arg=0x5555575d4a80) at /root/mysql-server/storage/perfschema/pfs.cc:1861 #13 0x00007ffff77816db in start_thread (arg=0x7fffce194700) at pthread_create.c:463 #14 0x00007ffff6b6b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 FOR LOG_OUTPUT = FILE, THERE IS NO SUCH CONDITION. SO, ITS WRITING TO SLOW QUERY LOG IN ALL THE SCENARIOS ######################################################################################################### LOG_OUTPUT = FILE and KILL command: ----------------------------------- (gdb) bt #0 inline_mysql_file_write (src_file=0x5555563cbb28 "/root/mysql-server/mysys/mf_iocache.c", src_line=1792, file=14, buffer=0x555557654dd0 "# Time: 191219 16:33:26\n# User@Host: root[root] @ localhost [] Id: 1\n# Query_time: 44.445251 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0\nSET timestamp=1576773206;\nselect sleep(300);\n ", count=195, flags=20) at /root/mysql-server/include/mysql/psi/mysql_file.h:1133 #1 0x0000555555e4e61e in my_b_flush_io_cache (info=0x555556cc7390, need_append_buffer_lock=0) at /root/mysql-server/mysys/mf_iocache.c:1791 #2 0x0000555555aa6ef6 in MYSQL_QUERY_LOG::write (this=0x555556cc7040, thd=0x555557e022e0, current_time=1576773206, query_start_arg=1576773161, user_host=0x7fffce193230 "root[root] @ localhost []", user_host_len=25, query_utime=44445251, lock_utime=0, is_command=false, sql_text=0x7fffa0005270 "select sleep(300)", sql_text_len=17) at /root/mysql-server/sql/log.cc:2108 #3 0x0000555555aa333d in Log_to_file_event_handler::log_slow (this=0x555556cc6b70, thd=0x555557e022e0, current_time=1576773206, query_start_arg=1576773161, user_host=0x7fffce193230 "root[root] @ localhost []", user_host_len=25, query_utime=44445251, lock_utime=0, is_command=false, sql_text=0x7fffa0005270 "select sleep(300)", sql_text_len=17) at /root/mysql-server/sql/log.cc:789 #4 0x0000555555aa3e36 in LOGGER::slow_log_print (this=0x555556bc45e0 <logger>, thd=0x555557e022e0, query=0x7fffa0005270 "select sleep(300)", query_length=17) at /root/mysql-server/sql/log.cc:1091 #5 0x0000555555aa717b in slow_log_print (thd=0x555557e022e0, query=0x7fffa0005270 "select sleep(300)", query_length=17) at /root/mysql-server/sql/log.cc:2163 #6 0x0000555555b76bc2 in log_slow_do (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1943 #7 0x0000555555b76c45 in log_slow_statement (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1967 #8 0x0000555555b76729 in dispatch_command (command=COM_QUERY, thd=0x555557e022e0, packet=0x555557e8f501 "", packet_length=17) at /root/mysql-server/sql/sql_parse.cc:1835 #9 0x0000555555b74138 in do_command (thd=0x555557e022e0) at /root/mysql-server/sql/sql_parse.cc:1064 #10 0x0000555555b398c6 in do_handle_one_connection (thd_arg=0x555557e022e0) at /root/mysql-server/sql/sql_connect.cc:982 #11 0x0000555555b39614 in handle_one_connection (arg=0x555557e022e0) at /root/mysql-server/sql/sql_connect.cc:899 #12 0x00005555561ee149 in pfs_spawn_thread (arg=0x5555575d4a80) at /root/mysql-server/storage/perfschema/pfs.cc:1861 #13 0x00007ffff77816db in start_thread (arg=0x7fffce194700) at pthread_create.c:463 #14 0x00007ffff6b6b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Suggested fix: May be we can use a separate function which allows to open the slow_log table or make some changes to the existing condition to exclude slow_log table.