A brief analysis of SQL examples for finding uncommitted transactions in MySQL

A long time ago, I summarized a blog post titled "How to Find Uncommitted Transaction Information in MySQL". Now it seems that many of the knowledge points or viewpoints in this article are a bit superficial, or not deep enough, and even some of the conclusions are wrong. Let’s revisit this topic. So let’s introduce it with the previous example.

--Prepare test environment data (the experimental environment is MySQL 8.0.18 Community Edition)

mysql> create table kkk(id int , name varchar(12));
Query OK, 0 rows affected (0.34 sec)
 
mysql> insert into kkk values(1, 'kerry');
Query OK, 1 row affected (0.01 sec)
 
mysql> insert into kkk values(2, 'jerry');
Query OK, 1 row affected (0.00 sec)
 
mysql> insert into kkk values(3, 'ken');
Query OK, 1 row affected (0.00 sec)
 
mysql> 
 
mysql> create table t(a varchar(10));
Query OK, 0 rows affected (0.47 sec)
 
mysql> insert into t values('test');
Query OK, 1 row affected (0.00 sec)

Execute the following SQL in a session window (connection ID=38)

mysql> select connection_id() from dual;
+-----------------+
| connection_id() |
+-----------------+
| 38 |
+-----------------+
1 row in set (0.00 sec)
 
mysql> set session autocommit=0;
Query OK, 0 rows affected (0.00 sec)
 
mysql> delete from kkk where id =1;
Query OK, 1 row affected (0.00 sec)
 
mysql>

In another session window (connection ID=39), execute the following SQL

mysql> SELECT t.trx_mysql_thread_id
 -> ,t.trx_id
 -> ,t.trx_state
 -> ,t.trx_tables_in_use
 -> ,t.trx_tables_locked
 -> ,t.trx_query
 -> ,t.trx_rows_locked 
 -> ,t.trx_rows_modified
 -> ,t.trx_lock_structs
 -> ,t.trx_started
 -> ,t.trx_isolation_level
 -> ,p.time 
 -> ,p.user
 -> ,p.host
 -> ,p.db
 -> ,p.command
 -> FROM information_schema.innodb_trx t 
 -> INNER JOIN information_schema.processlist p 
 -> ON t.trx_mysql_thread_id = p.id 
 -> WHERE t.trx_state = 'RUNNING' 
 -> AND p.time > 4 
 -> AND p.command = 'Sleep'\G 
*************************** 1. row ***************************
trx_mysql_thread_id: 38
  trx_id: 7981581
  trx_state: RUNNING
 trx_tables_in_use: 0
 trx_tables_locked: 1
  trx_query: NULL
 trx_rows_locked: 4
 trx_rows_modified: 1
 trx_lock_structs: 2
 trx_started: 2020-12-03 15:39:37
trx_isolation_level: REPEATABLE READ
  time: 23
  user: root
  host: localhost
   db: MyDB
  command: Sleep
1 row in set (0.00 sec)

Although the above SQL cannot find the SQL executed by the transaction, in fact, the last SQL executed by the uncommitted transaction in MySQL can be accurately found through the following script. As shown below:

SELECT t.trx_mysql_thread_id AS connection_id
 ,t.trx_id AS trx_id  
 ,t.trx_state AS trx_state 
 ,t.trx_started AS trx_started 
 ,TIMESTAMPDIFF(SECOND,t.trx_started, now()) AS "trx_run_time(s)" 
 ,t.trx_requested_lock_id AS trx_requested_lock_id
 ,t.trx_operation_state AS trx_operation_state
 ,t.trx_tables_in_use AS trx_tables_in_use
 ,t.trx_tables_locked AS trx_tables_locked
 ,t.trx_rows_locked AS trx_rows_locked
 ,t.trx_isolation_level AS trx_isolation_level
 ,t.trx_is_read_only AS trx_is_read_only
 ,t.trx_autocommit_non_locking AS trx_autocommit_non_locking
 ,e.event_name AS event_name
 ,e.timer_wait / 1000000000000 AS timer_wait
 ,e.sql_text 
