www.markleith.co.uk/?p=377
Internally MySQL uses various methods to manage (or, block) concurrent access to shared structures within the server - the most common being mutexes (or Mutual Exclusion locks), RW Locks, or Semaphores. Each have slightly different properties on how different threads are allowed to interact when trying to access these synchronization points.
There has been much written on the various hot spots in the server around these locking/blocking constructs over the past couple of years, so I won’t go further in to that here. See the excellent blogs from Mikael or Dimitri from within Oracle, or those from the likes of Mark or Domas over at Facebook, for examples.
Visibility in to what was happening in the server at this level has been very lacking however, with only SHOW MUTEX STATUS available in the standard server distribution, which only tracked InnoDB mutexes and not those at the server level - which could often be the blocking factors for scalability.
I’ve blogged about PERFORMANCE_SCHEMA before, but never really shown what you can now do whilst trying to track down what sessions are doing, and what they are currently waiting for.
I also saw a hack recently that put the fact that a connection was trying to grab a Query Cache mutex in to the thread state (”Waiting on query cache mutex”), to track whether the query cache was causing too much contention. I thought that was entirely the wrong way to track this kind of detail (it misuses the thread state, which should be stages of execution, not each synchronization point, and doesn’t give you any meaningful way to track the entire overhead). Hopefully I can now show why I thought that.
So with that, let’s dive in to an example of how it should really be done, (you will probably have to scroll this to the right):
SELECT NAME, IF(PPS.ID = 0, 'Internal Thread', CONCAT(IPS.USER, '@', IPS.HOST)) USER, DB, COMMAND, STATE, TIME, EVENT_NAME LAST_WAIT, IF(TIMER_WAIT IS NULL , 'Still Waiting', TIMER_WAIT/1000000000) LAST_WAIT_MS FROM performance_schema.EVENTS_WAITS_CURRENT JOIN performance_schema.THREADS PPS USING (THREAD_ID) LEFT JOIN INFORMATION_SCHEMA.PROCESSLIST IPS USING (ID); +----------------------------------------+--------------------+--------------------+---------+--------------+------+--------------------------------------------------+---------------+ | NAME | USER | DB | COMMAND | STATE | TIME | LAST_WAIT | LAST_WAIT_MS | +----------------------------------------+--------------------+--------------------+---------+--------------+------+--------------------------------------------------+---------------+ | thread/sql/main | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/sql/LOCK_thread_count | 0.0001 | | thread/innodb/io_handler_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/buf_pool_mutex | 0.0001 | | thread/innodb/io_handler_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/buf_pool_mutex | 0.0001 | | thread/innodb/io_handler_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/buf_pool_mutex | 0.0001 | | thread/innodb/io_handler_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/buf_pool_mutex | 0.0001 | | thread/innodb/io_handler_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/buf_pool_mutex | 0.0001 | | thread/innodb/io_handler_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/buf_pool_mutex | 0.0002 | | thread/innodb/io_handler_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/io/file/innodb/innodb_log_file | Still Waiting | | thread/innodb/io_handler_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/buf_pool_mutex | 0.0001 | | thread/innodb/io_handler_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/buf_pool_mutex | 0.0004 | | thread/innodb/srv_error_monitor_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/srv_innodb_monitor_mutex | 0.0002 | | thread/innodb/srv_master_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/fil_system_mutex | 0.0028 | | thread/innodb/srv_lock_timeout_thread | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/innodb/kernel_mutex | 0.0024 | | thread/sql/one_connection | msandbox@localhost | performance_schema | Query | executing | 0 | wait/io/file/myisam/dfile | 0.0053 | | thread/sql/signal_handler | Internal Thread | NULL | NULL | NULL | NULL | wait/synch/mutex/sql/LOCK_thread_count | 0.0030 | | thread/sql/one_connection | msandbox@localhost | test | Query | Sending DATA | 133 | wait/synch/rwlock/innodb/checkpoint_lock | Still Waiting | +----------------------------------------+--------------------+--------------------+---------+--------------+------+--------------------------------------------------+---------------+ 16 rows IN SET (0.78 sec)
The first thing to notice is that not only can we see what external connections are doing - we can now see what internal threads are doing as well. All threads are easily identified by the PERFORMANCE_SCHEMA.THREADS.NAME column, with all client connections having the same name of thread/sql/one_connection (the internal function to manage database connections is handle_one_connection()), and each internal thread within the server and storage engines are tagged with their own identifiers, such as thread/sql/main, the main MySQL Server thread, or thread/innodb/srv_master_thread, the main InnoDB storage engine thread.
So we show the name of each thread, and then figure out the user@host if the thread is an external client connection. We then show all of the normal output that you would expect of SHOW PROCESSLIST, with DB, COMMAND, STATE and TIME (I emit the INFO column, but you could add that if you like to see the statement executing as well).
The last two columns come from the new EVENTS_WAITS_CURRENT table. As you can see, we can now show exactly what the current, or last completed, wait for each session was, and for exactly how long they waited (down to picosecond precision).
In my example above, the last thread listed is waiting for checkpointing to complete within InnoDB, whilst an internal thread is waiting on file IO, on the InnoDB transaction logs (i.e, he is the guy working on the checkpoint) - ooops, I was running a huge INSERT … SELECT on an instance with default settings for innodb_log_file_size. 
If you start to see lots of lots of connections waiting on wait/synch/rwlock/innodb/checkpoint_lock like above, then you too know that you should probably be doing something about your log file sizes (or maybe check whether something else is causing too aggressive checkpointing, such as a very low innodb_max_dirty_pages_pct value).
Keep in mind this can only give you an indication that there are contention points that can be dealt with, as these statistics are very transient in nature.
Here’s an example of tracking down exactly what the contention points in your server are:
SELECT EVENT_NAME, SUM_TIMER_WAIT/1000000000 WAIT_MS, COUNT_STAR FROM performance_schema.EVENTS_WAITS_SUMMARY_GLOBAL_BY_EVENT_NAME ORDER BY SUM_TIMER_WAIT DESC, COUNT_STAR DESC LIMIT 30; +---------------------------------------------------------+-------------+------------+ | EVENT_NAME | WAIT_MS | COUNT_STAR | +---------------------------------------------------------+-------------+------------+ | wait/io/file/innodb/innodb_data_file | 150562.0345 | 182750 | | wait/io/file/innodb/innodb_log_file | 77795.5425 | 8913 | | wait/synch/rwlock/innodb/checkpoint_lock | 11636.7894 | 1284 | | wait/synch/rwlock/innodb/btr_search_latch | 7429.2204 | 39677465 | | wait/io/file/myisam/kfile | 7353.2737 | 2011 | | wait/synch/mutex/innodb/kernel_mutex | 4115.0534 | 59198510 | | wait/synch/mutex/innodb/fil_system_mutex | 3473.8341 | 1263809 | | wait/io/file/myisam/dfile | 2940.5701 | 641 | | wait/synch/mutex/innodb/buf_pool_mutex | 2650.8666 | 33982979 | | wait/synch/mutex/innodb/rw_lock_mutex | 1261.8025 | 18877546 | | wait/io/file/sql/FRM | 116.6419 | 863 | | wait/synch/cond/sql/COND_thread_count | 1.4073 | 1 | | wait/io/file/sql/pid | 1.2654 | 3 | | wait/synch/mutex/innodb/mutex_list_mutex | 0.7675 | 16727 | | wait/synch/mutex/innodb/rw_lock_list_mutex | 0.4023 | 8331 | | wait/io/file/sql/dbopt | 0.2745 | 12 | | wait/io/file/sql/casetest | 0.2041 | 5 | | wait/synch/mutex/innodb/thr_local_mutex | 0.2009 | 2050 | | wait/synch/mutex/mysys/THR_LOCK_open | 0.1993 | 989 | | wait/synch/rwlock/innodb/trx_purge_latch | 0.1436 | 255 | | wait/io/file/sql/ERRMSG | 0.1432 | 5 | | wait/synch/rwlock/sql/LOCK_grant | 0.1375 | 188 | | wait/synch/rwlock/sql/MDL_lock::rwlock | 0.1013 | 481 | | wait/synch/mutex/sql/Query_cache::structure_guard_mutex | 0.0923 | 628 | | wait/synch/mutex/mysys/THR_LOCK_myisam | 0.0781 | 283 | | wait/synch/rwlock/sql/Query_cache_query::LOCK | 0.0676 | 198 | | wait/io/file/mysys/charset | 0.0561 | 3 | | wait/synch/mutex/sql/LOCK_open | 0.0529 | 543 | | wait/synch/mutex/mysys/THR_LOCK_lock | 0.0504 | 244 | | wait/synch/mutex/innodb/srv_innodb_monitor_mutex | 0.0424 | 75 | +---------------------------------------------------------+-------------+------------+ 30 rows IN SET (0.00 sec)
All of the above is aggregated server wide, since server start. Of course IO is my largest issue - I was doing write heavy work.
But then you can see exactly what I was waiting on after that - the first culprit was as above, way too much checkpointing. Next is waiting for wait/synch/rwlock/innodb/btr_search_latch, the synchronization point for the InnoDB Adaptive Hash Index. I might also do well to disable it with innodb_adaptive_hash_index = 0 in my case.
I can tell immediately that the query cache is not a contention point as well for example - just look for high values for wait/synch/mutex/sql/Query_cache::structure_guard_mutex for that.
5.5 is coming people, get downloading and trying! We want your feedback!
UPDATE: Note that in 5.5.6 and above, you should actually use performance_schema.THREADS instead of PROCESSLIST, and performance_schema.EVENTS_WAITS_SUMMARY_GLOBAL_BY_EVENT_NAME instead of EVENTS_WAITS_SUMMARY_BY_EVENT_NAME, these were renamed within Bug#55416.
