Introduction
This paper is an introduction to the new 'performance schema' feature, which will be part of the upcoming MySQL 5.5 release. Covering in details every part of the performance schema would require much, much more than a simple article. The pace of this teaser is voluntarily fast, to have a quick overview of the new landscape, and help users already familiar with MySQL to understand by examples what the performance schema provides.
Please refer to the online documentation in the MySQL manual for more content.
Basic setup
Let's start a server, and a client connection for monitoring.
mysql> select version(); +---------------------+ | version() | +---------------------+ | 5.5.99-m3-debug-log | +---------------------+ 1 row in set (0.00 sec) mysql> prompt Monitor> ; PROMPT set to 'Monitor> ' Monitor>
Start two other clients, and set the prompt to identify them.
mysql> select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 2 | +-----------------+ 1 row in set (0.00 sec) mysql> prompt Client A (ID 2)> ; PROMPT set to 'Client A (ID 2)> ' Client A (ID 2)>
mysql> select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 3 | +-----------------+ 1 row in set (0.00 sec) mysql> prompt Client B (ID 3)> ; PROMPT set to 'Client B (ID 3)> ' Client B (ID 3)>
Performance schema visible artifacts
There is a new storage engine.
Monitor> show engines;
+--------------------+---------+----------------------------------------------------------------+--------------+------+------------+
| Engine | Support | Comment | Transactions | XA | Savepoints |
+--------------------+---------+----------------------------------------------------------------+--------------+------+------------+
| ndbcluster | NO | Clustered, fault-tolerant tables | NULL | NULL | NULL |
| MRG_MYISAM | YES | Collection of identical MyISAM tables | NO | NO | NO |
| MEMORY | YES | Hash based, stored in memory, useful for temporary tables | NO | NO | NO |
| BLACKHOLE | YES | /dev/null storage engine (anything you write to it disappears) | NO | NO | NO |
| CSV | YES | CSV storage engine | NO | NO | NO |
| MyISAM | DEFAULT | Default engine as of MySQL 3.23 with great performance | NO | NO | NO |
| ARCHIVE | YES | Archive storage engine | NO | NO | NO |
| FEDERATED | NO | Federated MySQL storage engine | NULL | NULL | NULL |
| PERFORMANCE_SCHEMA | YES | Performance Schema | NO | NO | NO |
| InnoDB | NO | Supports transactions, row-level locking, and foreign keys | NULL | NULL | NULL |
+--------------------+---------+----------------------------------------------------------------+--------------+------+------------+
10 rows in set (0.00 sec)
There is a new database.
Monitor> show databases;
+--------------------+
| Database |
+--------------------+
| information_schema |
| mtr |
| mysql |
| performance_schema |
| test |
+--------------------+
5 rows in set (0.00 sec)
Some new system variables are also available. Every system variable can be set on the server command line options, or set in the my.cnf configuration file.
Monitor> show variables like "performance_schema%"; +---------------------------------------------------+--------+ | Variable_name | Value | +---------------------------------------------------+--------+ | performance_schema | ON | | performance_schema_events_waits_history_long_size | 10000 | | performance_schema_events_waits_history_size | 10 | | performance_schema_max_cond_classes | 80 | | performance_schema_max_cond_instances | 1000 | | performance_schema_max_file_classes | 50 | | performance_schema_max_file_handles | 32768 | | performance_schema_max_file_instances | 10000 | | performance_schema_max_mutex_classes | 200 | | performance_schema_max_mutex_instances | 1000 | | performance_schema_max_rwlock_classes | 20 | | performance_schema_max_rwlock_instances | 1000 | | performance_schema_max_table_handles | 100000 | | performance_schema_max_table_instances | 50000 | | performance_schema_max_thread_classes | 50 | | performance_schema_max_thread_instances | 1000 | +---------------------------------------------------+--------+ 16 rows in set (0.01 sec)
There are also status variables, to inspect the internal performance schema status.
Monitor> show status like "performance_schema%"; +------------------------------------------+-------+ | Variable_name | Value | +------------------------------------------+-------+ | Performance_schema_cond_classes_lost | 0 | | Performance_schema_cond_instances_lost | 0 | | Performance_schema_file_classes_lost | 0 | | Performance_schema_file_handles_lost | 0 | | Performance_schema_file_instances_lost | 0 | | Performance_schema_locker_lost | 0 | | Performance_schema_mutex_classes_lost | 0 | | Performance_schema_mutex_instances_lost | 0 | | Performance_schema_rwlock_classes_lost | 0 | | Performance_schema_rwlock_instances_lost | 0 | | Performance_schema_table_handles_lost | 0 | | Performance_schema_table_instances_lost | 0 | | Performance_schema_thread_classes_lost | 0 | | Performance_schema_thread_instances_lost | 0 | +------------------------------------------+-------+ 14 rows in set (0.00 sec)
SHOW ENGINE STATUS can also be used to inspect the performance schema internal state.
Monitor> show engine PERFORMANCE_SCHEMA status; +--------------------+--------------------------------------------------------+----------+ | Type | Name | Status | +--------------------+--------------------------------------------------------+----------+ | performance_schema | EVENTS_WAITS_CURRENT.ROW_SIZE | 136 | | performance_schema | EVENTS_WAITS_CURRENT.ROW_COUNT | 3000 | | performance_schema | EVENTS_WAITS_HISTORY.ROW_SIZE | 120 | | performance_schema | EVENTS_WAITS_HISTORY.ROW_COUNT | 10000 | | performance_schema | EVENTS_WAITS_HISTORY.MEMORY | 1200000 | | performance_schema | EVENTS_WAITS_HISTORY_LONG.ROW_SIZE | 120 | | performance_schema | EVENTS_WAITS_HISTORY_LONG.ROW_COUNT | 10000 | | performance_schema | EVENTS_WAITS_HISTORY_LONG.MEMORY | 1200000 | | performance_schema | (PFS_MUTEX_CLASS).ROW_SIZE | 248 | | performance_schema | (PFS_MUTEX_CLASS).ROW_COUNT | 200 | | performance_schema | (PFS_MUTEX_CLASS).MEMORY | 49600 | ... | performance_schema | EVENTS_WAITS_SUMMARY_BY_THREAD_BY_EVENT_NAME.ROW_SIZE | 48 | | performance_schema | EVENTS_WAITS_SUMMARY_BY_THREAD_BY_EVENT_NAME.ROW_COUNT | 350000 | | performance_schema | EVENTS_WAITS_SUMMARY_BY_THREAD_BY_EVENT_NAME.MEMORY | 16800000 | | performance_schema | PERFORMANCE_SCHEMA.MEMORY | 26459600 | +--------------------+--------------------------------------------------------+----------+ 45 rows in set (0.00 sec)
Let's see what is in the new performance_schema database ...
Monitor> use performance_schema; Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Database changed Monitor> show tables; +----------------------------------------------+ | Tables_in_performance_schema | +----------------------------------------------+ | COND_INSTANCES | | EVENTS_WAITS_CURRENT | | EVENTS_WAITS_HISTORY | | EVENTS_WAITS_HISTORY_LONG | | EVENTS_WAITS_SUMMARY_BY_EVENT_NAME | | EVENTS_WAITS_SUMMARY_BY_INSTANCE | | EVENTS_WAITS_SUMMARY_BY_THREAD_BY_EVENT_NAME | | FILE_INSTANCES | | FILE_SUMMARY_BY_EVENT_NAME | | FILE_SUMMARY_BY_INSTANCE | | MUTEX_INSTANCES | | PERFORMANCE_TIMERS | | PROCESSLIST | | RWLOCK_INSTANCES | | SETUP_CONSUMERS | | SETUP_INSTRUMENTS | | SETUP_OBJECTS | | SETUP_TIMERS | +----------------------------------------------+ 18 rows in set (0.00 sec)
What is instrumented in the code ?
The available instrumentation is discovered dynamically.
Monitor> select * from SETUP_INSTRUMENTS; +------------------------------------------------------------+---------+-------+ | NAME | ENABLED | TIMED | +------------------------------------------------------------+---------+-------+ | wait/synch/mutex/sql/PAGE::lock | YES | YES | | wait/synch/mutex/sql/TC_LOG_MMAP::LOCK_sync | YES | YES | | wait/synch/mutex/sql/TC_LOG_MMAP::LOCK_active | YES | YES | | wait/synch/mutex/sql/TC_LOG_MMAP::LOCK_pool | YES | YES | | wait/synch/mutex/sql/LOCK_des_key_file | YES | YES | | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_index | YES | YES | | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_prep_xids | YES | YES | | wait/synch/mutex/sql/Delayed_insert::mutex | YES | YES | ... | wait/synch/rwlock/sql/LOCK_grant | YES | YES | | wait/synch/rwlock/sql/LOGGER::LOCK_logger | YES | YES | | wait/synch/rwlock/sql/LOCK_sys_init_connect | YES | YES | | wait/synch/rwlock/sql/LOCK_sys_init_slave | YES | YES | | wait/synch/rwlock/sql/LOCK_system_variables_hash | YES | YES | | wait/synch/rwlock/sql/Query_cache_query::lock | YES | YES | | wait/synch/rwlock/sql/LOCK_dboptions | YES | YES | | wait/synch/rwlock/myisam/MYISAM_SHARE::key_root_lock | YES | YES | | wait/synch/rwlock/myisam/MYISAM_SHARE::mmap_lock | YES | YES | ... | wait/synch/cond/sql/COND_flush_thread_cache | YES | YES | | wait/synch/cond/mysys/COND_alarm | YES | YES | | wait/synch/cond/mysys/IO_CACHE_SHARE::cond | YES | YES | | wait/synch/cond/mysys/IO_CACHE_SHARE::cond_writer | YES | YES | | wait/synch/cond/mysys/my_thread_var::suspend | YES | YES | | wait/synch/cond/mysys/THR_COND_threads | YES | YES | ... | wait/io/file/csv/metadata | YES | YES | | wait/io/file/csv/data | YES | YES | | wait/io/file/csv/update | YES | YES | | wait/io/file/myisam/data_tmp | YES | YES | | wait/io/file/myisam/dfile | YES | YES | | wait/io/file/myisam/kfile | YES | YES | | wait/io/file/myisam/log | YES | YES | | wait/io/file/myisammrg/MRG | YES | YES | +------------------------------------------------------------+---------+-------+ 167 rows in set (0.00 sec)
So, for this platform, 167 artifacts in the server and storage engines are instrumented. Let's see the breakdown by type.
Monitor> select count(*) from SETUP_INSTRUMENTS where name like 'wait/synch/mutex/%'; +----------+ | count(*) | +----------+ | 84 | +----------+ 1 row in set (0.00 sec) Monitor> select count(*) from SETUP_INSTRUMENTS where name like 'wait/synch/cond/%'; +----------+ | count(*) | +----------+ | 35 | +----------+ 1 row in set (0.00 sec) Monitor> select count(*) from SETUP_INSTRUMENTS where name like 'wait/synch/rwlock/%'; +----------+ | count(*) | +----------+ | 11 | +----------+ 1 row in set (0.00 sec) Monitor> select count(*) from SETUP_INSTRUMENTS where name like 'wait/io/file/%'; +----------+ | count(*) | +----------+ | 37 | +----------+ 1 row in set (0.00 sec)
What is running inside the server ?
The existing SHOW PROCESSLIST command can be used to see that ...
Monitor> show processlist; +----+------+-----------+--------------------+---------+------+-------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+------+-----------+--------------------+---------+------+-------+------------------+ | 1 | root | localhost | performance_schema | Query | 0 | NULL | show processlist | | 2 | root | localhost | NULL | Sleep | 3459 | | NULL | | 3 | root | localhost | NULL | Sleep | 3386 | | NULL | +----+------+-----------+--------------------+---------+------+-------+------------------+ 3 rows in set (0.00 sec)
Ok, nice try. Now, what is really running in the server ?
Monitor> select * from PROCESSLIST; +-----------+----+---------------------------+ | THREAD_ID | ID | NAME | +-----------+----+---------------------------+ | 0 | 0 | thread/sql/main | | 3 | 2 | thread/sql/one_connection | | 4 | 3 | thread/sql/one_connection | | 2 | 1 | thread/sql/one_connection | | 1 | 0 | thread/sql/signal_handler | +-----------+----+---------------------------+ 5 rows in set (0.00 sec)
Here we see two new threads that were previously hidden. Every thread instrumented in the code is displayed by the performance schema. This include for example, threads used internally by a storage engine.
We know Client A connection_id() is 2, let's find out what thread is executing Client A requests.
Monitor> select * from PROCESSLIST where ID=2; +-----------+----+---------------------------+ | THREAD_ID | ID | NAME | +-----------+----+---------------------------+ | 3 | 2 | thread/sql/one_connection | +-----------+----+---------------------------+ 1 row in set (0.00 sec)
What is this query waiting for, right now ?
First, we need a query that takes some time. For illustration, let's make client A sleep for 10 seconds.
Client A (ID 2)> select sleep(10);
While the query is still executing, see what event the code is waiting for.
Monitor> select * from EVENTS_WAITS_CURRENT where THREAD_ID=3\G
*************************** 1. row ***************************
THREAD_ID: 3
EVENT_ID: 46
EVENT_NAME: wait/synch/cond/sql/Item_func_sleep::cond
SOURCE: item_func.cc:3527
TIMER_START: 5617352941894736
TIMER_END: NULL
TIMER_WAIT: NULL
SPINS: NULL
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_TYPE: NULL
OBJECT_INSTANCE_BEGIN: 139803207157216
NESTING_EVENT_ID: NULL
OPERATION: timed_wait
NUMBER_OF_BYTES: NULL
FLAGS: 0
1 row in set (0.00 sec)
Looking at the results, we can tell that the query is still waiting (TIMER_WAIT is NULL) for an instrumented condition (EVENT_NAME starts with 'wait/synch/cond/'), which is located in the sql layer ('sql/'), and happen to be named 'Item_func_sleep::cond'. The instrumented call is located in file item_func.cc, line 3527 (SOURCE), and the call was a 'timed_wait' (OPERATION).
What are the recent wait events of this connection ?
After the sleep(10) is completed, let's look at the wait history for Client A connection.
Monitor> select THREAD_ID, EVENT_ID, EVENT_NAME, SOURCE, TIMER_WAIT, OBJECT_INSTANCE_BEGIN, OPERATION from EVENTS_WAITS_HISTORY where THREAD_ID=3 order by THREAD_ID, EVENT_ID; +-----------+----------+---------------------------------------------+--------------------+---------------+-----------------------+------------+ | THREAD_ID | EVENT_ID | EVENT_NAME | SOURCE | TIMER_WAIT | OBJECT_INSTANCE_BEGIN | OPERATION | +-----------+----------+---------------------------------------------+--------------------+---------------+-----------------------+------------+ | 3 | 43 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 399243 | 18775392 | lock | | 3 | 44 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:294 | 210035 | 18775392 | lock | | 3 | 45 | wait/synch/mutex/sql/LOCK_user_locks | item_func.cc:3837 | 500907 | 18580768 | lock | | 3 | 46 | wait/synch/cond/sql/Item_func_sleep::cond | item_func.cc:3527 | 5000241974790 | 140221896639968 | timed_wait | | 3 | 47 | wait/synch/cond/sql/Item_func_sleep::cond | item_func.cc:3527 | 5000237350843 | 140221896639968 | timed_wait | | 3 | 48 | wait/synch/mutex/mysys/my_thread_var::mutex | item_func.cc:3853 | 612102 | 19805600 | lock | | 3 | 49 | wait/synch/mutex/sql/LOCK_plugin | sql_plugin.cc:1013 | 356883 | 18701152 | lock | | 3 | 50 | wait/synch/rwlock/sql/LOGGER::LOCK_logger | log.h:582 | 276046 | 18672512 | read_lock | | 3 | 51 | wait/synch/mutex/sql/LOG::LOCK_log | log.cc:2515 | 372062 | 18989864 | lock | | 3 | 52 | wait/synch/mutex/sql/THD::LOCK_thd_data | sql_class.cc:3267 | 276046 | 19798240 | lock | +-----------+----------+---------------------------------------------+--------------------+---------------+-----------------------+------------+ 10 rows in set (0.00 sec)
It seems the wait for 10 seconds was interupted, so the code instead waited twice for 5 seconds, in the timed_wait.
What timer is used to measure all that ?
The performance schema provide different timers, with different characteristics.
Monitor> select * from PERFORMANCE_TIMERS; +-------------+-----------------+------------------+----------------+ | TIMER_NAME | TIMER_FREQUENCY | TIMER_RESOLUTION | TIMER_OVERHEAD | +-------------+-----------------+------------------+----------------+ | CYCLE | 2830706467 | 1 | 43 | | NANOSECOND | NULL | NULL | NULL | | MICROSECOND | 1000000 | 1 | 119 | | MILLISECOND | 1037 | 1 | 128 | | TICK | 103 | 1 | 451 | +-------------+-----------------+------------------+----------------+ 5 rows in set (0.00 sec)
The CYCLE timer shows that this machine has a 2.83 GHz CPU. The NANOSECOND timer is not available. Which timer to pick is configurable.
Monitor> select * from SETUP_TIMERS; +------+------------+ | NAME | TIMER_NAME | +------+------------+ | wait | CYCLE | +------+------------+ 1 row in set (0.00 sec)
Looking at history for a longer period
Let's use a sample scenario to illustrate how to use the history tables. First, we need some objects to use in queries.
Client A (ID 2)> create table test.t1(a int); Query OK, 0 rows affected (0.07 sec) Client A (ID 2)> lock table test.t1 read; Query OK, 0 rows affected (0.00 sec)
Get a timestamp, we will analyse the history from now on.
Monitor> select max(TIMER_START) from EVENTS_WAITS_HISTORY into @marker_begin; Query OK, 1 row affected (0.00 sec) Monitor> select @marker_begin; +------------------+ | @marker_begin | +------------------+ | 2461829402934558 | +------------------+ 1 row in set (0.00 sec)
Now the scenario itself: Client B will try to insert a row, and will be blocked. Client A will then unlock tables, unblocking B, which will finish.
Client B (ID 3)> insert into test.t1 values (1);
Client A (ID 2)> unlock tables; Query OK, 0 rows affected (0.00 sec)
Query OK, 1 row affected (12.98 sec)
Get a timestamp again, and let's see what happened with clients A and B ...
Monitor> select max(TIMER_START) from EVENTS_WAITS_HISTORY into @marker_end;
Query OK, 1 row affected (0.00 sec)
Monitor> select @marker_end;
+------------------+
| @marker_end |
+------------------+
| 2928891716761738 |
+------------------+
1 row in set (0.00 sec)
Monitor> select THREAD_ID, EVENT_ID, EVENT_NAME, SOURCE, TIMER_START, TIMER_WAIT, OBJECT_INSTANCE_BEGIN, OPERATION
-> from EVENTS_WAITS_HISTORY_LONG where (THREAD_ID=3 or THREAD_ID=4) and
-> (TIMER_START > @marker_begin) and (TIMER_START <= @marker_end)
-> order by TIMER_START asc;
+-----------+----------+---------------------------------------------------------+--------------------+------------------+----------------+-----------------------+-----------+
| THREAD_ID | EVENT_ID | EVENT_NAME | SOURCE | TIMER_START | TIMER_WAIT | OBJECT_INSTANCE_BEGIN | OPERATION |
+-----------+----------+---------------------------------------------------------+--------------------+------------------+----------------+-----------------------+-----------+
| 4 | 39 | wait/synch/mutex/sql/THD::LOCK_thd_data | sql_class.cc:3287 | 2612399119180647 | 1338223 | 19855856 | lock |
| 4 | 40 | wait/synch/mutex/sql/THD::LOCK_thd_data | sql_class.cc:3267 | 2612399126078620 | 216036 | 19855856 | lock |
| 4 | 41 | wait/synch/rwlock/sql/LOGGER::LOCK_logger | log.h:582 | 2612399129553199 | 321230 | 18672512 | read_lock |
| 4 | 42 | wait/synch/mutex/sql/LOG::LOCK_log | log.cc:2414 | 2612399134753242 | 458900 | 18988648 | lock |
| 4 | 43 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:294 | 2612399222016607 | 390065 | 18775392 | lock |
| 4 | 44 | wait/synch/rwlock/sql/LOCK_grant | sql_acl.cc:3990 | 2612399231231319 | 144024 | 18595168 | read_lock |
| 4 | 45 | wait/synch/mutex/sql/LOCK_global_read_lock | lock.cc:1513 | 2612399233796570 | 369238 | 18593248 | lock |
| 4 | 46 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 2612399239800747 | 224861 | 18775392 | lock |
| 4 | 47 | wait/synch/mutex/sql/LOCK_open | sql_base.cc:2745 | 2612399244679560 | 318053 | 18592864 | lock |
| 4 | 48 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 2612399248817073 | 213212 | 18775392 | lock |
| 4 | 49 | wait/synch/mutex/sql/TABLE_SHARE::mutex | sql_base.cc:404 | 2612399251601537 | 258043 | 19549224 | lock |
| 4 | 50 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 2612399255052112 | 210035 | 18775392 | lock |
| 4 | 51 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 2612399258115799 | 206858 | 18775392 | lock |
| 4 | 52 | wait/synch/mutex/mysys/THR_LOCK_myisam | mi_open.c:106 | 2612399299375498 | 390065 | 18775520 | lock |
| 4 | 53 | wait/io/file/myisam/dfile | mi_open.c:1271 | 2612399310495351 | 9763627 | 140221840474240 | open |
| 4 | 54 | wait/synch/mutex/mysys/THR_LOCK_open | my_open.c:137 | 2612399317282482 | 429248 | 18775008 | lock |
| 4 | 55 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 2612399318713897 | 212859 | 18775392 | lock |
| 4 | 56 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 2612399322194477 | 206858 | 18775392 | lock |
| 4 | 57 | wait/synch/mutex/myisam/MYISAM_SHARE::intern_lock | mi_open.c:620 | 2612399323862755 | 320877 | 19920280 | lock |
| 4 | 58 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 2612399325593867 | 207211 | 18775392 | lock |
| 4 | 59 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 2612399328546359 | 204034 | 18775392 | lock |
| 4 | 60 | wait/synch/mutex/sql/TABLE_SHARE::mutex | ha_myisam.cc:1712 | 2612399334115287 | 282047 | 19549224 | lock |
| 4 | 61 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:294 | 2612399342195810 | 210035 | 18775392 | lock |
| 4 | 62 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:294 | 2612399364672379 | 255219 | 18775392 | lock |
| 4 | 63 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:181 | 2612399369764404 | 252042 | 18775392 | lock |
| 4 | 64 | wait/synch/mutex/myisam/MYISAM_SHARE::intern_lock | mi_locking.c:53 | 2612399372932932 | 224861 | 19920280 | lock |
| 4 | 65 | wait/synch/mutex/mysys/THR_LOCK::mutex | thr_lock.c:525 | 2612399376764394 | 237216 | 19920048 | lock |
| 4 | 66 | wait/synch/cond/mysys/my_thread_var::suspend | thr_lock.c:444 | 2612399380827071 | 12977803964893 | 19864808 | wait |
| 3 | 199 | wait/synch/mutex/sql/THD::LOCK_thd_data | sql_class.cc:3287 | 2625377031586434 | 1311395 | 19798240 | lock |
| 3 | 200 | wait/synch/mutex/sql/THD::LOCK_thd_data | sql_class.cc:3267 | 2625377038712798 | 212859 | 19798240 | lock |
| 3 | 201 | wait/synch/rwlock/sql/LOGGER::LOCK_logger | log.h:582 | 2625377043456412 | 345234 | 18672512 | read_lock |
| 3 | 202 | wait/synch/mutex/sql/LOG::LOCK_log | log.cc:2414 | 2625377048476425 | 486081 | 18988648 | lock |
| 3 | 203 | wait/synch/mutex/mysys/THR_LOCK::mutex | thr_lock.c:814 | 2625377120023171 | 456076 | 19920048 | lock |
| 3 | 204 | wait/synch/mutex/myisam/MYISAM_SHARE::intern_lock | mi_locking.c:53 | 2625377132169195 | 231215 | 19920280 | lock |
| 3 | 205 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:294 | 2625377136297883 | 231215 | 18775392 | lock |
| 3 | 206 | wait/synch/mutex/sql/LOCK_open | sql_base.cc:1201 | 2625377139598433 | 306051 | 18592864 | lock |
| 3 | 207 | wait/synch/mutex/sql/LOCK_plugin | sql_plugin.cc:1013 | 2625377157094525 | 320877 | 18701152 | lock |
| 3 | 208 | wait/synch/mutex/sql/THD::LOCK_thd_data | sql_class.cc:3267 | 2625377169918662 | 266868 | 19798240 | lock |
| 4 | 67 | wait/synch/mutex/mysys/my_thread_var::mutex | thr_lock.c:503 | 2625377197730120 | 648108 | 19864864 | lock |
| 4 | 68 | wait/synch/rwlock/sql/LOCK_grant | sql_acl.cc:4266 | 2625377233568092 | 450075 | 18595168 | read_lock |
| 4 | 69 | wait/io/file/myisam/kfile | mi_locking.c:548 | 2625377256953989 | 23803143 | 140221840473616 | write |
| 4 | 70 | wait/io/file/myisam/dfile | mi_dynrec.c:233 | 2625377283097522 | 32138179 | 140221840474240 | write |
| 4 | 71 | wait/io/file/myisam/dfile | mi_dynrec.c:233 | 2625377316267873 | 3855819 | 140221840474240 | write |
| 4 | 72 | wait/synch/mutex/sql/Query_cache::structure_guard_mutex | sql_cache.cc:523 | 2625377334778134 | 666111 | 18596216 | lock |
| 4 | 73 | wait/synch/mutex/sql/Query_cache::structure_guard_mutex | sql_cache.cc:545 | 2625377336920491 | 206858 | 18596216 | lock |
| 4 | 74 | wait/synch/mutex/sql/LOCK_global_read_lock | lock.cc:1561 | 2625377342084175 | 342057 | 18593248 | lock |
| 4 | 75 | wait/synch/mutex/sql/LOCK_plugin | sql_plugin.cc:1013 | 2625377346678117 | 416893 | 18701152 | lock |
| 4 | 76 | wait/synch/mutex/mysys/THR_LOCK::mutex | thr_lock.c:814 | 2625377544669110 | 596923 | 19920048 | lock |
| 4 | 77 | wait/synch/mutex/myisam/MYISAM_SHARE::intern_lock | mi_locking.c:53 | 2625377550156848 | 429248 | 19920280 | lock |
| 4 | 78 | wait/synch/mutex/mysys/KEY_CACHE::cache_lock | mf_keycache.c:4115 | 2625377552830470 | 330055 | 18991320 | lock |
| 4 | 79 | wait/io/file/myisam/kfile | mi_open.c:934 | 2625377557658098 | 4545934 | 140221840473616 | write |
| 4 | 80 | wait/synch/mutex/mysys/THR_LOCK_malloc | safemalloc.c:294 | 2625377565252540 | 438073 | 18775392 | lock |
| 4 | 81 | wait/synch/mutex/sql/LOCK_open | sql_base.cc:1201 | 2625377568201855 | 495259 | 18592864 | lock |
| 4 | 82 | wait/synch/mutex/sql/THD::LOCK_thd_data | sql_class.cc:3267 | 2625377578982828 | 336056 | 19855856 | lock |
+-----------+----------+---------------------------------------------------------+--------------------+------------------+----------------+-----------------------+-----------+
54 rows in set (0.02 sec)
Important things to notice:
- client B (thread 4) executes events up to 66, and is blocked for 12 seconds in a wait.
- client A (thread 3) executes events 199 to 208
- client B (thread 4) then resumes execution.
- Both threads are using a mutex named 'MYISAM_SHARE::intern_lock' in myisam.
- Looking at (thread 4, event 64), and (thread 3, event 204), the mutex address is the same (OBJECT_INSTANCE_BEGIN).
There you have it: the two clients were competing on a table lock for a myisam table ... This illustrate that very detailed data can be observed in the performance schema history tables,
What's the big picture ?
The performance schema maintains aggregates from the low level wait events collected, here are sample queries showing aggregates based on different criteria.
Monitor> select * from EVENTS_WAITS_SUMMARY_BY_EVENT_NAME order by SUM_TIMER_WAIT desc limit 20; +---------------------------------------------------+------------+----------------+----------------+----------------+----------------+ | EVENT_NAME | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | +---------------------------------------------------+------------+----------------+----------------+----------------+----------------+ | wait/synch/cond/mysys/my_thread_var::suspend | 1 | 12977803964893 | 12977803964893 | 12977803964893 | 12977803964893 | | wait/io/file/sql/FRM | 605 | 61285161668 | 332879 | 101297787 | 44527633212 | | wait/synch/mutex/mysys/THR_LOCK_malloc | 2676 | 505940427 | 138023 | 189065 | 4560760 | | wait/io/file/myisam/kfile | 82 | 406281114 | 459253 | 4954647 | 187585259 | | wait/io/file/myisam/dfile | 50 | 149008360 | 621280 | 2980167 | 32138179 | | wait/synch/cond/sql/COND_thread_count | 1 | 140672618 | 140672618 | 140672618 | 140672618 | | wait/synch/mutex/sql/THD::LOCK_thd_data | 218 | 105269189 | 156026 | 482886 | 1569438 | | wait/io/file/sql/casetest | 10 | 75699438 | 2265201 | 7569943 | 22200876 | | wait/io/file/sql/pid | 3 | 65458555 | 4716786 | 21819518 | 35012658 | | wait/io/file/sql/ERRMSG | 5 | 58504102 | 1422237 | 11700820 | 23653118 | | wait/synch/mutex/mysys/THR_LOCK_open | 249 | 58411263 | 147201 | 234583 | 636106 | | wait/io/file/sql/dbopt | 9 | 58032847 | 2748458 | 6448094 | 11395899 | | wait/synch/mutex/sql/LOCK_plugin | 271 | 54424481 | 144024 | 200828 | 543267 | | wait/synch/mutex/sql/LOCK_open | 155 | 37872311 | 144024 | 244337 | 630105 | | wait/synch/mutex/mysys/THR_LOCK::mutex | 123 | 29474088 | 141200 | 239626 | 645284 | | wait/io/file/sql/MYSQL_LOG | 4 | 29470558 | 732122 | 7367639 | 15266544 | | wait/io/file/mysys/charset | 3 | 29210044 | 2685624 | 9736681 | 21207534 | | wait/synch/mutex/sql/LOG::LOCK_log | 72 | 23395428 | 234039 | 324936 | 486081 | | wait/synch/rwlock/sql/LOGGER::LOCK_logger | 73 | 18702646 | 117196 | 256200 | 945334 | | wait/synch/mutex/sql/LOCK_global_system_variables | 54 | 13213849 | 152849 | 244700 | 483257 | +---------------------------------------------------+------------+----------------+----------------+----------------+----------------+ 20 rows in set (0.00 sec) Monitor> select * from EVENTS_WAITS_SUMMARY_BY_INSTANCE order by SUM_TIMER_WAIT desc limit 20; +----------------------------------------------+-----------------------+------------+----------------+----------------+----------------+----------------+ | EVENT_NAME | OBJECT_INSTANCE_BEGIN | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | +----------------------------------------------+-----------------------+------------+----------------+----------------+----------------+----------------+ | wait/synch/cond/mysys/my_thread_var::suspend | 19864808 | 1 | 12977803964893 | 12977803964893 | 12977803964893 | 12977803964893 | | wait/io/file/sql/FRM | 140221841262352 | 47 | 60087698477 | 332879 | 1278461669 | 44527633212 | | wait/synch/mutex/mysys/THR_LOCK_malloc | 18775392 | 2704 | 512769918 | 138023 | 189633 | 4560760 | | wait/io/file/myisam/kfile | 140221840473616 | 15 | 267174404 | 705294 | 17811626 | 187585259 | | wait/synch/cond/sql/COND_thread_count | 18595424 | 1 | 140672618 | 140672618 | 140672618 | 140672618 | | wait/synch/mutex/sql/THD::LOCK_thd_data | 19232304 | 183 | 91473949 | 206858 | 499857 | 1626271 | | wait/io/file/myisam/dfile | 140221840474240 | 6 | 68756281 | 3855819 | 11459380 | 32138179 | | wait/io/file/sql/pid | 140221843119376 | 3 | 65458555 | 4716786 | 21819518 | 35012658 | | wait/io/file/sql/FRM | 140221837128352 | 21 | 64639595 | 428895 | 3078075 | 8455409 | | wait/io/file/sql/ERRMSG | 140221837099024 | 5 | 58504102 | 1422237 | 11700820 | 23653118 | | wait/synch/mutex/mysys/THR_LOCK_open | 18775008 | 249 | 58411263 | 147201 | 234583 | 636106 | | wait/io/file/sql/FRM | 140221837118368 | 21 | 57031386 | 411245 | 2715780 | 6571095 | | wait/synch/mutex/sql/LOCK_plugin | 18701152 | 273 | 55084591 | 144024 | 201775 | 543267 | | wait/io/file/sql/FRM | 140221837118992 | 21 | 54062656 | 404891 | 2574412 | 6213859 | | wait/io/file/sql/FRM | 140221837123360 | 21 | 53900982 | 440897 | 2566713 | 5968171 | | wait/io/file/sql/FRM | 140221837125232 | 21 | 52953177 | 399243 | 2521579 | 6217036 | | wait/io/file/sql/FRM | 140221837123984 | 21 | 52554287 | 402067 | 2502585 | 6229038 | | wait/io/file/sql/FRM | 140221837124608 | 21 | 52463213 | 426071 | 2498248 | 6262220 | | wait/io/file/sql/FRM | 140221837119616 | 21 | 52320248 | 414069 | 2491440 | 5970995 | | wait/io/file/sql/FRM | 140221837126480 | 21 | 52121509 | 399243 | 2481976 | 6055009 | +----------------------------------------------+-----------------------+------------+----------------+----------------+----------------+----------------+ 20 rows in set (0.00 sec) Monitor> select * from EVENTS_WAITS_SUMMARY_BY_THREAD_BY_EVENT_NAME order by SUM_TIMER_WAIT desc limit 20; +-----------+----------------------------------------------+------------+----------------+----------------+----------------+----------------+ | THREAD_ID | EVENT_NAME | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | +-----------+----------------------------------------------+------------+----------------+----------------+----------------+----------------+ | 4 | wait/synch/cond/mysys/my_thread_var::suspend | 1 | 12977803964893 | 12977803964893 | 12977803964893 | 12977803964893 | | 3 | wait/io/file/sql/FRM | 35 | 60054668620 | 332879 | 1715847674 | 44527633212 | | 2 | wait/io/file/sql/FRM | 174 | 717013247 | 584921 | 4120765 | 13067354 | | 0 | wait/io/file/sql/FRM | 396 | 513479801 | 384064 | 1296666 | 7093182 | | 0 | wait/synch/mutex/mysys/THR_LOCK_malloc | 1862 | 296733212 | 138023 | 159362 | 1797123 | | 3 | wait/io/file/myisam/kfile | 9 | 223447588 | 999343 | 24827509 | 187585259 | | 2 | wait/synch/mutex/mysys/THR_LOCK_malloc | 763 | 193050758 | 198033 | 253015 | 4560760 | | 0 | wait/synch/cond/sql/COND_thread_count | 1 | 140672618 | 140672618 | 140672618 | 140672618 | | 0 | wait/io/file/myisam/kfile | 67 | 139106710 | 459253 | 2076219 | 5604934 | | 2 | wait/synch/mutex/sql/THD::LOCK_thd_data | 191 | 96076716 | 206858 | 503019 | 1626271 | | 0 | wait/io/file/myisam/dfile | 44 | 80252079 | 621280 | 1823910 | 3555416 | | 0 | wait/io/file/sql/casetest | 10 | 75699438 | 2265201 | 7569943 | 22200876 | | 1 | wait/io/file/sql/pid | 3 | 65458555 | 4716786 | 21819518 | 35012658 | | 0 | wait/io/file/sql/ERRMSG | 5 | 58504102 | 1422237 | 11700820 | 23653118 | | 2 | wait/io/file/sql/dbopt | 8 | 49073354 | 2748458 | 6134169 | 11395899 | | 4 | wait/io/file/myisam/dfile | 3 | 45757625 | 3855819 | 15252541 | 32138179 | | 2 | wait/synch/mutex/mysys/THR_LOCK_open | 116 | 32695213 | 218860 | 281855 | 366061 | | 0 | wait/synch/mutex/sql/LOCK_plugin | 187 | 30413774 | 144024 | 162640 | 344881 | | 0 | wait/io/file/sql/MYSQL_LOG | 4 | 29470558 | 732122 | 7367639 | 15266544 | | 0 | wait/io/file/mysys/charset | 3 | 29210044 | 2685624 | 9736681 | 21207534 | +-----------+----------------------------------------------+------------+----------------+----------------+----------------+----------------+ 20 rows in set (0.01 sec)
Harvesting the data for more
The performance schema currently exposes only a few aggregates. Since the data is available as a SQL table (as opposed to a SHOW xxx result), regular SQL queries can be used, to build higher level score cards.
Monitor> select THREAD_ID, SUM(COUNT_STAR), SUM(SUM_TIMER_WAIT) from EVENTS_WAITS_SUMMARY_BY_THREAD_BY_EVENT_NAME group by THREAD_ID; +-----------+-----------------+---------------------+ | THREAD_ID | SUM(COUNT_STAR) | SUM(SUM_TIMER_WAIT) | +-----------+-----------------+---------------------+ | 0 | 3189 | 1501188274 | | 1 | 12 | 69725619 | | 2 | 2009 | 1539441825 | | 3 | 206 | 60356070610 | | 4 | 82 | 12977904034039 | +-----------+-----------------+---------------------+ 5 rows in set (0.01 sec)
Monitor> select SUM(COUNT_STAR), SUM(SUM_TIMER_WAIT) from EVENTS_WAITS_SUMMARY_BY_EVENT_NAME; +-----------------+---------------------+ | SUM(COUNT_STAR) | SUM(SUM_TIMER_WAIT) | +-----------------+---------------------+ | 5556 | 13041387778194 | +-----------------+---------------------+ 1 row in set (0.00 sec)
The end
Interested readers are encouraged to try and play with the server to discover more, and look for more postings related to the MySQL performance schema.
-- Marc Alff
0 comments:
Post a Comment