FROM information_schema.innodb_trx t, 
 performance_schema.events_statements_current e, 
 performance_schema.threads c 
WHERE t.trx_mysql_thread_id = c.processlist_id 
 AND e.thread_id = c.thread_id\G;

As shown in the following screenshot:

Continue to execute the following SQL in the session window (connection ID=38): "select * from t;". As shown below

mysql> set session autocommit=0;
Query OK, 0 rows affected (0.01 sec)
 
mysql> delete from kkk where id =1;
Query OK, 1 row affected (0.00 sec)
 
mysql> select * from t;
+------+
| a |
+------+
| test |
+------+
1 row in set (0.00 sec)
 
mysql>

Continue to execute the following SQL in the session window (connection ID=39), and you will find that the captured SQL statement is the last SQL statement executed by the transaction, "select * from t"

mysql> SELECT t.trx_mysql_thread_id AS connection_id
 -> ,t.trx_id AS trx_id  
 -> ,t.trx_state AS trx_state 
 -> ,t.trx_started AS trx_started 
 -> ,TIMESTAMPDIFF(SECOND,t.trx_started, now()) AS "trx_run_time(s)" 
 -> ,t.trx_requested_lock_id AS trx_requested_lock_id
 -> ,t.trx_operation_state AS trx_operation_state
 -> ,t.trx_tables_in_use AS trx_tables_in_use
 -> ,t.trx_tables_locked AS trx_tables_locked
 -> ,t.trx_rows_locked AS trx_rows_locked
 -> ,t.trx_isolation_level AS trx_isolation_level
 -> ,t.trx_is_read_only AS trx_is_read_only
 -> ,t.trx_autocommit_non_locking AS trx_autocommit_non_locking
 -> ,e.event_name AS event_name
 -> ,e.timer_wait / 1000000000000 AS timer_wait
 -> ,e.sql_text 
 -> FROM information_schema.innodb_trx t, 
 -> performance_schema.events_statements_current e, 
 -> performance_schema.threads c 
 -> WHERE t.trx_mysql_thread_id = c.processlist_id 
 -> AND e.thread_id = c.thread_id\G; 
*************************** 1. row ***************************
  connection_id: 38
   trx_id: 7981581
   trx_state: RUNNING
  trx_started: 2020-12-03 15:39:37
  trx_run_time(s): 237
 trx_requested_lock_id: NULL
 trx_operation_state: NULL
  trx_tables_in_use: 0
  trx_tables_locked: 1
  trx_rows_locked: 4
 trx_isolation_level: REPEATABLE READ
  trx_is_read_only: 0
trx_autocommit_non_locking: 0
  event_name: statement/sql/select
  timer_wait: 0.0002
   sql_text: select * from t
1 row in set (0.00 sec)
 
ERROR: 
No query specified 

That is to say, the above SQL can only obtain the last SQL statement executed by the uncommitted transaction. In the production environment, there is often more than one SQL statement in a transaction, but a collection of multiple SQL statements. What if you want to find out all the SQL statements executed in an uncommitted transaction? In fact, there is a way in MySQL. The following SQL statement can find out or

SELECT trx.trx_mysql_thread_id AS processlist_id
 ,sc.thread_id
 ,trx.trx_started
 ,TO_SECONDS(now())-TO_SECONDS(trx_started) AS trx_last_time 
 ,pc1.user
 ,pc1.host
 ,pc1.db
 ,sc.SQL_TEXT AS current_sql_text
 ,sh.history_sql_test
FROM INFORMATION_SCHEMA.INNODB_TRX trx
INNER JOIN INFORMATION_SCHEMA.processlist pc1 ON trx.trx_mysql_thread_id=pc1.id
INNER JOIN performance_schema.threads th on th.processlist_id = trx.trx_mysql_thread_id
INNER JOIN performance_schema.events_statements_current sc ON sc.THREAD_ID = th.THREAD_ID
INNER JOIN (
  SELECT thread_id AS thread_id, GROUP_CONCAT(SQL_TEXT SEPARATOR ';') AS history_sql_test
  FROM performance_schema.events_statements_history 
  GROUP BY thread_id 
  ) sh ON sh.thread_id = th.thread_id
