Bug #104121 PSI_THREAD_INFO not updated while executing PREPARED STATEMENTS.
Submitted: 26 Jun 15:19 Modified: 17 Aug 17:29
Reporter: Pranay Motupalli Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:>=5.7.28 , >=8.0.18, 8.0.25, 5.7.34 OS:Any
Assigned to: CPU Architecture:Any

[26 Jun 15:19] Pranay Motupalli
Description:
PSI_THREAD_INFO doesn't' get updated while executing a PREPARED STATEMENT. This is a regression caused due to commit https://github.com/mysql/mysql-server/commit/afcaac4d6f8aecc70c418138f1d8dd4e4965e629

How to repeat:
Used tpcc-mysql tool to generate load. Source: https:/github.com/Percona-Lab/tpcc-mysql

Create MySQL server with version 5.7.28/8.0.18 or above.

cd tpcc-mysql
mysql -uroot -pxxxxx -h x.x.x.x -e "CREATE DATABASE tpcc10;"
mysql -uroot -pxxxxxx -h x.x.x.x tpcc10 < create_table.sql
mysql -uroot -pxxxxxx -h x.x.x.x tpcc10 < add_fkey_idx.sql
./tpcc_load -h xxxxx -uroot -pxxxxxxx -w 1 -d tpcc10
./tpcc_start -h xxxxx -uroot -pxxxxxxx -w 1 -d tpcc10 -c10 -r1 -l1200 &

When load is running, run the following query:

mysql> select a.processlist_info,b.info from performance_schema.threads a , information_schema.processlist b where a.processlist_id=b.id\G
*************************** 1. row ***************************
processlist_info: SELECT 1
            info: NULL
*************************** 2. row ***************************
processlist_info: select a.processlist_info,b.info from performance_schema.threads a , information_schema.processlist b where a.processlist_id=b.id
            info: select a.processlist_info,b.info from performance_schema.threads a , information_schema.processlist b where a.processlist_id=b.id
*************************** 3. row ***************************
processlist_info: commit
            info: NULL
*************************** 4. row ***************************
processlist_info: commit
            info: NULL
*************************** 5. row ***************************
processlist_info: commit
            info: SELECT i_price, i_name, i_data FROM item WHERE i_id = ?
*************************** 6. row ***************************
processlist_info: commit
            info: UPDATE warehouse SET w_ytd = w_ytd + 3584 WHERE w_id = 1
*************************** 7. row ***************************
processlist_info: commit
            info: commit
*************************** 8. row ***************************
processlist_info: commit
            info: SELECT d_next_o_id, d_tax FROM district WHERE d_id = ? AND d_w_id = ? FOR UPDATE
*************************** 9. row ***************************
processlist_info: commit
            info: UPDATE warehouse SET w_ytd = w_ytd + 4889 WHERE w_id = 1
*************************** 10. row ***************************
processlist_info: commit
            info: NULL
*************************** 11. row ***************************
processlist_info: commit
            info: NULL
*************************** 12. row ***************************
processlist_info: commit
            info: UPDATE warehouse SET w_ytd = w_ytd + 4366 WHERE w_id = 1
12 rows in set (0.00 sec)

As you can see, PROCESSLIST_INFO and PSI_THREAD_INFO is not matching for all the queries except the current executed query. The non matching ones are prepared statements. It works for normal query as we call set_query_for_display in mysql_parse function.

The reason why we are seeing commit in PROCESSLIST_INFO is that 'commit' here is the previously executed statement on the same thread. This is also a bug which I reported before https://bugs.mysql.com/bug.php?id=99039

#####################################

Analysis:
########

5.7.26:
#######

void THD::set_query(const LEX_CSTRING& query_arg)
{
  DBUG_ASSERT(this == current_thd);
  mysql_mutex_lock(&LOCK_thd_query);
  m_query_string= query_arg;
  mysql_mutex_unlock(&LOCK_thd_query);

#ifdef HAVE_PSI_THREAD_INTERFACE
  PSI_THREAD_CALL(set_thread_info)(query_arg.str, query_arg.length);    ----------------> This one was removed and placed in set_query_for_display() function in sql_class.h. In versions >= 5.7.28/8.0.18, this function is not being called.
#endif
}

void set_thd_to_ps(THD *thd, Prepared_statement *stmt)
{
  DBUG_ENTER("Statement_backup::set_thd_to_ps");

  mysql_mutex_lock(&thd->LOCK_thd_data);
  m_lex=    thd->lex;
  thd->lex= stmt->lex;
  mysql_mutex_unlock(&thd->LOCK_thd_data);

  m_query_string= thd->query();
  thd->set_query(stmt->m_query_string);     ---------> set_query is being called in all versions.

  DBUG_VOID_RETURN;
}

