MySQL 5.7 has had some great improvements within Performance Schema to be able to better trace what connections are doing, from adding memory information, through to transaction information, metadata locking, prepared statements, and even user variables, so far (there is still more to come in the next release – stay tuned).
Of course there are other improvements on top of this as well, such as the new replication tables, but I won’t go in to that here. Today I want to focus on the kind of data you can now get in MySQL 5.7 for debugging what a foreground user connection has been doing.
I’ve written before about how Performance Schema allows you to create a much better alternative to SHOW FULL PROCESSLIST, however that solution was never really satisfying to me. It’s fine for a high level overview of the connections to the database, but there was so much more information available within Performance Schema, even in MySQL 5.6, that can be exposed on a per thread basis.
The problem is that a lot of that extra data that I wanted exposed is really of a structured form, such as the last N statements (or in 5.7, last N transactions even) that a connection has executed, or a summary of wait information, for example. Everybody loves JSON now’a’days, so that was the obvious choice to me – I wanted a JSON object, per thread, of the available data from Performance Schema.
And so started the writing of a query from hell. But the output is, if I may say so myself, a thing of beauty.
Lets whet that appetite a little (and you may need to scroll to the right):
thread_info:
{
"user": "root@localhost",
"thd_id": 106950,
"connection_id": 106927,
"database": "memtrunkio",
"current_statement": {
"time": 1,
"rows_examined": 0,
"rows_affected": 0,
"rows_sent": 0,
"tmp_tables": 0,
"tmp_disk_tables": 0,
"sort_rows": 0,
"sort_merge_passes": 0,
"text": "/* mem dbpool.default */ insert into `memtrunkio__quan`.`normalized_statements_by_server_by_schema` (firstSeen, lastSeen, normalized_statement_id, `schema`, server, id) values (1424379489000, 1424430252000, x'083ADE6E
3A814355A823472B787CF079', 'memtrunkio', 'cd6fe2ae-a6ce-11e4-87eb-180373e22685', x'22D1E8D4ECDB30848B8C39456204E29F') ON DUPLICATE KEY UPDATE
firstSeen = COALESCE( LEAST(firstSeen, VALUES(firstSeen)), firstSeen),
lastSeen = COALESCE( GREATEST(lastSeen, VALUES(lastSeen)), lastSeen)"
},
"last_transactions": [
{
"time": "1.86 s",
"state": "COMMITTED",
"mode": "READ WRITE",
"autocommitted": "NO",
"gtid": "",
"isolation": "REPEATABLE READ",
"statements": [
{
"time": "1.37 s",
"schema": "memtrunkio",
"rows_examined": 0,
"rows_affected": 1,
"rows_sent": 0,
"tmp_tables": 0,
"tmp_disk_tables": 0,
"sort_rows": 0,
"sort_merge_passes": 0,
"statement": "/* mem dbpool.default */ insert into `memtrunkio__quan`.`normalized_statements_by_server_by_schema_data` (bytesMax, bytesMin, bytesTotal, collectionDuration, createdTmpDiskTables, createdTmpTables, errorCou
nt, execCount, execTimeMax, execTimeMin, execTimeTotal, lockTimeTotal, noGoodIndexUsedCount, noIndexUsedCount, rowsExaminedTotal, rowsMax, rowsMin, rowsTotal, selectFullJoin, selectFullRangeJoin, selectRange, selectRangeCheck, sel
ectScan, sortMergePasses, sortRange, sortRows, sortScan, timestamp, warningCount, round_robin_bin, normalized_statement_by_server_by_schema_id) values (null, null, null, 120000, 0, 4, 0, 4, 2858, 801, 4231, 1000, 0, 4, 1856, null,
null, 1856, 0, 0, 0, 0, 4, 0, 0, 0, 0, 1424430258000, 0, 32344, x'CDD64BD9418A30C0B310095788B9DD41') ON DUPLICATE KEY UPDATE bytesMax = IF(VALUES(`timestamp`) >= `timestamp`, VALUES(bytesMax), bytesMax), bytesMin = IF(VALUES(`tim
estamp`) >= `timestamp`, VALUES(bytesMin), bytesMin), bytesTotal = IF(VALUES(`timestamp`) >= `timestamp`, VALUES(bytesTotal), by"
},
{
"time": "269.82 us",
"schema": "memtrunkio",
"rows_examined": 0,
"rows_affected": 1,
"rows_sent": 0,
"tmp_tables": 0,
"tmp_disk_tables": 0,
"sort_rows": 0,
"sort_merge_passes": 0,
"statement": "/* mem dbpool.default */ insert into `memtrunkio__quan`.`example_statements` (bytes, comments, connectionId, errors, execTime, hostFrom, hostTo, noGoodIndexUsed, noIndexUsed, rows, source_location_id, `text
`, timestamp, user, warnings, round_robin_bin, normalized_statement_by_server_by_schema_id) values (null, null, 13949, 0, 1178, 'localhost', null, 0, 1, 464, null, 'SHOW /*!50000 GLOBAL */ VARIABLES', 1424430227189, 'root', 0, 323
43, x'CDD64BD9418A30C0B310095788B9DD41') ON DUPLICATE KEY UPDATE bytes = IF(VALUES(`timestamp`) >= `timestamp`, VALUES(bytes), bytes), comments = IF(VALUES(`timestamp`) >= `timestamp`, VALUES(comments), comments), connectionId =
IF(VALUES(`timestamp`) >= `timestamp`, VALUES(connectionId), connectionId), errors = IF(VALUES(`timestamp`) >= `timestamp`, VALUES(errors), errors), execTime = IF(VALUES(`timestamp`) >= `timestamp`, VALUES(execTime), execTime), ho
stFrom = IF(VALUES(`timestamp`) >= `timestamp`, VALUES(hostFrom), hostFrom), hostTo = IF(VALUES(`timestamp`) >= `timestamp`, VAL"
},
{
"time": "42.07 ms",
"schema": "memtrunkio",
"rows_examined": 0,
"rows_affected": 0,
"rows_sent": 0,
"tmp_tables": 0,
"tmp_disk_tables": 0,
"sort_rows": 0,
"sort_merge_passes": 0,
"statement": "/* mem dbpool.default */ commit"
}
]
}
],
"metadata_locks": [
{ "lock_type": "SHARED_WRITE", "lock_duration": "TRANSACTION", "lock_status": "GRANTED", "scope": "memtrunkio__quan.normalized_statements_by_server_by_schema" },
{ "lock_type": "INTENTION_EXCLUSIVE", "lock_duration": "STATEMENT", "lock_status": "GRANTED", "scope": "*.*" }
],
"table_handles": [
{ "schema": "memtrunkio__quan", "table": "normalized_statements_by_server_by_schema" }
],
"memory_summary": {
"total_memory": "70.30 KiB",
"memory_details": [
{ "type": "sql/thd::main_mem_root", "count": 3, "allocated": "23.95 KiB", "total_allocated": "2.20 MiB", "high_allocated": "175.36 KiB" },
{ "type": "sql/NET::buff", "count": 1, "allocated": "16.01 KiB", "total_allocated": "16.01 KiB", "high_allocated": "16.01 KiB" },
{ "type": "sql/String::value", "count": 1, "allocated": "16.00 KiB", "total_allocated": "32.01 KiB", "high_allocated": "32.01 KiB" },
{ "type": "mysys/array_buffer", "count": 6, "allocated": "8.92 KiB", "total_allocated": "9.05 KiB", "high_allocated": "8.92 KiB" },
{ "type": "sql/THD::transactions::mem_root", "count": 1, "allocated": "4.02 KiB", "total_allocated": "4.02 KiB", "high_allocated": "4.02 KiB" },
{ "type": "vio/vio", "count": 1, "allocated": "608 bytes", "total_allocated": "608 bytes", "high_allocated": "608 bytes" },
{ "type": "innodb/mem0mem", "count": 1, "allocated": "232 bytes", "total_allocated": "4.29 MiB", "high_allocated": "25.69 KiB" },
{ "type": "sql/THD::Session_tracker", "count": 6, "allocated": "209 bytes", "total_allocated": "209 bytes", "high_allocated": "209 bytes" },
{ "type": "innodb/std", "count": 6, "allocated": "208 bytes", "total_allocated": "38.63 KiB", "high_allocated": "592 bytes" },
{ "type": "sql/THD::variables", "count": 1, "allocated": "64 bytes", "total_allocated": "64 bytes", "high_allocated": "64 bytes" },
{ "type": "innodb/ha_innodb", "count": 1, "allocated": "48 bytes", "total_allocated": "48 bytes", "high_allocated": "48 bytes" },
{ "type": "sql/MYSQL_LOCK", "count": 1, "allocated": "32 bytes", "total_allocated": "800 bytes", "high_allocated": "32 bytes" },
{ "type": "sql/THD::db", "count": 1, "allocated": "11 bytes", "total_allocated": "11 bytes", "high_allocated": "11 bytes" },
{ "type": "sql/Security_context", "count": 1, "allocated": "10 bytes", "total_allocated": "10 bytes", "high_allocated": "10 bytes" },
{ "type": "sql/THD::Session_sysvar_resource_manager", "count": 1, "allocated": "8 bytes", "total_allocated": "8 bytes", "high_allocated": "8 bytes" },
{ "type": "sql/MPVIO_EXT::auth_info", "count": 1, "allocated": "5 bytes", "total_allocated": "5 bytes", "high_allocated": "5 bytes" },
{ "type": "innodb/os0event", "count": 0, "allocated": "0 bytes", "total_allocated": "34.23 KiB", "high_allocated": "112 bytes" },
{ "type": "innodb/dict0mem", "count": 0, "allocated": "0 bytes", "total_allocated": "8.25 KiB", "high_allocated": "27 bytes" },
{ "type": "innodb/btr0sea", "count": 0, "allocated": "0 bytes", "total_allocated": "1.95 KiB", "high_allocated": "1.58 KiB" },
{ "type": "innodb/btr0pcur", "count": 0, "allocated": "0 bytes", "total_allocated": "281 bytes", "high_allocated": "0 bytes" }
]
},
"stage_summary": [
{ "stage": "update", "count": 24, "total_time": "6.14 s", "max_time": "2.17 s" },
{ "stage": "starting", "count": 36, "total_time": "100.37 ms", "max_time": "41.97 ms" },
{ "stage": "freeing items", "count": 34, "total_time": "4.76 ms", "max_time": "667.76 us" },
{ "stage": "init", "count": 25, "total_time": "1.27 ms", "max_time": "108.59 us" },
{ "stage": "Opening tables", "count": 29, "total_time": "269.16 us", "max_time": "24.17 us" },
{ "stage": "closing tables", "count": 34, "total_time": "217.84 us", "max_time": "95.68 us" },
{ "stage": "query end", "count": 34, "total_time": "80.45 us", "max_time": "7.28 us" },
{ "stage": "System lock", "count": 25, "total_time": "63.90 us", "max_time": "5.30 us" },
{ "stage": "checking permissions", "count": 25, "total_time": "49.99 us", "max_time": "4.30 us" },
{ "stage": "cleaning up", "count": 35, "total_time": "29.80 us", "max_time": "1.32 us" },
{ "stage": "end", "count": 24, "total_time": "24.17 us", "max_time": "3.97 us" }
],
"wait_summary": {
"total_wait_time": "6.17 s",
"wait_details": [
{ "wait": "io/table/sql/handler", "count": 38, "time_total": "6.16 s", "time_pct": "99.7837", "time_max": "2.03 s" },
{ "wait": "idle", "count": 36, "time_total": "8.90 ms", "time_pct": "0.1443", "time_max": "3.28 ms" },
{ "wait": "io/socket/sql/client_connection", "count": 156, "time_total": "4.36 ms", "time_pct": "0.0707", "time_max": "666.64 us" },
{ "wait": "lock/table/sql/handler", "count": 25, "time_total": "32.98 us", "time_pct": "0.0005", "time_max": "2.52 us" },
{ "wait": "synch/sxlock/innodb/index_tree_rw_lock", "count": 91, "time_total": "15.49 us", "time_pct": "0.0003", "time_max": "864.76 ns" },
{ "wait": "synch/mutex/innodb/trx_mutex", "count": 156, "time_total": "12.37 us", "time_pct": "0.0002", "time_max": "536.22 ns" },
{ "wait": "synch/mutex/sql/THD::LOCK_query_plan", "count": 118, "time_total": "9.13 us", "time_pct": "0.0001", "time_max": "547.24 ns" },
{ "wait": "synch/mutex/sql/THD::LOCK_thd_data", "count": 87, "time_total": "7.04 us", "time_pct": "0.0001", "time_max": "224.21 ns" },
{ "wait": "synch/mutex/sql/THD::LOCK_thd_query", "count": 70, "time_total": "5.06 us", "time_pct": "0.0001", "time_max": "187.92 ns" },
{ "wait": "synch/mutex/innodb/trx_undo_mutex", "count": 25, "time_total": "2.15 us", "time_pct": "0.0000", "time_max": "230.04 ns" }
]
},
"user_variables": [
{ }
]
}
This is a snapshot of one of the connections from a MySQL Enterprise Monitor server, with this particular connection having inserted some data related to the Query Analyzer, with one past transaction that inserted a normalized and example statement in a single transaction with a final commit, and currently inserting another normalized statement.
Because it is currently executing an INSERT on the `memtrunkio__quan`.`normalized_statements_by_server_by_schema` table, you can also see that it holds a SHARED_WRITE metadata lock (for the duration of the TRANSACTION) on that table, and holds a table handle on that table as well.
Finally, you can see a summary of all of that connections memory usage, and timing information for both stages and lower level waits for those transactions and statements that it has executed.
Whilst developing this output, I’ve been using it almost exclusively against our own MEM schema. In the process it’s managed to help me find some interesting bugs. For instance, here’s a previous incarnation of that output, that helped find a bug where we were not committing between DELETE statements when purging data from all of our instrument tables. Ultimately this meant we were holding open huge transactions, with many many metadata locks being held across all of the instrument tables:
session_info:
{
user: "mem@localhost",
thd_id: 86676,
current_statement: "",
last_statements: [
{"/* mem dbpool.default */ SET foreign_key_checks=1"},
{"/* mem dbpool.default */ SET foreign_key_checks=0"},
{"/* mem dbpool.default */ DELETE FROM `mem__instruments`.`QueryCacheFragmentationData` WHERE `timestamp` < 1393598543538 LIMIT 1000"},
{"/* mem dbpool.default */ SET foreign_key_checks=1"},
{"/* mem dbpool.default */ SET foreign_key_checks=0"},
{"/* mem dbpool.default */ DELETE FROM `mem__instruments`.`ClusterDataNodeRedoLogspaceUsageData` WHERE `timestamp` < 1393598543538 LIMIT 1000"},
{"/* mem dbpool.default */ SET foreign_key_checks=1"},
{"/* mem dbpool.default */ SET foreign_key_checks=0"},
{"/* mem dbpool.default */ DELETE FROM `mem__instruments`.`PreparedStatementUtilizationData` WHERE `timestamp` < 1393598543539 LIMIT 1000"},
{"/* mem dbpool.default */ SET foreign_key_checks=1"}
],
metadata_locks: [
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.preparedstatementutilizationdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.clusterdatanoderedologspaceusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.querycachefragmentationdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.semisyncmastertransactionsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbredologiousagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.connectionsaborteddata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbrowdetailsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.semisyncmasterwaitsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.querycachequeriesincachedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.rowaccessesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.tablelocksdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.agentluamemusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.cpupercentage" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.avgrowaccessesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.temporarytablesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbrowlocktimedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.querycachememorydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.rowwritesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.clusterdiskpagebufferhitratiodata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.clusterdatanodesinreadystatedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.connectionsmaxdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.inventorystatisticssummarizeddata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.threadpoolqueriesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbrowlockdetailsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.binlogcachedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.slaverelaylogspaceusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbsemaphoresdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.diskiototaldata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.loadaveragedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbcheckpointagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.querycacheaveragefreeblocksizedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.querycachelowmemprunesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.rowsreturneddata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.httpbytes" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.hitratiosdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.mysqlconnectionoperationsstatsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.myisamkeybufferactivitydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.diskioopstotaldata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.supportdiagnosticsadvisor_variables" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbadaptivehashsearchesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbbufferpoolactivitydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.querycacheefficiencydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.binlogiousagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.httpcounts_ssl" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.statementstatisticsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbdatafileiousagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.semisyncmasterwaitingsessionsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.connectionpooldata_uipool" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.clusterdatanodeundobufferusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.kbytesinoutdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.agentlatencytime" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.jvmmemoryusage" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.clusterdatanodeundologspaceusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.preparedstatementsqldata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.lockwaitratiodata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.httpclientactivity" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.httptimes_ssl" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.ramusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.databasetransactionsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.statementerrorsandwarningsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.slavesecondsbehinddata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.binlogspaceusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbdatadictionarymemorydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.ehcachebacklogactivity" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbbufferpoolpendingopsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.threadpoolqueueagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbchangebufferusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.jvmgctime" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.httpcounts" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbchangebufferactivitydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.jvmgccounts" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.clusterdatanodedatamemoryusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbtransactionsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.mebruntime" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.assetselectorcachesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.cpuaverage" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.httptimes" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.threadpoolqueuesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.myisamindexfileiousagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbrowlocktimestatisticsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.myisamkeybufferusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.preparedstatementapidata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbadaptivehashmemorydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.openedtablesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.threadcachedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.slowqueriesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.networktrafficadvisor_networktraffic" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.threadpoolqueriesstalleddata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodblockmemorydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.clusterdatanoderedobufferusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbcompressiontimedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.connectionpooldata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbrowlockwaitsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.qrtidata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbundologsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.swapioopsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.connectionsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.rowscanratiodata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.clusterdatanodeindexmemoryusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.purgeoperationsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.sortingdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.swapusagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.threadpoolcurrentthreadsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.mysqlprocessactivity" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbdoublewritebufferactivitydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.fsstatistics" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbpendinglogwritesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.querycacheaveragequerysizedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbhistlengthdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.preparedstatementapiinvalidationsdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.myisamdatafileiousagedata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbosfileaccessdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbbufferpooldata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.databaseactivitydata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.semisyncmasteravgwaittimesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__instruments.innodbopenfilesdata" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__quan.explains" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__quan.histograms" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__quan.normalized_statements_by_server_by_schema_data" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__quan.explain_stages" },
{ lock_type: "SHARED_WRITE", lock_duration: "TRANSACTION", lock_status: "GRANTED", scope: "mem__quan.example_statements" }
],
memory: [
{ type: "sql/NET::buff", count: "1", allocated: "16.01 KiB", total_allocated: "16.01 KiB" },
{ type: "sql/String::value", count: "1", allocated: "16.00 KiB", total_allocated: "32.05 KiB" },
{ type: "mysys/array_buffer", count: "7", allocated: "8.98 KiB", total_allocated: "9.11 KiB" },
{ type: "sql/thd::main_mem_root", count: "1", allocated: "8.02 KiB", total_allocated: "1.42 MiB" },
{ type: "sql/THD::transactions::mem_root", count: "1", allocated: "4.02 KiB", total_allocated: "4.02 KiB" },
{ type: "vio/vio", count: "1", allocated: "488 bytes", total_allocated: "488 bytes" },
{ type: "sql/THD::Session_tracker", count: "6", allocated: "209 bytes", total_allocated: "209 bytes" },
{ type: "sql/THD::variables", count: "1", allocated: "64 bytes", total_allocated: "64 bytes" },
{ type: "sql/TABLE", count: "0", allocated: "26 bytes", total_allocated: "25.82 KiB" },
{ type: "sql/Security_context", count: "1", allocated: "10 bytes", total_allocated: "10 bytes" },
{ type: "sql/THD::Session_sysvar_resource_manager", count: "1", allocated: "8 bytes", total_allocated: "8 bytes" },
{ type: "sql/MPVIO_EXT::auth_info", count: "1", allocated: "4 bytes", total_allocated: "4 bytes" },
{ type: "sql/THD::db", count: "1", allocated: "4 bytes", total_allocated: "4 bytes" },
{ type: "myisam/record_buffer", count: "0", allocated: "0 bytes", total_allocated: "1.37 KiB" },
{ type: "myisam/MI_INFO", count: "0", allocated: "0 bytes", total_allocated: "6.44 KiB" },
{ type: "myisam/MYISAM_SHARE", count: "0", allocated: "0 bytes", total_allocated: "8.36 KiB" },
{ type: "mysys/my_file_info", count: "0", allocated: "0 bytes", total_allocated: "584 bytes" },
{ type: "mysys/IO_CACHE", count: "0", allocated: "0 bytes", total_allocated: "32.00 KiB" },
{ type: "sql/MYSQL_LOCK", count: "0", allocated: "0 bytes", total_allocated: "11.23 KiB" },
{ type: "sql/my_bitmap_map", count: "0", allocated: "0 bytes", total_allocated: "648 bytes" },
{ type: "sql/SQL_SELECT::test_quick_select", count: "0", allocated: "0 bytes", total_allocated: "603.25 KiB" },
{ type: "sql/QUICK_RANGE_SELECT::alloc", count: "0", allocated: "0 bytes", total_allocated: "583.41 KiB" }
],
stage_summary: [
{ stage: "starting", count: "486", total_time: "122.07 ms", max_time: "26.19 ms" },
{ stage: "updating", count: "146", total_time: "14.52 ms", max_time: "11.06 ms" },
{ stage: "statistics", count: "40", total_time: "10.23 ms", max_time: "8.18 ms" },
{ stage: "freeing items", count: "485", total_time: "8.20 ms", max_time: "133.35 us" },
{ stage: "System lock", count: "196", total_time: "4.34 ms", max_time: "163.46 us" },
{ stage: "Sending data", count: "40", total_time: "3.79 ms", max_time: "1.60 ms" },
{ stage: "init", count: "196", total_time: "2.82 ms", max_time: "212.24 us" },
{ stage: "Opening tables", count: "442", total_time: "2.54 ms", max_time: "48.02 us" },
{ stage: "removing tmp table", count: "2", total_time: "1.52 ms", max_time: "955.25 us" },
{ stage: "update", count: "10", total_time: "983.24 us", max_time: "281.10 us" },
{ stage: "closing tables", count: "485", total_time: "747.98 us", max_time: "27.34 us" },
{ stage: "query end", count: "485", total_time: "489.16 us", max_time: "4.79 us" },
{ stage: "end", count: "196", total_time: "409.23 us", max_time: "63.80 us" },
{ stage: "cleaning up", count: "486", total_time: "363.86 us", max_time: "4.67 us" },
{ stage: "checking permissions", count: "205", total_time: "340.21 us", max_time: "6.87 us" },
{ stage: "preparing", count: "40", total_time: "257.71 us", max_time: "20.84 us" },
{ stage: "optimizing", count: "40", total_time: "182.29 us", max_time: "10.39 us" },
{ stage: "Creating tmp table", count: "2", total_time: "75.55 us", max_time: "38.71 us" },
{ stage: "executing", count: "40", total_time: "15.72 us", max_time: "1.21 us" }
]
}
It’s been an eye opener for many of our transaction semantics (especially as we use Hibernate, it’s not always clear what is happening under the covers).
I’ve implemented this as a stored function, that takes the MySQL connection id as a parameter to dump the info for. So it can be used as part of any statement against for instance the performance_schema.threads or INFORMATION_SCHEMA.PROCESSLIST tables, such as:
mysql> SELECT sys.ps_thread_info(id) AS thread_info
-> FROM INFORMATION_SCHEMA.PROCESSLIST
-> WHERE Command != 'Sleep'
-> ORDER BY Time DESC\G
*************************** 1. row ***************************
thread_info:
{
"user": "root@localhost",
"thd_id": 122149,
"connection_id": 122127,
"database": "sys",
"current_statement": {
"time": 0,
"rows_examined": 0,
"rows_affected": 0,
"rows_sent": 0,
"tmp_tables": 1,
"tmp_disk_tables": 1,
"sort_rows": 1,
...
You can get a copy of the function here.
I’m considering adding it to the sys schema – what do you think?