WHERE trx_mysql_thread_id != connection_id()
 AND TO_SECONDS(now())-TO_SECONDS(trx_started) >= 0;

However, there is a problem with these two SQL statements: they will find all the SQL statements executed in the history of the current connection (of course, the premise is that these SQL statements are still saved in the performance_schema.events_statements_history table). In other words, this SQL statement not only queries all the scripts executed by uncommitted transactions, but also queries many historical SQL scripts, for example, the SQL statements of the transactions before this session (connection). In addition, there is a more troublesome problem: it is difficult to distinguish which SQL statements correspond to which transactions. Other information is needed to identify. It is time-consuming and laborious. As shown in the screenshot below.

Because only the information_schema.innodb_trx system table contains the start time of the transaction (trx_started), and other system tables do not have transaction-related time, we can only use the TIMER_START field in performance_schema.events_statements_history to obtain the time when the SQL of the event starts executing, and this time must be less than or equal to the start time of the corresponding transaction (trx_started). So we can find all SQL statements of uncommitted transactions from this breakthrough. The following is a detailed introduction to fields such as TIMER_START.

The introduction of TIMER_START, TIMER_END, and TIMER_WAIT is as follows:

TIMER_START, TIMER_END, TIMER_WAIT: time information of the event. The values ​​are in picoseconds (trillionths of a second).

The TIMER_START and TIMER_END values ​​represent the start and end times of the event.

TIMER_WAIT is the time (duration) consumed by the event execution

If the event is not completed, TIMER_END is the current time, and TIMER_WAIT is the time elapsed so far (TIMER_END - TIMER_START).

If the TIMED field of the corresponding monitor in the monitoring instrument configuration table setup_instruments is set to NO, the time information of the monitor will not be collected. In the information record collected for this event, the values ​​of the TIMER_START, TIMER_END, and TIMER_WAIT fields are all NULL.

After testing and struggling for a long time, I finally came up with an almost perfect SQL:

SELECT @dt_ts:=UNIX_TIMESTAMP(NOW());
SELECT 
 @dt_timer:=MAX(sh.TIMER_START)
FROM performance_schema.threads AS t
INNER JOIN performance_schema.events_statements_history AS sh
ON t.`THREAD_ID`=sh.`THREAD_ID`
WHERE t.PROCESSLIST_ID=CONNECTION_ID();
 
 
SELECT sh.current_schema AS database_name
 ,t.thread_id
 ,it.trx_mysql_thread_id AS connection_id
 ,it.trx_id
 ,sh.event_id
 ,it.trx_state
 ,REPLACE(REPLACE(REPLACE(sh.`SQL_TEXT`,'\n',' '),'\r',' '),'\t',' ') AS executed_sql
 ,it.trx_started
 ,FROM_UNIXTIME(@dt_ts-CAST((@dt_timer-sh.TIMER_START)/1000000000000 AS SIGNED)) AS start_time
 ,FROM_UNIXTIME(@dt_ts-CAST((@dt_timer-sh.TIMER_END) /1000000000000 AS SIGNED)) AS end_time
 ,(sh.TIMER_END-sh.TIMER_START)/1000000000000 AS used_seconds
 ,sh.TIMER_WAIT/1000000000000 AS wait_seconds
 ,sh.LOCK_TIME/1000000000000 AS lock_seconds
 ,sh.ROWS_AFFECTED AS affected_rows
 ,sh.ROWS_SENT AS send_rows
FROM performance_schema.threads AS t
INNER JOIN information_schema.innodb_trx it ON it.trx_mysql_thread_id = t.processlist_id 
INNER JOIN performance_schema.events_statements_history AS sh
 ON t.`THREAD_ID`=sh.`THREAD_ID`
