What is a mutex anyway?

While I was working on the MySQL Workbench booth at MySQL Connect this year, an attendee came up and asked what a mutex was and how important it is to them in their function as a DBA.

It’s a good question. The short answer is:

Mutexes are mutually exclusive locks and are designed to prevent concurrent access to resources that in doing so may result in unsafe conditions.

They are required as part of virtually all multi-threaded applications (not just MySQL), and are not something that you can specifically prevent from happening. This is a different concept to row-locks and table locks.

Some examples

If the InnoDB buffer pool is full, internally free space needs to be created in order to be able to load your desired page into memory. What you don’t want, is in between freeing and loading somebody else to take your desired free-slot.

When a page becomes too full, it may need to split data into other pages. It is possible that there could be a thread deadlock if two pages left and right of each-other reach this condition at once and can’t decide who should proceed first.

Should you care as a DBA?

Yes, and no.

No in the sense that you are not expected to fix these problems, they are usually very internal to the operations of the database and require a MySQL developer to fix them.

Yes in the sense that newer MySQL versions often change the way internal locking works if a mutex becomes hot for a large number of users. Hot is the terminology used to describe a mutex which has other threads blocked waiting for it for a large amount of time. This contention reduces scalability on multi-core machines because some threads sit idle, essentially waiting for the ablity to run.

Hot Mutex History

Here is an incomplete list of some of the mutexes worked on in newer versions of MySQL:

MySQL 5.7:

  • Index lock contention is reduced via introduction of a new SX lock mode. This improves performance of large tables.

  • The LOCK_thread_count mutex protected several independent internal server structures and variables, and was a bottleneck, particularly affecting server performance in the circumstance when many clients were connecting and disconnecting at once.

MySQL 5.6:

  • The kernel mutex is split into smaller, localized locks. This mutex previous covered many different internal tasks to InnoDB.
  • LOCK_open mutex is split – this mutex used to be a mutex to protect the metadata of a table within the MySQL Server.
  • The default configuration was changed, so that InnoDB has 8 buffer pool instances when the buffer pool is > 1GB.

MySQL 5.5:

How can you see if a mutex is hot?

Various metadata commands can expose mutexes that are hot. For example: SHOW ENGINE INNODB STATUS, SHOW ENGINE INNODB MUTEX and PERFORMANCE_SCHEMA. Operating specific tools can also be used, such as oprofile or Linux Perf.

Here is an example from SHOW ENGINE INNODB MUTEX (via dimitrik):

mysql> show engine innodb mutex;
+--------+----------------------------+-------------------+
| Type   | Name                       | Status            |
+--------+----------------------------+-------------------+
| InnoDB | log/log0log.c:775          | os_waits=26       |
| InnoDB | log/log0log.c:771          | os_waits=1        |
| InnoDB | buf/buf0buf.c:1208         | os_waits=3219     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=6990     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=4619     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=5627     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=7873     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=4466     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=16929    |
| InnoDB | buf/buf0buf.c:1208         | os_waits=19305    |
| InnoDB | buf/buf0buf.c:1208         | os_waits=16301962 |
| InnoDB | buf/buf0buf.c:1208         | os_waits=11649    |
| InnoDB | buf/buf0buf.c:1208         | os_waits=950471   |
| InnoDB | buf/buf0buf.c:1208         | os_waits=6545     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=4262     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=5642     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=7878     |
| InnoDB | buf/buf0buf.c:1208         | os_waits=387166   |
| InnoDB | fil/fil0fil.c:1559         | os_waits=1265     |
| InnoDB | srv/srv0srv.c:987          | os_waits=460452   |
| InnoDB | combined buf/buf0buf.c:900 | os_waits=38503    |
| InnoDB | log/log0log.c:832          | os_waits=184      |
| InnoDB | combined buf/buf0buf.c:901 | os_waits=77       |
+--------+----------------------------+-------------------+
23 rows in set (0.56 sec)

Here is an example of SHOW ENGINE INNODB STATUS (via the MySQL forums):

