Blog

Tracking MySQL query history in long running transactions

TransactionHistoryWordCloud-1024x649.png

Here we will use the information_schema coupled with the performance_schema to find more information about the open transactions.

Given a long running time of say 1 second, we can do the following.

SELECT trx.trx_id,
trx.trx_started,
trx.trx_mysql_thread_id
FROM INFORMATION_SCHEMA.INNODB_TRX trx
WHERE trx.trx_started < CURRENT_TIMESTAMP - INTERVAL 1 SECONDG
*************************** 1. row ***************************
trx_id: 3357
trx_started: 2014-08-08 12:10:23
trx_mysql_thread_id: 2170

To avoid collecting system transactions we can join to the processlist table and eliminate system users from the list.

SELECT trx.trx_id,
       trx.trx_started,
       trx.trx_mysql_thread_id
FROM INFORMATION_SCHEMA.INNODB_TRX trx
JOIN INFORMATION_SCHEMA.PROCESSLIST ps ON trx.trx_mysql_thread_id = ps.id
WHERE trx.trx_started < CURRENT_TIMESTAMP - INTERVAL 1 SECOND
  AND ps.user != 'system_user'G
*************************** 1. row *************************** 
trx_id: 3357 
trx_started: 2014-08-08 12:10:23 
trx_mysql_thread_id: 2170

If the performance schema is enabled, we are then able to use the performance_schema.threads table to map the processlist_id to the thread_id.

SELECT *
FROM performance_schema.threads
WHERE processlist_id = 2170G
*************************** 1. row ***************************
THREAD_ID: 2189
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 2170
PROCESSLIST_USER: root
PROCESSLIST_HOST: NULL
PROCESSLIST_DB: test
PROCESSLIST_COMMAND: Sleep
PROCESSLIST_TIME: 2428
PROCESSLIST_STATE: NULL
PROCESSLIST_INFO: NULL
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES

Once we have the thread_id we can get a history of that thread from the performance_schema.events_statements_history table.

SELECT thread_id,
       EVENT_ID,
       END_EVENT_ID,
       EVENT_NAME,    
   SQL_TEXT
FROM events_statements_history
WHERE thread_id = 2189G
*************************** 1. row *************************** 
thread_id: 2189 
EVENT_ID: 11 
END_EVENT_ID: 33 
EVENT_NAME: statement/sql/show_databases 
SQL_TEXT: show databases 
*************************** 2. row *************************** 
thread_id: 2189 
EVENT_ID: 35 
END_EVENT_ID: 58 
EVENT_NAME: statement/sql/show_tables 
SQL_TEXT: show tables 
*************************** 3. row *************************** 
thread_id: 2189 
EVENT_ID: 60 
END_EVENT_ID: 71 
EVENT_NAME: statement/com/Field List 
SQL_TEXT: NULL 
*************************** 4. row *************************** 
thread_id: 2189 
EVENT_ID: 73 
END_EVENT_ID: 99 
EVENT_NAME: statement/sql/insert 
SQL_TEXT: insert into mytest values (7, "inigo") 
*************************** 5. row *************************** 
thread_id: 2189 
EVENT_ID: 101 
END_EVENT_ID: 132 
EVENT_NAME: statement/sql/select 
SQL_TEXT: select * from mytest

*************************** 6. row *************************** 
thread_id: 2189 
EVENT_ID: 134 
END_EVENT_ID: 144 
EVENT_NAME: statement/sql/begin 
SQL_TEXT: start transaction 

*************************** 7. row *************************** 
thread_id: 2189 
EVENT_ID: 146 
END_EVENT_ID: 176 
EVENT_NAME: statement/sql/select 
SQL_TEXT: select * from mytest 
*************************** 8. row *************************** 
thread_id: 2189 
EVENT_ID: 178 
END_EVENT_ID: 201 
EVENT_NAME: statement/sql/insert 
SQL_TEXT: insert into mytest values (5, "stephen") 
*************************** 9. row *************************** 
thread_id: 2189 
EVENT_ID: 203 
END_EVENT_ID: 225 
EVENT_NAME: statement/sql/insert 
SQL_TEXT: insert into mytest values (6, "dave") 
*************************** 10. row *************************** 
thread_id: 2189 
EVENT_ID: 227 
END_EVENT_ID: 259 
EVENT_NAME: statement/sql/select 
SQL_TEXT: select * from mytest

In this case we can see that event_id 134 started the last transaction. Once the transaction commits we can expect to see something like the following.

thread_id: 2189
EVENT_ID: 261
END_EVENT_ID: 274
EVENT_NAME: statement/sql/commit
SQL_TEXT: commit

Joining the pieces together we get:

SELECT ps.id 'PROCESS ID',
             esh.event_name 'EVENT NAME',
                            esh.sql_text 'SQL'
FROM information_schema.innodb_trx trx
JOIN information_schema.processlist ps ON trx.trx_mysql_thread_id = ps.id
JOIN performance_schema.threads th ON th.processlist_id = trx.trx_mysql_thread_id
JOIN performance_schema.events_statements_history esh ON esh.thread_id = th.thread_id
WHERE trx.trx_started < CURRENT_TIME - INTERVAL 10 SECOND
  AND ps.USER != SYSTEM_USER