WHERE t.PROCESSLIST_ID IN (
  SELECT 
   p.ID AS conn_id
  FROM `information_schema`.`INNODB_TRX` t
  INNER JOIN `information_schema`.`PROCESSLIST` p
   ON t.trx_mysql_thread_id=p.id
  WHERE t.trx_state='RUNNING'
   AND p.COMMAND='Sleep'
   AND p.TIME>2
  )
AND sh.TIMER_START<@dt_timer
AND FROM_UNIXTIME(@dt_ts-CAST((@dt_timer-sh.TIMER_START)/1000000000000 AS SIGNED)) >=it.trx_started
ORDER BY it.trx_id ASC, sh.TIMER_START ASC; 

It can find out the SQL of uncommitted transactions. There is no problem with simple test, and it is also OK to construct several uncommitted transaction tests at the same time. However, the above SQL consists of three SQLs, which always feels a bit awkward. After some research, I found that it can be transformed into the following SQL.

SELECT sh.current_schema AS database_name
 ,t.thread_id
 ,it.trx_mysql_thread_id AS connection_id
 ,it.trx_id
 ,sh.event_id
 ,it.trx_state
 ,REPLACE(REPLACE(REPLACE(sh.`SQL_TEXT`,'\n',' '),'\r',' '),'\t',' ') AS executed_sql
 ,it.trx_started
 ,DATE_SUB(NOW(), INTERVAL (SELECT VARIABLE_VALUE FROM performance_schema.global_status WHERE VARIABLE_NAME='UPTIME') - sh.TIMER_START*10e-13 second) AS start_time
 ,DATE_SUB(NOW(), INTERVAL (SELECT VARIABLE_VALUE FROM performance_schema.global_status WHERE VARIABLE_NAME='UPTIME') - sh.TIMER_END*10e-13 second) AS end_time
 ,(sh.TIMER_END-sh.TIMER_START)/1000000000000 AS used_seconds
 ,sh.TIMER_WAIT/1000000000000 AS wait_seconds
 ,sh.LOCK_TIME/1000000000000 AS lock_seconds
 ,sh.ROWS_AFFECTED AS affected_rows
 ,sh.ROWS_SENT AS send_rows
FROM performance_schema.threads AS t
INNER JOIN information_schema.innodb_trx it ON it.trx_mysql_thread_id = t.processlist_id 
INNER JOIN performance_schema.events_statements_history AS sh
 ON t.`THREAD_ID`=sh.`THREAD_ID`
WHERE t.PROCESSLIST_ID IN (
  SELECT 
   p.ID AS conn_id
  FROM `information_schema`.`INNODB_TRX` t
  INNER JOIN `information_schema`.`PROCESSLIST` p
   ON t.trx_mysql_thread_id=p.id
  WHERE t.trx_state='RUNNING'
   AND p.COMMAND='Sleep'
   AND p.TIME>2
  )
AND sh.TIMER_START<(SELECT VARIABLE_VALUE*1000000000000 FROM performance_schema.global_status WHERE VARIABLE_NAME='UPTIME')
AND DATE_SUB(NOW(), INTERVAL (SELECT VARIABLE_VALUE FROM performance_schema.global_status WHERE VARIABLE_NAME='UPTIME') - sh.TIMER_START*10e-13 second) >= it.trx_started
ORDER BY it.trx_id ASC, sh.TIMER_START ASC;

Note: performance_schema.global_status was introduced in MySQL 5.7. If the database is MySQL 5.6, you can replace performance_schema.global_status in SQL with INFORMATION_SCHEMA.GLOBAL_STATUS

So is this SQL necessarily perfect? Netizen MSSQL123 reported that in a test environment, the above SQL could not find any data, because FROM_UNIXTIME(@dt_ts-CAST((@dt_timer-sh.TIMER_START)/1000000000000 AS SIGNED)) >=it.trx_started would filter out the data. It was found that the corresponding trx_started values ​​were all greater than start_time.