..
---------- 
SEMAPHORES 
---------- 
OS WAIT ARRAY INFO: reservation count 334026866, signal count 322155474 
--Thread 139787989395216 has waited at ../../../storage/innobase/trx/trx0undo.c line 1684 for 165.00 seconds the semaphore: 
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1 
waiters flag 1 
--Thread 139788009264912 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 165.00 seconds the semaphore: 
S-lock on RW-latch at 0x7f230fbd2b48 created in file ../../../storage/innobase/buf/buf0buf.c line 550 
a writer (thread id 139787989395216) has reserved it in mode exclusive 
number of readers 0, waiters flag 1 
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463 
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463 
--Thread 139787997423376 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 15.00 seconds the semaphore: 
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1 
waiters flag 1 
--Thread 139788384470800 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore: 
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550 
a writer (thread id 139788006655760) has reserved it in mode exclusive 
number of readers 0, waiters flag 1 
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463 
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463 
..

And one for PERFORMANCE_SCHEMA (via Mark Leith):

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)

Published by

morgo

I joined MySQL AB in 2006, left, and am now back at Oracle working on the MySQL team. I’ve also worked at Percona and InPowered.

  • Here is another example of the PERFORMANCE_SCHEMA mutex example on a reasonably busy 5.6 server. If you see the mention of ‘wait/io/file/%’ in the event_name, these mutexes are related to reading/writing to disk.

    mysql> 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 |
    +——————————————————-+——————+————-+
    | idle | 11719125529.3820 | 91754165 |
    | wait/io/table/sql/handler | 36727186.6918 | 31884490559 |
    | wait/io/file/innodb/innodb_data_file | 473047.7050 | 1958390 |
    | wait/io/file/sql/binlog | 468179.8326 | 14535454 |
    | wait/io/file/innodb/innodb_log_file | 370579.5113 | 5852927 |
    | wait/lock/table/sql/handler | 40857.1368 | 109148128 |
    | wait/io/file/sql/slow_log | 14403.8516 | 1610898 |
    | wait/io/file/myisam/kfile | 13128.6356 | 4466353 |
    | wait/io/file/myisam/dfile | 6940.8403 | 2490871 |
    | wait/io/file/sql/FRM | 26.3468 | 1237 |
    | wait/io/file/sql/binlog_index | 2.0246 | 134 |
    | wait/io/file/sql/relaylog | 0.9187 | 33 |
    | wait/io/file/sql/ERRMSG | 0.5696 | 5 |
    | wait/io/file/mysys/cnf | 0.3124 | 5 |
    | wait/io/file/mysys/charset | 0.2651 | 3 |
    | wait/io/file/sql/casetest | 0.1274 | 10 |
    | wait/io/file/sql/dbopt | 0.1223 | 14 |
    | wait/io/file/sql/pid | 0.0531 | 3 |
    | wait/io/file/sql/relaylog_index | 0.0454 | 10 |
    | wait/io/file/sql/misc | 0.0330 | 3 |
    | wait/io/file/archive/data | 0.0085 | 2 |
    | wait/io/file/sql/global_ddl_log | 0.0068 | 2 |
    | wait/synch/mutex/sql/LOCK_delayed_create | 0.0000 | 0 |
    | wait/synch/mutex/sql/LOCK_delayed_insert | 0.0000 | 0 |
    | wait/synch/mutex/sql/LOCK_crypt | 0.0000 | 0 |
    | wait/synch/mutex/sql/LOCK_connection_count | 0.0000 | 0 |
    | wait/synch/mutex/sql/LOCK_active_mi | 0.0000 | 0 |
    | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_commit_queue | 0.0000 | 0 |
    | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_xids | 0.0000 | 0 |
    | wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_commit | 0.0000 | 0 |
    +——————————————————-+——————+————-+
    30 rows in set (0.04 sec)

    • Mark Leith

      Actually, the ones with ‘io’ in the name are a couple of different types of events:

      * wait/io/table/sql/handler – is table IO (handler layer read/write of rows)

      * wait/io/file/% – are all tracking real file IO, rather than mutexes protecting the IO, broken out by the type of file

      * wait/lock/table/sql/handler – is table level lock events

      All mutex events start with ‘wait/synch/mutex’, so if you only want a summary of mutexes:

      SELECT EVENT_NAME, SUM_TIMER_WAIT/1000000000 WAIT_MS, COUNT_STAR
      FROM performance_schema.events_waits_summary_global_by_event_name
      WHERE SUM_TIMER_WAIT > 0
      AND EVENT_NAME LIKE ‘wait/synch/mutex/%’
      ORDER BY SUM_TIMER_WAIT DESC, COUNT_STAR DESC;

      • Thanks Mark! I’ve corrected my comment to be clearer.

  • ronaldbradford

    Save the hassle of reading the output and view it using the MySQL plugin for New Relic. With this link http://j.mp/newrelic-mysql you can get a unlimited server FREE account.