MySQL Bugs: #114480: P_S doesn't record SQL or digest for prepared statements for Non-mysql client

Bug #114480	P_S doesn't record SQL or digest for prepared statements for Non-mysql client
Submitted:	26 Mar 2024 7:36	Modified:	26 Mar 2024 12:57
Reporter:	Aristotle Po	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Performance Schema	Severity:	S3 (Non-critical)
Version:	8.0	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	P_S doesn't record SQL or digest for prepared statements for Non-mysql client ap

Description:
P_S doesn't record SQL or digest for prepared statements for Non-mysql client apps
Related to old 5.6 Bug 69218 

Server version:   8.0.36 MySQL Community Server - GPL

mysql [localhost:8036] {root} ((none)) > SELECT * FROM performance_schema.setup_instruments WHERE NAME IN ('statement/com/Prepare', 'statement/com/Execute', 'statement/sql/prepare_sql', 'statement/sql/execute_sql');
+---------------------------+---------+-------+------------+-------+------------+---------------+
| NAME                      | ENABLED | TIMED | PROPERTIES | FLAGS | VOLATILITY | DOCUMENTATION |
+---------------------------+---------+-------+------------+-------+------------+---------------+
| statement/com/Execute     | YES     | YES   |            | NULL  |          0 | NULL          |
| statement/com/Prepare     | YES     | YES   |            | NULL  |          0 | NULL          |
| statement/sql/execute_sql | YES     | YES   |            | NULL  |          0 | NULL          |
| statement/sql/prepare_sql | YES     | YES   |            | NULL  |          0 | NULL          |
+---------------------------+---------+-------+------------+-------+------------+---------------+
4 rows in set (0.00 sec)

######################################################################
# Below we see that SQL_TEXT are NULL for non-mysql client applications 
######################################################################

mysql [localhost:8036] {root} ((none)) > SELECT THREAD_ID, EVENT_NAME, SQL_TEXT, COUNT(*) FROM performance_schema.events_statements_history_long  GROUP BY THREAD_ID, EVENT_NAME, SQL_TEXT;
+-----------+---------------------------+--------------------------+----------+
| THREAD_ID | EVENT_NAME                | SQL_TEXT                 | COUNT(*) |
+-----------+---------------------------+--------------------------+----------+
|        63 | statement/sql/prepare_sql | PREPARE stmt1 FROM ...   |        1 |
|        63 | statement/sql/execute_sql | EXECUTE stmt1            |        1 |
|        63 | statement/sql/dealloc_sql | DEALLOCATE PREPARE stmt1 |        1 |
|        63 | statement/sql/prepare_sql | PREPARE stmt2 FROM ...   |        1 |
|        63 | statement/sql/execute_sql | EXECUTE stmt2            |        1 |
|        64 | statement/com/Prepare     | NULL                     |        6 |
|        64 | statement/sql/begin       | BEGIN                    |      342 |
|        64 | statement/com/Execute     | NULL                     |     1710 |
|        64 | statement/com/Close stmt  | NULL                     |        5 |
|        64 | statement/com/Quit        | NULL                     |        1 |
+-----------+---------------------------+--------------------------+----------+
10 rows in set (0.00 sec)

mysql [localhost:8036] {root} ((none)) > SELECT THREAD_ID, EVENT_ID, SQL_TEXT, DIGEST_TEXT, EVENT_NAME, MYSQL_ERRNO FROM performance_schema.events_statements_history_long LIMIT 9;
+-----------+----------+--------------------------+----------------------------+---------------------------+-------------+
| THREAD_ID | EVENT_ID | SQL_TEXT                 | DIGEST_TEXT                | EVENT_NAME                | MYSQL_ERRNO |
+-----------+----------+--------------------------+----------------------------+---------------------------+-------------+
|        63 |        3 | PREPARE stmt1 FROM ...   | PREPARE `stmt1` FROM ?     | statement/sql/prepare_sql |           0 |
|        63 |        4 | EXECUTE stmt1            | EXECUTE `stmt1`            | statement/sql/execute_sql |           0 |
|        63 |        6 | DEALLOCATE PREPARE stmt1 | DEALLOCATE PREPARE `stmt1` | statement/sql/dealloc_sql |           0 |
|        63 |        7 | PREPARE stmt2 FROM ...   | PREPARE `stmt2` FROM ?     | statement/sql/prepare_sql |           0 |
|        63 |        8 | EXECUTE stmt2            | EXECUTE `stmt2`            | statement/sql/execute_sql |           0 |
|        64 |        1 | NULL                     | NULL                       | statement/com/Prepare     |        1295 |
|        64 |        2 | NULL                     | NULL                       | statement/com/Prepare     |           0 |
|        64 |        3 | NULL                     | NULL                       | statement/com/Prepare     |           0 |
|        64 |        4 | NULL                     | NULL                       | statement/com/Prepare     |           0 |
+-----------+----------+--------------------------+----------------------------+---------------------------+-------------+
9 rows in set (0.00 sec)

How to repeat:
###################
# Create test table
###################
CREATE TABLE test.t1(i INT);

###################
# Prepare sysbench table
###################
sysbench oltp_write_only --threads=1 --time=1 --tables=1 --table-size=10 --db-driver=mysql --mysql-db=test --mysql-user=msandbox --mysql-password=msandbox --mysql-storage-engine=InnoDB --report-interval=5 --mysql-host=127.0.0.1 --mysql-port=8036 prepare