-------------------------------------------------------------------------Supplementary information----------------------------------------------------------------------------------------------------

Then in the same test environment, when testing the next day, it was suddenly discovered that the first SQL statement above was normal, but the second SQL statement had a slight difference in start_time due to different writing methods, resulting in completely different query results (the second SQL statement was accurate to milliseconds, and a batch of data was filtered out due to deviation during comparison)

------------------------------------------------------------------------------------------------------------------------------------------------

Searching for relevant documents, I learned that the TIMER_START field value may fluctuate or deviate, and this fluctuation or deviation may affect the query results. The following content comes from http://porthos.ist.utl.pt/docs/mySQL/performance-schema.html

Modifications to the setup_timers table affect monitoring immediately. Events already in progress may use the original timer for the begin time and the new timer for the end time. To avoid unpredictable results after you make timer changes, use TRUNCATE TABLE to reset Performance Schema statistics.

The timer baseline ("time zero") occurs at Performance Schema initialization during server startup. TIMER_START and TIMER_END values ​​in events represent picoseconds since the baseline. TIMER_WAIT values ​​are durations in picoseconds.

Picosecond values ​​in events are approximate. Their accuracy is subject to the usual forms of error associated with conversion from one unit to another. If the CYCLE timer is used and the processor rate varies, there might be drift. For these reasons, it is not reasonable to look at the TIMER_START value for an event as an accurate measure of time elapsed since server startup. On the other hand, it is reasonable to use TIMER_START or TIMER_WAIT values ​​in ORDER BY clauses to order events by start time or duration.

The choice of picoseconds in events rather than a value such as microseconds has a performance basis. One implementation goal was to show results in a uniform time unit, regardless of the timer. In an ideal world this time unit would look like a wall-clock unit and be reasonably precise; in other words, microseconds. But to convert cycles or nanoseconds to microseconds, it would be necessary to perform a division for every instrumentation. Division is expensive on many platforms. Multiplication is not expensive, so that is what is used. Therefore, the time unit is an integer multiple of the highest possible TIMER_FREQUENCY value, using a multiplier large enough to ensure that there is no major precision loss. The result is that the time unit is “picoseconds.” This precision is spurious, but the decision enables overhead to be minimized.

Before MySQL 5.7.8, while a wait, stage, statement, or transaction event is executing, the respective current-event tables display the event with TIMER_START populated, but with TIMER_END and TIMER_WAIT set to NULL

One of the passages is translated as follows:

The picosecond values ​​for events are approximate. Their accuracy is affected by common forms of error associated with converting from one unit to another. If the CYCLE timer is used and the processor speed varies, there may be deviations. For these reasons, it is not reasonable to consider the TIMER_START value of an event as an accurate measure of the time that has elapsed since the server was started. On the other hand, it is reasonable to use TIMER_START or TIMER_WAIT values ​​in the ORDER BY clause to sort events by start time or duration.

We often want to solve the problem with one blow, but due to the complex environment and some uncontrollable factors, the reality is often as cruel as "there is no silver bullet". If the fluctuation or deviation of TIMER_START affects the query results, we must find a large number of SQLs through the SQLs in the previous article, and then manually identify which SQLs are uncommitted transactions through other fields or information.

References:

https://stackoverflow.com/questions/25607249/mysql-performance-schema-how-to-get-event-time-from-events-statements-current-ta

http://porthos.ist.utl.pt/docs/mySQL/performance-schema.html

https://dev.mysql.com/doc/refman/5.7/en/performance-schema-timing.html

https://dev.mysql.com/doc/refman/8.0/en/performance-schema-timing.html

This is the end of this article about how to find uncommitted transaction SQL in MySQL. For more information about how to find uncommitted transaction SQL in MySQL, please search previous articles on 123WORDPRESS.COM or continue to browse the following related articles. I hope you will support 123WORDPRESS.COM in the future!