Stack Trace:
-----------

Breakpoint 1, THD::set_query (this=this@entry=0x2b5241c7a000, query_arg=...) at /sql/sql_class.cc:4357
4357	/sql/sql_class.cc: No such file or directory.
(gdb) bt
#0  THD::set_query (this=this@entry=0x2b5241c7a000, query_arg=...) at /sql/sql_class.cc:4357
#1  0x0000000000d26e31 in set_thd_to_ps (stmt=0x2b5241d91180, thd=0x2b5241c7a000, this=<synthetic pointer>) at /sql/sql_prepare.cc:299
#2  Prepared_statement::execute (this=this@entry=0x2b5241d91180, expanded_query=expanded_query@entry=0x2b4f245ef490, open_cursor=open_cursor@entry=false)
    at /sql/sql_prepare.cc:3878
#3  0x0000000000d29fc3 in Prepared_statement::execute_loop (this=0x2b5241d91180, expanded_query=0x2b4f245ef490, open_cursor=<optimized out>, packet=<optimized out>, packet_end=<optimized out>)
    at /sql/sql_prepare.cc:3585
#4  0x0000000000d2a2eb in mysqld_stmt_execute (thd=thd@entry=0x2b5241c7a000, stmt_id=<optimized out>, flags=0, params=0x2b5241cf98ea "", params_length=20)
    at /sql/sql_prepare.cc:2573
#5  0x0000000000cffee6 in dispatch_command (thd=thd@entry=0x2b5241c7a000, com_data=com_data@entry=0x2b4f245efd10, command=COM_STMT_EXECUTE)
    at /sql/sql_parse.cc:1421
#6  0x0000000000d00e13 in do_command (thd=thd@entry=0x2b5241c7a000) at /sql/sql_parse.cc:1028
#7  0x0000000000dbfc18 in handle_connection (arg=arg@entry=0x2b50af5ffa40) at /sql/conn_handler/connection_handler_per_thread.cc:306
#8  0x00000000012ead59 in pfs_spawn_thread (arg=0x2b521d3a8460) at /storage/perfschema/pfs.cc:2190
#9  0x00002b4f23c92dc5 in start_thread () from /lib64/libpthread.so.0
#10 0x00002b4f23f9dc9d in clone () from /lib64/libc.so.6
(gdb) p query_arg
$1 = (const LEX_CSTRING &) @0x2b5241d913d0: {str = 0x2b5245a90a50 "SELECT count(*) FROM stock WHERE s_w_id = ? AND s_i_id = ? AND s_quantity < ?", length = 77}

5.7.28:
#######

void THD::set_query(const LEX_CSTRING& query_arg)
{
  DBUG_ASSERT(this == current_thd);
  mysql_mutex_lock(&LOCK_thd_query);
  m_query_string= query_arg;
  mysql_mutex_unlock(&LOCK_thd_query);
}

Update function for PSI_THREAD_INFO was moved to set_query_for_display and mysql doesn't call it.

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
  }

Stack Trace: 
-----------

It never touched the set_query_for_display function here but touches set_query as expected but doesn't set PSI_THREAD_INFO.

Breakpoint 9, THD::set_query (this=this@entry=0x2b9e9f21d000, query_arg=...) at /sql/sql_class.cc:4364
4364	/sql/sql_class.cc: No such file or directory.
(gdb) bt
#0  THD::set_query (this=this@entry=0x2b9e9f21d000, query_arg=...) at /sql/sql_class.cc:4364
#1  0x0000000000d26ef1 in set_thd_to_ps (stmt=0x2b9e9f2e2f80, thd=0x2b9e9f21d000, this=<synthetic pointer>) at /sql/sql_prepare.cc:306
#2  Prepared_statement::execute (this=this@entry=0x2b9e9f2e2f80, expanded_query=expanded_query@entry=0x2b9b85585490, open_cursor=open_cursor@entry=false)
    at /sql/sql_prepare.cc:3886
#3  0x0000000000d2a0a3 in Prepared_statement::execute_loop (this=0x2b9e9f2e2f80, expanded_query=0x2b9b85585490, open_cursor=<optimized out>, packet=<optimized out>, packet_end=<optimized out>)
    at /sql/sql_prepare.cc:3593