ORDER BY esh.EVENT_ID
+------------+----------------------+--------------------------------------+ 
| PROCESS ID | EVENT NAME           | SQL                                  | 
+------------+----------------------+--------------------------------------+ 
| 2170       | statement/sql/commit | commit                               | 
| 2170       | statement/sql/select | select * from mytest                 | 
| 2170       | statement/sql/error  | end transaction                      | 
| 2170       | statement/sql/commit | commit                               | 
| 2170       | statement/sql/commit | commit                               | 
| 2170       | statement/sql/commit | commit                               | 
| 2170       | statement/sql/begin  | start transaction                    | 
| 2170       | statement/sql/select | select * from mytest                 | 
| 2170       | statement/sql/select | select * from mytest                 | 
| 2170       | statement/sql/insert | insert into mytest values (8, "bob") | 
+------------+----------------------+--------------------------------------+

This shows us the known history for process 2170 seen here in the SHOW ENGINE INNODB STATUS output

------------
TRANSACTIONS
------------
Trx id counter 3368
Purge done for trx's n:o < 3365 undo n:o < 0 state: running but idle
History list length 10
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 2169, OS thread handle 0x12bf06000, query id 4734 localhost root init
show engine innodb status
---TRANSACTION 3363, ACTIVE 1924 sec
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 2170, OS thread handle 0x12be1e000, query id 4726 localhost root cleaning up
Trx read view will not see trx with id >= 3364, sees < 3364

However, there are of course some caveats on this technique:

1. Enabling the performance_schema can carry some overhead.
There are many variables which determine exactly what affect enabling the instrumentation will have on your workload. Benchmarks vary, however I would expect some overhead - but as always, the best path of action is to test it and see.

You may already be running with PS enabled, as with MySQL 5.6 the performance schema is enabled by default. To check run the following command.

SHOW GLOBAL variables LIKE 'performance_schema';
+--------------------+-------+ 
| Variable_name      | Value | 
+--------------------+-------+ 
| performance_schema | ON    | 
+--------------------+-------+

The performance_schema can be enabled using the startup command line arguments to mysqld or in the MySQL configuration file.

Once enabled, you need to enable the instrumentation for the particular part of the performance schema that populates the events_statements_history table.

UPDATE setup_instruments SET ENABLED = 'YES', timed = 'YES' WHERE NAME LIKE 'statement/%’;
UPDATE setup_consumers SET ENABLED = ‘YES' WHERE NAME LIKE 'events_statements%';

Optionally you can enable this for a specific schema by updating the setup_objects table.

SELECT * FROM setup_objects;
+-------------+--------------------+-------------+---------+-------+
| OBJECT_TYPE | OBJECT_SCHEMA      | OBJECT_NAME | ENABLED | TIMED |
+-------------+--------------------+-------------+---------+-------+
| TABLE       | mysql              | %           | NO      | NO    |
| TABLE       | performance_schema | %           | NO      | NO    |
| TABLE       | information_schema | %           | NO      | NO    |
| TABLE       | %                  | %           | YES     | YES   |
+-------------+--------------------+-------------+---------+-------+

2. The length of history is dependent on the performance schema settings and the workload applied:

SHOW GLOBAL variables LIKE '%events_statements_history%';
+--------------------------------------------------------+-------+
| Variable_name                                          | Value |
+--------------------------------------------------------+-------+
| performance_schema_events_statements_history_long_size | 10000 |
| performance_schema_events_statements_history_size      | 10    |
+--------------------------------------------------------+-------+

Obviously keeping a longer history is going to be more costly and the more activity on the system the shorter the time period that remains visible. The history size is not dynamic, so you must set it at startup either on the command lineor in the MySQL configuration file with the performance_schema_events_statements_history_size option.

Running a select on the threads table can show if a thread is instrumented.

SELECT * FROM threads WHERE THREAD_ID = 2190G
*************************** 1. row ***************************
THREAD_ID: 2190
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 2171
PROCESSLIST_USER: root
PROCESSLIST_HOST: NULL
PROCESSLIST_DB: test
PROCESSLIST_COMMAND: Sleep
PROCESSLIST_TIME: 26
PROCESSLIST_STATE: NULL
PROCESSLIST_INFO: NULL
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES


It's clear that newer versions of MySQL can provide some very interesting insight into what  is actually being executed inside the database and that knowing more about the instrumentation it offers can reduce the guesswork needed to resolve development problems.

Long running transactions can be problematic for OLTP workloads, particularly where we would expect most to be completed in less than a second. In some cases a transaction staying open just a few seconds can cause behaviour that is entirely unexpected, with the developers at a loss as to why a transaction remained open. There are a number of ways to find long running transactions, luckily versions of MySQL from 5.6 onwards provide some very insightful instrumentation.

Take care of your MySQL performance.

MySQL audits available from only €99 per server. Learn More
blog comments powered by Disqus