Description:
After the execution of a statement, PROCESSLIST_INFO is not getting updated in PERFORMANCE_SCHEMA.THREADS table.
How to repeat:
>= 5.6.46
=========
mysql> select @@performance_schema,@@version;
+----------------------+------------+
| @@performance_schema | @@version |
+----------------------+------------+
| 1 | 5.6.46-log |
+----------------------+------------+
1 row in set (0.01 sec)
Session 1:
----------
mysql> select now(),connection_id();
+---------------------+-----------------+
| now() | connection_id() |
+---------------------+-----------------+
| 2020-03-23 14:11:14 | 109 |
+---------------------+-----------------+
1 row in set (0.00 sec)
Opening Session keeping Session 1 open
Session 2:
----------
Reading from performance_schema.threads
mysql> select * from performance_schema.threads where PROCESSLIST_ID=109\G
*************************** 1. row ***************************
THREAD_ID: 128
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 109
PROCESSLIST_USER: root
PROCESSLIST_HOST: 172.31.41.31
PROCESSLIST_DB: NULL
PROCESSLIST_COMMAND: Sleep
PROCESSLIST_TIME: 18
PROCESSLIST_STATE: NULL
PROCESSLIST_INFO: select now(),connection_id()
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES
1 row in set (0.00 sec)
Reading from information_schema.processlist
mysql> select * from information_schema.processlist where id=109\G
*************************** 1. row ***************************
ID: 109
USER: root
HOST: 172.31.41.31:57020
DB: NULL
COMMAND: Sleep
TIME: 55
STATE:
INFO: NULL
1 row in set (0.01 sec)
<= 5.6.45:
==========
mysql> select @@version,@@performance_schema;
+------------+----------------------+
| @@version | @@performance_schema |
+------------+----------------------+
| 5.6.44-log | 1 |
+------------+----------------------+
1 row in set (0.00 sec)
Session 1:
---------
mysql> select now(),connection_id();
+---------------------+-----------------+
| now() | connection_id() |
+---------------------+-----------------+
| 2020-03-23 14:08:55 | 98 |
+---------------------+-----------------+
1 row in set (0.00 sec)
Opening Session keeping Session 1 open
Session 2:
----------
Reading from performance_schema.threads
mysql> select * from performance_schema.threads where PROCESSLIST_ID=98\G
*************************** 1. row ***************************
THREAD_ID: 117
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 98
PROCESSLIST_USER: root
PROCESSLIST_HOST: 172.31.41.31
PROCESSLIST_DB: NULL
PROCESSLIST_COMMAND: Sleep
PROCESSLIST_TIME: 74
PROCESSLIST_STATE: NULL
PROCESSLIST_INFO: NULL
PARENT_THREAD_ID: 1
ROLE: NULL
INSTRUMENTED: YES
1 row in set (0.00 sec)
Reading from information_schema.processlist
mysql> select * from information_schema.processlist where id=98\G
*************************** 1. row ***************************
ID: 98
USER: root
HOST: 172.31.41.31:40716
DB: NULL
COMMAND: Sleep
TIME: 110
STATE:
INFO: NULL
1 row in set (0.00 sec)
####################################################
MySQL <=5.6.45:
==============
Thread 26 "mysqld" hit Breakpoint 7, THD::set_query (this=0x5623f453b540, string_arg=...) at /root/mysql-server/sql/sql_class.cc:4674
4674 mysql_mutex_lock(&LOCK_thd_data);
(gdb) n
4675 set_query_inner(string_arg);
(gdb) n
4676 mysql_mutex_unlock(&LOCK_thd_data);
(gdb) n
4679 PSI_THREAD_CALL(set_thread_info)(query(), query_length());
(gdb) bt
#0 THD::set_query (this=0x5623f453b540, string_arg=...) at /root/mysql-server/sql/sql_class.cc:4679
#1 0x00005623f097f7d6 in THD::reset_query (this=0x5623f453b540) at /root/mysql-server/sql/sql_class.h:4042
#2 0x00005623f096e767 in dispatch_command (command=COM_QUERY, thd=0x5623f453b540, packet=0x5623f453ed81 "", packet_length=12)
at /root/mysql-server/sql/sql_parse.cc:1839
#3 0x00005623f096c138 in do_command (thd=0x5623f453b540) at /root/mysql-server/sql/sql_parse.cc:1064
#4 0x00005623f09318c6 in do_handle_one_connection (thd_arg=0x5623f453b540) at /root/mysql-server/sql/sql_connect.cc:982
#5 0x00005623f0931614 in handle_one_connection (arg=0x5623f453b540) at /root/mysql-server/sql/sql_connect.cc:899
#6 0x00005623f0fe6149 in pfs_spawn_thread (arg=0x5623f410dfe0) at /root/mysql-server/storage/perfschema/pfs.cc:1861
#7 0x00007f5a22f0c6db in start_thread (arg=0x7f59f9825700) at pthread_create.c:463
#8 0x00007f5a222f688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
https://github.com/mysql/mysql-server/blob/mysql-5.6.44/sql/sql_class.cc
Function:
========
void reset_query() /* Mutex protected */
{ set_query(CSET_STRING()); }
void THD::set_query(const CSET_STRING &string_arg)
{
mysql_mutex_lock(&LOCK_thd_data);
set_query_inner(string_arg);
mysql_mutex_unlock(&LOCK_thd_data);
#ifdef HAVE_PSI_THREAD_INTERFACE
PSI_THREAD_CALL(set_thread_info)(query(), query_length());
#endif
}
MySQL >= 5.6.46
################
Thread 22 "mysqld" hit Breakpoint 11, mysql_execute_command (thd=0x559bd73d30e0) at /root/mysql-server/sql/sql_parse.cc:2355
2355 {
..
..
..
5039 goto finish;
(gdb) n
5046 DBUG_ASSERT(!thd->in_active_multi_stmt_transaction() ||
(gdb) n
5049 if (! thd->in_sub_stmt)
(gdb) p thd->in_sub_stmt
$12 = 0
(gdb) n
5052 if (thd->killed_errno())
(gdb) n
5054 if (thd->killed == THD::KILL_QUERY || thd->killed == THD::KILL_BAD_DATA)
(gdb) p thd->killed
$13 = THD::NOT_KILLED
(gdb) bt
#0 mysql_execute_command (thd=0x559bd73d30e0) at /root/mysql-server/sql/sql_parse.cc:5054
#1 0x0000559bd4ab59e5 in mysql_parse (thd=0x559bd73d30e0, rawbuf=0x7f6154005300 "select now()", length=12, parser_state=0x7f618311c6a0)
at /root/mysql-server/sql/sql_parse.cc:6435
#2 0x0000559bd4aa8574 in dispatch_command (command=COM_QUERY, thd=0x559bd73d30e0, packet=0x559bd750fcc1 "", packet_length=12)
at /root/mysql-server/sql/sql_parse.cc:1406
#3 0x0000559bd4aa75a8 in do_command (thd=0x559bd73d30e0) at /root/mysql-server/sql/sql_parse.cc:1071
#4 0x0000559bd4a6cdb5 in do_handle_one_connection (thd_arg=0x559bd73d30e0) at /root/mysql-server/sql/sql_connect.cc:989
#5 0x0000559bd4a6cb30 in handle_one_connection (arg=0x559bd73d30e0) at /root/mysql-server/sql/sql_connect.cc:906
#6 0x0000559bd5120983 in pfs_spawn_thread (arg=0x559bd746cce0) at /root/mysql-server/storage/perfschema/pfs.cc:1868
#7 0x00007f61ac70a6db in start_thread (arg=0x7f618311d700) at pthread_create.c:463
#8 0x00007f61abaf488f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Code: https://github.com/mysql/mysql-server/blob/mysql-5.6.46/sql/sql_parse.cc
Function: mysql_execute_command
#############################################################
DBUG_ASSERT(!thd->in_active_multi_stmt_transaction() ||
thd->in_multi_stmt_transaction_mode());
if (! thd->in_sub_stmt)
{
/* report error issued during command execution */
if (thd->killed_errno())
thd->send_kill_message();
if (thd->killed == THD::KILL_QUERY || thd->killed == THD::KILL_BAD_DATA)
{
thd->killed= THD::NOT_KILLED;
thd->mysys_var->abort= 0;
thd->reset_query_for_display();
}
if (thd->is_error() || (thd->variables.option_bits & OPTION_MASTER_SQL_ERROR))
trans_rollback_stmt(thd);
else
{
/* If commit fails, we should be able to reset the OK status. */
thd->get_stmt_da()->set_overwrite_status(true);
trans_commit_stmt(thd);
thd->get_stmt_da()->set_overwrite_status(false);
}
}
Code: https://github.com/mysql/mysql-server/blob/mysql-5.6.46/sql/sql_class.h
void set_query_for_display(const char *query_arg, size_t query_length_arg) {
MYSQL_SET_STATEMENT_TEXT(m_statement_psi, query_arg, query_length_arg);
#ifdef HAVE_PSI_THREAD_INTERFACE
PSI_THREAD_CALL(set_thread_info)(query_arg, query_length_arg);
#endif
}
void reset_query_for_display(void) { set_query_for_display(NULL, 0); }
##############################################################
Looks like in >=5.6.46 versions, MySQL started using set_query_for_display and reset_query_for_display functions. However, in this case, it looks like reset_query_for_display is not being called after execution of the query.
As per MySQL doc https://dev.mysql.com/doc/mysql-perfschema-excerpt/5.6/en/threads-table.html,
PROCESSLIST_INFO
The statement the thread is executing, or NULL if it is not executing any statement. The statement might be the one sent to the server, or an innermost statement if the statement executes other statements. For example, if a CALL statement executes a stored procedure that is executing a SELECT statement, the PROCESSLIST_INFO value shows the SELECT statement.
In this case, MySQL is showing the last executed statement in PROCESSLIST_INFO even after the completion of statement execution which is violating the above statement.
Suggested fix:
This regression has been caused due to changes made in commit https://github.com/mysql/mysql-server/commit/4012ca94f66aa4a4c963b1f58b349f28f7ba4c23
May be reset_query_for_display function can be called after completion of statement execution to fix this issue.
Description: After the execution of a statement, PROCESSLIST_INFO is not getting updated in PERFORMANCE_SCHEMA.THREADS table. How to repeat: >= 5.6.46 ========= mysql> select @@performance_schema,@@version; +----------------------+------------+ | @@performance_schema | @@version | +----------------------+------------+ | 1 | 5.6.46-log | +----------------------+------------+ 1 row in set (0.01 sec) Session 1: ---------- mysql> select now(),connection_id(); +---------------------+-----------------+ | now() | connection_id() | +---------------------+-----------------+ | 2020-03-23 14:11:14 | 109 | +---------------------+-----------------+ 1 row in set (0.00 sec) Opening Session keeping Session 1 open Session 2: ---------- Reading from performance_schema.threads mysql> select * from performance_schema.threads where PROCESSLIST_ID=109\G *************************** 1. row *************************** THREAD_ID: 128 NAME: thread/sql/one_connection TYPE: FOREGROUND PROCESSLIST_ID: 109 PROCESSLIST_USER: root PROCESSLIST_HOST: 172.31.41.31 PROCESSLIST_DB: NULL PROCESSLIST_COMMAND: Sleep PROCESSLIST_TIME: 18 PROCESSLIST_STATE: NULL PROCESSLIST_INFO: select now(),connection_id() PARENT_THREAD_ID: NULL ROLE: NULL INSTRUMENTED: YES 1 row in set (0.00 sec) Reading from information_schema.processlist mysql> select * from information_schema.processlist where id=109\G *************************** 1. row *************************** ID: 109 USER: root HOST: 172.31.41.31:57020 DB: NULL COMMAND: Sleep TIME: 55 STATE: INFO: NULL 1 row in set (0.01 sec) <= 5.6.45: ========== mysql> select @@version,@@performance_schema; +------------+----------------------+ | @@version | @@performance_schema | +------------+----------------------+ | 5.6.44-log | 1 | +------------+----------------------+ 1 row in set (0.00 sec) Session 1: --------- mysql> select now(),connection_id(); +---------------------+-----------------+ | now() | connection_id() | +---------------------+-----------------+ | 2020-03-23 14:08:55 | 98 | +---------------------+-----------------+ 1 row in set (0.00 sec) Opening Session keeping Session 1 open Session 2: ---------- Reading from performance_schema.threads mysql> select * from performance_schema.threads where PROCESSLIST_ID=98\G *************************** 1. row *************************** THREAD_ID: 117 NAME: thread/sql/one_connection TYPE: FOREGROUND PROCESSLIST_ID: 98 PROCESSLIST_USER: root PROCESSLIST_HOST: 172.31.41.31 PROCESSLIST_DB: NULL PROCESSLIST_COMMAND: Sleep PROCESSLIST_TIME: 74 PROCESSLIST_STATE: NULL PROCESSLIST_INFO: NULL PARENT_THREAD_ID: 1 ROLE: NULL INSTRUMENTED: YES 1 row in set (0.00 sec) Reading from information_schema.processlist mysql> select * from information_schema.processlist where id=98\G *************************** 1. row *************************** ID: 98 USER: root HOST: 172.31.41.31:40716 DB: NULL COMMAND: Sleep TIME: 110 STATE: INFO: NULL 1 row in set (0.00 sec) #################################################### MySQL <=5.6.45: ============== Thread 26 "mysqld" hit Breakpoint 7, THD::set_query (this=0x5623f453b540, string_arg=...) at /root/mysql-server/sql/sql_class.cc:4674 4674 mysql_mutex_lock(&LOCK_thd_data); (gdb) n 4675 set_query_inner(string_arg); (gdb) n 4676 mysql_mutex_unlock(&LOCK_thd_data); (gdb) n 4679 PSI_THREAD_CALL(set_thread_info)(query(), query_length()); (gdb) bt #0 THD::set_query (this=0x5623f453b540, string_arg=...) at /root/mysql-server/sql/sql_class.cc:4679 #1 0x00005623f097f7d6 in THD::reset_query (this=0x5623f453b540) at /root/mysql-server/sql/sql_class.h:4042 #2 0x00005623f096e767 in dispatch_command (command=COM_QUERY, thd=0x5623f453b540, packet=0x5623f453ed81 "", packet_length=12) at /root/mysql-server/sql/sql_parse.cc:1839 #3 0x00005623f096c138 in do_command (thd=0x5623f453b540) at /root/mysql-server/sql/sql_parse.cc:1064 #4 0x00005623f09318c6 in do_handle_one_connection (thd_arg=0x5623f453b540) at /root/mysql-server/sql/sql_connect.cc:982 #5 0x00005623f0931614 in handle_one_connection (arg=0x5623f453b540) at /root/mysql-server/sql/sql_connect.cc:899 #6 0x00005623f0fe6149 in pfs_spawn_thread (arg=0x5623f410dfe0) at /root/mysql-server/storage/perfschema/pfs.cc:1861 #7 0x00007f5a22f0c6db in start_thread (arg=0x7f59f9825700) at pthread_create.c:463 #8 0x00007f5a222f688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 https://github.com/mysql/mysql-server/blob/mysql-5.6.44/sql/sql_class.cc Function: ======== void reset_query() /* Mutex protected */ { set_query(CSET_STRING()); } void THD::set_query(const CSET_STRING &string_arg) { mysql_mutex_lock(&LOCK_thd_data); set_query_inner(string_arg); mysql_mutex_unlock(&LOCK_thd_data); #ifdef HAVE_PSI_THREAD_INTERFACE PSI_THREAD_CALL(set_thread_info)(query(), query_length()); #endif } MySQL >= 5.6.46 ################ Thread 22 "mysqld" hit Breakpoint 11, mysql_execute_command (thd=0x559bd73d30e0) at /root/mysql-server/sql/sql_parse.cc:2355 2355 { .. .. .. 5039 goto finish; (gdb) n 5046 DBUG_ASSERT(!thd->in_active_multi_stmt_transaction() || (gdb) n 5049 if (! thd->in_sub_stmt) (gdb) p thd->in_sub_stmt $12 = 0 (gdb) n 5052 if (thd->killed_errno()) (gdb) n 5054 if (thd->killed == THD::KILL_QUERY || thd->killed == THD::KILL_BAD_DATA) (gdb) p thd->killed $13 = THD::NOT_KILLED (gdb) bt #0 mysql_execute_command (thd=0x559bd73d30e0) at /root/mysql-server/sql/sql_parse.cc:5054 #1 0x0000559bd4ab59e5 in mysql_parse (thd=0x559bd73d30e0, rawbuf=0x7f6154005300 "select now()", length=12, parser_state=0x7f618311c6a0) at /root/mysql-server/sql/sql_parse.cc:6435 #2 0x0000559bd4aa8574 in dispatch_command (command=COM_QUERY, thd=0x559bd73d30e0, packet=0x559bd750fcc1 "", packet_length=12) at /root/mysql-server/sql/sql_parse.cc:1406 #3 0x0000559bd4aa75a8 in do_command (thd=0x559bd73d30e0) at /root/mysql-server/sql/sql_parse.cc:1071 #4 0x0000559bd4a6cdb5 in do_handle_one_connection (thd_arg=0x559bd73d30e0) at /root/mysql-server/sql/sql_connect.cc:989 #5 0x0000559bd4a6cb30 in handle_one_connection (arg=0x559bd73d30e0) at /root/mysql-server/sql/sql_connect.cc:906 #6 0x0000559bd5120983 in pfs_spawn_thread (arg=0x559bd746cce0) at /root/mysql-server/storage/perfschema/pfs.cc:1868 #7 0x00007f61ac70a6db in start_thread (arg=0x7f618311d700) at pthread_create.c:463 #8 0x00007f61abaf488f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Code: https://github.com/mysql/mysql-server/blob/mysql-5.6.46/sql/sql_parse.cc Function: mysql_execute_command ############################################################# DBUG_ASSERT(!thd->in_active_multi_stmt_transaction() || thd->in_multi_stmt_transaction_mode()); if (! thd->in_sub_stmt) { /* report error issued during command execution */ if (thd->killed_errno()) thd->send_kill_message(); if (thd->killed == THD::KILL_QUERY || thd->killed == THD::KILL_BAD_DATA) { thd->killed= THD::NOT_KILLED; thd->mysys_var->abort= 0; thd->reset_query_for_display(); } if (thd->is_error() || (thd->variables.option_bits & OPTION_MASTER_SQL_ERROR)) trans_rollback_stmt(thd); else { /* If commit fails, we should be able to reset the OK status. */ thd->get_stmt_da()->set_overwrite_status(true); trans_commit_stmt(thd); thd->get_stmt_da()->set_overwrite_status(false); } } Code: https://github.com/mysql/mysql-server/blob/mysql-5.6.46/sql/sql_class.h void set_query_for_display(const char *query_arg, size_t query_length_arg) { MYSQL_SET_STATEMENT_TEXT(m_statement_psi, query_arg, query_length_arg); #ifdef HAVE_PSI_THREAD_INTERFACE PSI_THREAD_CALL(set_thread_info)(query_arg, query_length_arg); #endif } void reset_query_for_display(void) { set_query_for_display(NULL, 0); } ############################################################## Looks like in >=5.6.46 versions, MySQL started using set_query_for_display and reset_query_for_display functions. However, in this case, it looks like reset_query_for_display is not being called after execution of the query. As per MySQL doc https://dev.mysql.com/doc/mysql-perfschema-excerpt/5.6/en/threads-table.html, PROCESSLIST_INFO The statement the thread is executing, or NULL if it is not executing any statement. The statement might be the one sent to the server, or an innermost statement if the statement executes other statements. For example, if a CALL statement executes a stored procedure that is executing a SELECT statement, the PROCESSLIST_INFO value shows the SELECT statement. In this case, MySQL is showing the last executed statement in PROCESSLIST_INFO even after the completion of statement execution which is violating the above statement. Suggested fix: This regression has been caused due to changes made in commit https://github.com/mysql/mysql-server/commit/4012ca94f66aa4a4c963b1f58b349f28f7ba4c23 May be reset_query_for_display function can be called after completion of statement execution to fix this issue.