###################
# Setup P_S query history for a specific user(msandbox)
###################
UPDATE performance_schema.setup_actors SET ENABLED = 'NO', HISTORY = 'NO' WHERE HOST = '%' AND USER = '%';
DELETE FROM performance_schema.setup_actors WHERE USER = 'msandbox';
INSERT INTO performance_schema.setup_actors (HOST,USER,ROLE,ENABLED,HISTORY) VALUES('%','msandbox','%','YES','YES');

UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', timed = 'YES' WHERE ENABLED <> 'YES' AND NAME LIKE 'statement/%';
UPDATE performance_schema.setup_consumers   SET ENABLED = 'YES'                WHERE ENABLED <> 'YES' AND NAME LIKE 'events_statements%';

###################
# Verify
###################
SELECT * FROM performance_schema.setup_actors;
SELECT * FROM performance_schema.setup_instruments WHERE ENABLED <> 'YES' AND NAME LIKE 'statement/%';
SELECT * FROM performance_schema.setup_consumers   WHERE ENABLED <> 'YES' AND NAME LIKE 'events_statements%';
-- https://dev.mysql.com/doc/refman/8.0/en/performance-schema-prepared-statements-instances-t...
SELECT * FROM performance_schema.setup_instruments WHERE NAME IN ('statement/com/Prepare', 'statement/com/Execute', 'statement/sql/prepare_sql', 'statement/sql/execute_sql');
EXIT;

###################
# Relogin as root and Clear summary tables
###################
CALL sys.ps_truncate_all_tables(FALSE);

###################
# Run mysql client as msandbox user
# Note : DEALLOCATE removes it from performance_schema.prepared_statements_instances
###################

PREPARE stmt1 FROM 'INSERT INTO test.t1 VALUES(1)';
EXECUTE stmt1;
DEALLOCATE PREPARE stmt1;
PREPARE stmt2 FROM 'DELETE FROM test.t1';
EXECUTE stmt2;

###################
# Run sysbench app as msandbox user
###################
sysbench oltp_write_only --threads=1 --time=1 --tables=1 --table-size=10 --db-driver=mysql --mysql-db=test --mysql-user=msandbox --mysql-password=msandbox --mysql-storage-engine=InnoDB --report-interval=5 --mysql-host=127.0.0.1 --mysql-port=8036 run

###################
# Verify
###################
SELECT OWNER_OBJECT_TYPE, OWNER_OBJECT_SCHEMA, OWNER_OBJECT_NAME, STATEMENT_NAME, SQL_TEXT FROM performance_schema.prepared_statements_instances ;
SELECT THREAD_ID, EVENT_ID, SQL_TEXT, DIGEST_TEXT, EVENT_NAME, MYSQL_ERRNO FROM performance_schema.events_statements_history_long LIMIT 9;
SELECT THREAD_ID, EVENT_NAME, SQL_TEXT, COUNT(*) FROM performance_schema.events_statements_history_long  GROUP BY THREAD_ID, EVENT_NAME, SQL_TEXT;

Suggested fix:
Data in events_statements_history_long table should include even non-mysql client applications using prepared statements.

############################################
# Enabling general log was able to capture the complete query.
############################################
mysql [localhost:8036] {root} ((none)) > SHOW GLOBAL VARIABLES WHERE Variable_name IN ('general_log', 'general_log_file', 'log_output');
+------------------+---------------------------------------------+
| Variable_name    | Value                                       |
+------------------+---------------------------------------------+
| general_log      | ON                                          |
| general_log_file | /nfs/sandboxes/my/msb_8_0_36/data/nitro.log |
| log_output       | TABLE                                       |
+------------------+---------------------------------------------+
3 rows in set (0.00 sec)

mysql [localhost:8036] {root} ((none)) > TRUNCATE TABLE mysql.general_log;
Query OK, 0 rows affected (0.01 sec)

############################################
# Run same sysbench app :
############################################
shell> sysbench oltp_write_only --threads=1 --time=1 --tables=1 --table-size=10 --db-driver=mysql --mysql-db=test --mysql-user=msandbox --mysql-password=msandbox --mysql-storage-engine=InnoDB --report-interval=5 --mysql-host=127.0.0.1 --mysql-port=8036 run

############################################
# Verify :
############################################
mysql [localhost:8036] {root} ((none)) > SELECT v.* FROM (SELECT thread_id, convert(argument using utf8) argument_txt FROM mysql.general_log WHERE user_host LIKE 'msandbox%' ORDER BY thread_id, event_time) v  WHERE v.argument_txt <> '' LIMIT 6;
+-----------+---------------------------------------------------------+
| thread_id | argument_txt                                            |
+-----------+---------------------------------------------------------+
|        18 | COMMIT                                                  |
|        18 | UPDATE sbtest1 SET k=k+1 WHERE id=?                     |
|        18 | UPDATE sbtest1 SET c=? WHERE id=?                       |
|        18 | DELETE FROM sbtest1 WHERE id=?                          |
|        18 | INSERT INTO sbtest1 (id, k, c, pad) VALUES (?, ?, ?, ?) |
|        18 | BEGIN                                                   |
+-----------+---------------------------------------------------------+
6 rows in set, 1 warning (0.01 sec)

Hi Mr. Po,

Thank you for your bug report.

We were able to repeat it fully.

This is now a verified bug report.

Posted by developer:
 
Added the following note to the MySQL Server 9.6.0 release notes:
		
Performance Schema did not capture SQL or digests for prepared statements from non-MySQL clients.