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.
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.