Bug #98046 Inconsistent behavior while logging a killed query in the slow query log
Submitted: 21 Dec 2019 8:14 Modified: 23 Dec 2019 6:39
Reporter: Pranay Motupalli Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:All OS:Linux
Assigned to: CPU Architecture:Any
Tags: slow query log

[21 Dec 2019 8:14] Pranay Motupalli
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.
[23 Dec 2019 6:39] Bogdan Kecman
Thanks for the report, verified as described.