#4  0x0000000000d2a3cb in mysqld_stmt_execute (thd=thd@entry=0x2b9e9f21d000, stmt_id=<optimized out>, flags=0, params=0x2b9e9f27f6ea "", params_length=14)
    at /sql/sql_prepare.cc:2581
#5  0x0000000000cfffe5 in dispatch_command (thd=thd@entry=0x2b9e9f21d000, com_data=com_data@entry=0x2b9b85585d10, command=COM_STMT_EXECUTE)
    at /sql/sql_parse.cc:1428
#6  0x0000000000d00ea3 in do_command (thd=thd@entry=0x2b9e9f21d000) at /sql/sql_parse.cc:1035
#7  0x0000000000dc01a8 in handle_connection (arg=arg@entry=0x2b9cf6bfc0a0) at /sql/conn_handler/connection_handler_per_thread.cc:313
#8  0x00000000012eb849 in pfs_spawn_thread (arg=0x2b9e7e3a9260) at /storage/perfschema/pfs.cc:2197
#9  0x00002b9b84c28dc5 in start_thread () from /lib64/libpthread.so.0
#10 0x00002b9b84f33c9d in clone () from /lib64/libc.so.6

NON-PREPARED STATEMENT:
----------------------
(gdb) bt
#0  pfs_set_thread_info_v1 (info=info@entry=0x2b9ea5d4f030 "commit", info_len=info_len@entry=6) at /storage/perfschema/pfs.cc:2527
#1  0x0000000000cfe7f3 in set_query_for_display (query_length_arg=<optimized out>, query_arg=<optimized out>, this=0x2b9ea5d1a000) at /sql/sql_class.h:4398
#2  mysql_parse (thd=thd@entry=0x2b9ea5d1a000, parser_state=parser_state@entry=0x2b9b8f7036b0) at /sql/sql_parse.cc:5667
#3  0x0000000000cff302 in dispatch_command (thd=thd@entry=0x2b9ea5d1a000, com_data=com_data@entry=0x2b9b8f703d10, command=COM_QUERY)
    at /sql/sql_parse.cc:1497
#4  0x0000000000d00ea3 in do_command (thd=thd@entry=0x2b9ea5d1a000) at /sql/sql_parse.cc:1035
#5  0x0000000000dc01a8 in handle_connection (arg=arg@entry=0x2b9cf6bfcdc0) at /sql/conn_handler/connection_handler_per_thread.cc:313
#6  0x00000000012eb849 in pfs_spawn_thread (arg=0x2b9e7e3a8ee0) at /storage/perfschema/pfs.cc:2197
#7  0x00002b9b84c28dc5 in start_thread () from /lib64/libpth

Suggested fix:
Root Cause:
----------
Regression due to commit https://github.com/mysql/mysql-server/commit/afcaac4d6f8aecc70c418138f1d8dd4e4965e629

Proposed Solution:
------------------
Call set_query_for_display in THD::set_query function.
[28 Jun 14:46] Pranay Motupalli
root@ip-172-31-50-102:~/mysql-server# git diff @{upstream}
diff --git a/sql/sql_class.cc b/sql/sql_class.cc
index b8f43573b21..5c0dc2ffb01 100644
--- a/sql/sql_class.cc
+++ b/sql/sql_class.cc
@@ -4369,6 +4369,7 @@ void THD::set_query(const LEX_CSTRING& query_arg)
   mysql_mutex_lock(&LOCK_thd_query);
   m_query_string= query_arg;
   mysql_mutex_unlock(&LOCK_thd_query);
+  current_thd->set_query_for_display(query_arg.str, query_arg.length);
 }
[29 Jun 5:30] MySQL Verification Team
Hello Pranay,

Thank you for the report and feedback.
Verified as described.

regards,
Umesh
[29 Jun 6:21] MySQL Verification Team
MySQL Server 8.0.25, 5.7.34 test results

Attachment: 104121.results (application/octet-stream, text), 16.37 KiB.

[29 Jun 6:27] MySQL Verification Team
Hi Pranay,

Please note that in order to submit contributions you must first sign the Oracle Contribution Agreement (OCA). More details are described in "Contributions" tab. Also, once you sign OCA ensure to re-send the patch via "Contributions" tab.
Otherwise we would not be able to accept it.

regards,
Umesh
[30 Jun 1:04] Pranay Motupalli
I hereby submit the above one-lined under public domain for anybody to use freely. I will not sign the OCA.
[17 Aug 17:29] Pranay Motupalli
Hi Team,

Can you please provide the status of this bug fix.

Thanks