Using the MySQL 5.6 Performance Schema it is very easy to see what is actually running on your MySQL instance. No more sampling or installing software or worrying about disk I/O performance with techniques like SHOW PROCESSLIST, enabling the general query log or sniffing the TCP/IP stack.
The following SQL is used to give me a quick 60 second view on a running MySQL system of ALL statements executed.
use performance_schema;
update setup_consumers set enabled='YES' where name IN ('events_statements_history','events_statements_current','statements_digest');
truncate table events_statements_current; truncate table events_statements_history; truncate table events_statements_summary_by_digest;
do sleep(60);
select now(),(count_star/(select sum(count_star) FROM events_statements_summary_by_digest) * 100) as pct, count_star, left(digest_text,150) as stmt, digest from events_statements_summary_by_digest order by 2 desc;
update setup_consumers set enabled='NO' where name IN ('events_statements_history','events_statements_current','statements_digest');
NOTE: These statements are for simple debugging and demonstration purposes. If you want to monitor SQL statements on an ongoing basis, you should not simply truncate tables and globally enable/disable options.
There are four performance schema tables that are applicable for looking at initial SQL analysis.
- The events_statements_summary_by_digest table shown below gives as the name suggests a way to summarize all queries into a common query pattern (or digest). This is great to get a picture of volume and frequency of SQL statements.
- The events_statements_current shows the currently running SQL statements
- The events_statements_history shows the fun, because it provides a *short, default 10 threads* history of the SQL statements that have run in any given thread.
- The events_statements_history_long (when enabled) gives you a history of the most recent 10,000 events.
One query can give me a detailed review of the type and frequency of ALL SQL statements run. The ALL is important, because on a slave you also get ALL replication applied events.
mysql> select now(),(count_star/(select sum(count_star) FROM events_statements_summary_by_digest) * 100) as pct, count_star, left(digest_text,150) as stmt, digest from events_statements_summary_by_digest order by 2 desc; select * from events_statements_current where digest='ffb6231b78efc022175650d37a837b99'G
+---------------------+---------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+ | now() | pct | count_star | stmt | digest | +---------------------+---------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+ | 2013-11-07 18:24:46 | 60.6585 | 7185 | SELECT * FROM `D.....` WHERE `name` = ? | d6399273d75e2348d6d7ea872489a30c | | 2013-11-07 18:24:46 | 23.4192 | 2774 | SELECT nc . id , nc . name FROM A.................. anc JOIN N........... nc ON anc . ............_id = nc . id WHERE ......._id = ? | c6e2249eb91767aa09945cbb118adbb3 | | 2013-11-07 18:24:46 | 5.5298 | 655 | BEGIN | 7519b14a899fd514365211a895f5e833 | | 2013-11-07 18:24:46 | 4.6180 | 547 | INSERT INTO V........ VALUES (...) ON DUPLICATE KEY UPDATE v.... = v.... + ? | ffb6231b78efc022175650d37a837b99 | | 2013-11-07 18:24:46 | 1.0891 | 129 | SELECT COUNT ( * ) FROM T............... WHERE rule = ? AND ? LIKE concat ( pattern , ? ) | 22d984df583adc9a1ac282239e7629e2 | | 2013-11-07 18:24:46 | 1.0553 | 125 | SELECT COUNT ( * ) FROM T............... WHERE rule = ? AND ? LIKE concat ( ? , pattern , ? ) | a8ee43287bb2ee35e2c144c569a8b2de | | 2013-11-07 18:24:46 | 0.9033 | 107 | INSERT IGNORE INTO `K......` ( `id` , `k......` ) VALUES (...) | 675e32e9eac555f33df240e80305c013 | | 2013-11-07 18:24:46 | 0.7936 | 94 | SELECT * FROM `K......` WHERE k...... IN (...) | 8aa7dc3b6f729aec61bd8d7dfa5978fa | | 2013-11-07 18:24:46 | 0.4559 | 54 | SELECT COUNT ( * ) FROM D..... WHERE NAME = ? OR NAME = ? | 1975f53832b0c2506de482898cf1fd37 | | 2013-11-07 18:24:46 | 0.3208 | 38 | SELECT h . * FROM H........ h LEFT JOIN H............ ht ON h . id = ht . ......_id WHERE ht . ........._id = ? ORDER BY h . level ASC | ca838db99e40fdeae920f7feae99d19f | | 2013-11-07 18:24:46 | 0.2702 | 32 | SELECT h . * , ( POW ( ? * ( lat - - ? ) , ? ) + POW ( ? * ( ? - lon ) * COS ( lat / ? ) , ? ) ) AS distance FROM H........ h FORCE INDEX ( lat ) WHER | cd6e32fc0a20fab32662e2b0a282845c | | 2013-11-07 18:24:46 | 0.1857 | 22 | SELECT h . * , ( POW ( ? * ( lat - ? ) , ? ) + POW ( ? * ( - ? - lon ) * COS ( lat / ? ) , ? ) ) AS distance FROM H........ h FORCE INDEX ( lat ) WHER | a7b43944f5811ef36c0ded7e79793536 | | 2013-11-07 18:24:46 | 0.0760 | 9 | SELECT h . * , ( POW ( ? * ( lat - ? ) , ? ) + POW ( ? * ( ? - lon ) * COS ( lat / ? ) , ? ) ) AS distance FROM H........ h FORCE INDEX ( lat ) WHERE | 4ccd8b28ae9e87a9c0b372a58ca22af7 | | 2013-11-07 18:24:46 | 0.0169 | 2 | SELECT * FROM `K......` WHERE k...... IN (?) | 44286e824d922d8e2ba6d993584844fb | | 2013-11-07 18:24:46 | 0.0084 | 1 | SELECT h . * , ( POW ( ? * ( lat - - ? ) , ? ) + POW ( ? * ( - ? - lon ) * COS ( lat / ? ) , ? ) ) AS distance FROM H........ h FORCE INDEX ( lat ) WH | 299095227a67d99824af2ba012b81633 | | 2013-11-07 18:24:46 | 0.0084 | 1 | SELECT * FROM `H........` WHERE `id` = ? | 2924ea1d925a6e158397406403a63e3a | | 2013-11-07 18:24:46 | 0.0084 | 1 | SHOW ENGINE INNODB STATUS | 0b04d3acd555401f1cbc479f920b1bac | | 2013-11-07 18:24:46 | 0.0084 | 1 | DO `sleep` (?) | 3d6e973c2657d0d136bbbdad05e68c7a | | 2013-11-07 18:24:46 | 0.0084 | 1 | SHOW ENGINE INNODB MUTEX | a031f0e6068cb12c5b7508106687c2cb | | 2013-11-07 18:24:46 | 0.0084 | 1 | SELECT NOW ( ) , ( `count_star` / ( SELECT SUM ( `count_star` ) FROM `events_statements_summary_by_digest` ) * ? ) AS `pct` , `count_star` , LEFT ( `d | 8a9e990cd85d6c42a2e537d04c8c5910 | | 2013-11-07 18:24:46 | 0.0084 | 1 | SHOW SLAVE STATUS | d2a0ffb1232f2704cef785f030306603 | | 2013-11-07 18:24:46 | 0.0084 | 1 | TRUNCATE TABLE `events_statements_summary_by_digest` | a7bef5367816ca771571e648ba963515 | | 2013-11-07 18:24:46 | 0.0084 | 1 | UPDATE `setup_consumers` SET `enabled` = ? WHERE NAME IN (...) | 8205ea424267a604a3a4f68a76bc0bbb | | 2013-11-07 18:24:46 | 0.0084 | 1 | SHOW GLOBAL STATUS | ddf94d7d7b176021b8586a3cce1e85c9 | +---------------------+---------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+
This immediately shows me a single simple application query that is executed 60% of the time. Further review of the data and usage pattern shows that should be cached. This is an immediate improvement on system scalability.
While you can look at the raw performance schema data, using ps_helper from Mark Leith makes live easier using the statement_analysis view because of normalizing timers into human readable formats (check out lock_latency).
mysql> select * from ps_helper.statement_analysis order by exec_count desc limit 10; +-------------------------------------------------------------------+-----------+------------+-----------+------------+---------------+-------------+-------------+--------------+-----------+---------------+--------------+------------+-----------------+-------------+-------------------+----------------------------------+ | query | full_scan | exec_count | err_count | warn_count | total_latency | max_latency | avg_latency | lock_latency | rows_sent | rows_sent_avg | rows_scanned | tmp_tables | tmp_disk_tables | rows_sorted | sort_merge_passes | digest | +-------------------------------------------------------------------+-----------+------------+-----------+------------+---------------+-------------+-------------+--------------+-----------+---------------+--------------+------------+-----------------+-------------+-------------------+----------------------------------+ | CREATE VIEW `io_by_thread_by_l ... SUM ( `sum_timer_wait` ) DESC | | 146117 | 0 | 0 | 00:01:47.36 | 765.11 ms | 734.74 us | 00:01:02.00 | 3 | 0 | 3 | 0 | 0 | 0 | 0 | c877ec02dce17ea0aca2f256e5b9dc70 | | SELECT nc . id , nc . name FRO ... nc . id WHERE ......._id = ? | | 41394 | 0 | 0 | 16.85 s | 718.37 ms | 407.00 us | 5.22 s | 155639 | 4 | 312077 | 0 | 0 | 0 | 0 | c6e2249eb91767aa09945cbb118adbb3 | | BEGIN | | 16281 | 0 | 0 | 223.24 ms | 738.82 us | 13.71 us | 0 ps | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 7519b14a899fd514365211a895f5e833 | | INSERT INTO V........ VALUES ( ... KEY UPDATE v.... = v.... + ? | | 12703 | 0 | 0 | 1.73 s | 34.23 ms | 136.54 us | 696.50 ms | 0 | 0 | 0 | 0 | 0 | 0 | 0 | ffb6231b78efc022175650d37a837b99 | | SELECT * FROM `D.....` WHERE `name` = ? | | 10620 | 0 | 0 | 3.85 s | 25.21 ms | 362.52 us | 705.16 ms | 1 | 0 | 1 | 0 | 0 | 0 | 0 | d6399273d75e2348d6d7ea872489a30c | | SELECT COUNT ( * ) FROM T..... ... ? LIKE concat ( pattern , ? ) | | 2830 | 0 | 0 | 1.22 s | 2.14 ms | 432.60 us | 215.62 ms | 2830 | 1 | 101880 | 0 | 0 | 0 | 0 | 22d984df583adc9a1ac282239e7629e2 | | SELECT COUNT ( * ) FROM T..... ... KE concat ( ? , pattern , ? ) | | 2727 | 0 | 0 | 932.01 ms | 30.95 ms | 341.77 us | 189.47 ms | 2727 | 1 | 38178 | 0 | 0 | 0 | 0 | a8ee43287bb2ee35e2c144c569a8b2de | | INSERT IGNORE INTO `K......` ( `id` , `k......` ) VALUES (...) | | 2447 | 0 | 0 | 499.33 ms | 9.65 ms | 204.06 us | 108.28 ms | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 675e32e9eac555f33df240e80305c013 | | SELECT * FROM `K......` WHERE k...... IN (...) | | 2237 | 0 | 0 | 1.58 s | 62.33 ms | 704.19 us | 345.61 ms | 59212 | 26 | 59212 | 0 | 0 | 0 | 0 | 8aa7dc3b6f729aec61bd8d7dfa5978fa | | SELECT COUNT ( * ) FROM D..... WHERE NAME = ? OR NAME = ? | | 1285 | 0 | 0 | 797.72 ms | 131.29 ms | 620.79 us | 340.45 ms | 1285 | 1 | 8 | 0 | 0 | 0 | 0 | 1975f53832b0c2506de482898cf1fd37 | +-------------------------------------------------------------------+-----------+------------+-----------+------------+---------------+-------------+-------------+--------------+-----------+---------------+--------------+------------+-----------------+-------------+-------------------+----------------------------------+
Indeed, this simple query highlights a pile of additional information necessary for analysis like:
- What is that CREATE VIEW command that’s executed many more times?
- In this view, query 2 is executed some 3x more then query 4, yet in my 60 second sample it was 3x less. Has the profile of query load changed. What exactly is being sampled in this view?
- The lock_latency shows some incredibility large lock times, over 5 seconds for the top SELECT statement. Is this an outlier. Unfortunately the views give min/avg/max for the total_latency but no breakdown on lock_latency to see how much of a problem this actually is?
A quick note, the statement_analysis_raw view gives you the full SQL statement, so for example the first point listed the statement actually was.
select query from ps_helper.statement_analysis_raw order by exec_count desc limit 1; CREATE VIEW `io_by_thread_by_latency` AS SELECT IF ( `processlist_id` IS NULL , `SUBSTRING_INDEX` ( NAME , ? , - ? ) , `CONCAT` ( `processlist_user` , ? , `processlist_host` ) ) SYSTEM_USER , SUM ( `count_star` ) `count_star` , `format_time` ( SUM ( `sum_timer_wait` ) ) `total_latency` , `format_time` ( MIN ( `min_timer_wait` ) ) `min_latency` , `format_time` ( AVG ( `avg_timer_wait` ) ) `avg_latency` , `format_time` ( MAX ( `max_timer_wait` ) ) `max_latency` , `thread_id` , `processlist_id` FROM `performance_schema` . `events_waits_summary_by_thread_by_event_name` LEFT JOIN `performance_schema` . `threads` USING ( `thread_id` ) WHERE `event_name` LIKE ? AND `sum_timer_wait` > ? GROUP BY `thread_id` ORDER BY SUM ( `sum_timer_wait` ) DESC