What a difference Atomics can make

Following up to my previous blog on graphing statement execution in performance_schema, Sunny Bains on the InnoDB team pointed out that in looking at the INSERT graph, he didn’t think I had atomic operations enabled within my build.

Particularly here (from trunk):

225 /******************************************************************//**
226 Increments lock_word the specified amount and returns new value.
227 @return lock->lock_word after increment */
228 UNIV_INLINE
229 lint
230 rw_lock_lock_word_incr(
231 /*===================*/
232         rw_lock_t*      lock,           /*!< in/out: rw-lock */
233         ulint           amount)         /*!< in: amount of increment */
234 {
235 #ifdef INNODB_RW_LOCKS_USE_ATOMICS
236         return(os_atomic_increment_lint(&lock->lock_word, amount));
237 #else /* INNODB_RW_LOCKS_USE_ATOMICS */
238         lint local_lock_word;
239 
240         mutex_enter(&(lock->mutex));    < === See this a lot in his graph
241 
242         lock->lock_word += amount;
243         local_lock_word = lock->lock_word;
244 
245         mutex_exit(&(lock->mutex));
246 
247         return(local_lock_word);
248 #endif /* INNODB_RW_LOCKS_USE_ATOMICS */
249 }

He was of course right, I was building on OS X 10.5, which ships with this gcc version by default:

Cerberus:lp-mysql-trunk mark$ gcc --version
i686-apple-darwin9-gcc-4.0.1 (GCC) 4.0.1 (Apple Inc. build 5493)

InnoDB supports atomic operations with GCC 4.1.2 or later, so a quick update of gcc using ports (sudo port install gcc45) later:

Cerberus:lp-mysql-trunk mark$ export CC=/opt/local/bin/gcc-mp-4.5
Cerberus:lp-mysql-trunk mark$ export CXX=/opt/local/bin/gcc-mp-4.5
Cerberus:lp-mysql-trunk mark$ cmake . && make
-- The C compiler identification is GNU
-- The CXX compiler identification is GNU
-- The CXX compiler identification is GNU
...
-- Performing Test HAVE_GCC_ATOMIC_BUILTINS
-- Performing Test HAVE_GCC_ATOMIC_BUILTINS - Success
...
-- Performing Test HAVE_IB_GCC_ATOMIC_BUILTINS
-- Performing Test HAVE_IB_GCC_ATOMIC_BUILTINS - Success
-- Performing Test HAVE_IB_ATOMIC_PTHREAD_T_GCC
-- Performing Test HAVE_IB_ATOMIC_PTHREAD_T_GCC - Success
...

Re-running the same tests that I had done before to generate the graphs really does tell a picture, even when just looking at the thumbnail view:

InnoDB INSERT no atomics

InnoDB INSERT no atomics

InnoDB INSERT atomics

InnoDB INSERT atomics

The timings may not be a true reflection of the consistent overhead (this is my macbook, which does a lot of other work whilst I’m testing this stuff out), but just looking at the difference in numbers of synchronization points, it’s clear that there will be far less contention (and hence potential wait time) in the atomics cases – obviously.

So what’s the lesson we can learn from this?

If you see a large number of waits for either the wait/synch/mutex/innodb/rw_lock_mutex or wait/synch/mutex/innodb/thr_local_mutex, you may want to investigate whether the build you are using for your platform has atomic operations enabled. If not, then consider finding a platform or build that does support them.

These are instrumented within performance_schema within the current 5.5 GA release as well, so you can tell whether these are one of your top waits by simply looking at the summary of all mutex waits for InnoDB globally:

Cerberus:~ mark$ ~/sandboxes/msb_5_5_10/use
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.5.10 MySQL Community Server (GPL)

Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SELECT * 
    ->   FROM performance_schema.events_waits_summary_global_by_event_name 
    ->  WHERE event_name like 'wait/synch/mutex/innodb/%' 
    ->  ORDER BY sum_timer_wait DESC;
+-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+
| EVENT_NAME                                            | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
+-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+
| wait/synch/mutex/innodb/mutex_list_mutex              |       8367 |      382312980 |          34020 |          45692 |         158760 |
| wait/synch/mutex/innodb/rw_lock_list_mutex            |       8286 |      380714040 |          34020 |          45946 |        3549420 |
| wait/synch/mutex/innodb/kernel_mutex                  |        848 |      326206440 |          34020 |         384677 |       93589020 |
| wait/synch/mutex/innodb/log_sys_mutex                 |       1658 |      222532380 |          34020 |         134217 |        3961440 |
| wait/synch/mutex/innodb/rseg_mutex                    |       2847 |      204581160 |          34020 |          71858 |         283500 |
| wait/synch/mutex/innodb/buf_pool_mutex                |       3204 |      160389180 |          34020 |          50059 |         298620 |
| wait/synch/mutex/innodb/fil_system_mutex              |       2022 |      119584080 |          34020 |          59141 |         298620 |
| wait/synch/mutex/innodb/flush_list_mutex              |        773 |       29253420 |          34020 |          37844 |         136080 |
| wait/synch/mutex/innodb/recv_sys_mutex                |        166 |       10069920 |          45360 |          60662 |         147420 |
| wait/synch/mutex/innodb/log_flush_order_mutex         |        147 |        6486480 |          34020 |          44125 |         173880 |
| wait/synch/mutex/innodb/purge_sys_mutex               |         62 |        3938760 |          41580 |          63528 |         124740 |
| wait/synch/mutex/innodb/trx_undo_mutex                |         31 |        3424680 |          34020 |         110473 |         181440 |
| wait/synch/mutex/innodb/dict_sys_mutex                |         37 |        3073140 |          41580 |          83057 |         321300 |
| wait/synch/mutex/innodb/trx_doublewrite_mutex         |         59 |        2683800 |          34020 |          45488 |         158760 |
| wait/synch/mutex/innodb/autoinc_mutex                 |         24 |        2540160 |          56700 |         105840 |         215460 |
| wait/synch/mutex/innodb/thr_local_mutex               |         11 |         774900 |          41580 |          70445 |         136080 |
| wait/synch/mutex/innodb/srv_innodb_monitor_mutex      |         10 |         627480 |          41580 |          62748 |          94500 |
| wait/synch/mutex/innodb/innobase_share_mutex          |          3 |         340200 |          60480 |         113400 |         173880 |
| wait/synch/mutex/innodb/file_format_max_mutex         |          5 |         272160 |          34020 |          54432 |          86940 |
| wait/synch/mutex/innodb/ibuf_mutex                    |          3 |         117180 |          34020 |          39060 |          41580 |
| wait/synch/mutex/innodb/rw_lock_mutex                 |          0 |              0 |              0 |              0 |              0 |
| wait/synch/mutex/innodb/syn_arr_mutex                 |          0 |              0 |              0 |              0 |              0 |
| wait/synch/mutex/innodb/srv_dict_tmpfile_mutex        |          0 |              0 |              0 |              0 |              0 |
...

This is a standard MySQL 5.5.10 build for OS X, which has had similar kinds of statements run against it. We can see that wait/synch/mutex/innodb/rw_lock_mutex has had 0 waits, and wait/synch/mutex/innodb/thr_local_mutex has only had 11 waits globally. None are anywhere near close to the top wait events. This build most certainly does have atomics enabled.

So for those of you running 5.5 in production now:

What are your top waits?

5 comments

  1. @Daniël van Eeden I know, this was done for a reason however – as the buffers that performance_schema uses to store the instrumentation data are a fixed size (ring buffers), so that we don’t cause (expensive) memory allocation for instrumentation inside of the statements that we are tracking.

    These are only allocated on start up.

    • Well, that instrumentation is certainly not for free (although it is relatively light overhead – and 5.6 has made even more headway here). I believe that was why it was chosen to not be enabled by default however.

      I’d love to see it on by default. But first we want/need people trying it, getting happy with it etc. – and then telling us to enable it by default. ;)

  2. Here is some info from a production system running 5.5.6-rc.

    mysql> SELECT * FROM performance_schema.EVENTS_WAITS_SUMMARY_GLOBAL_BY_EVENT_NAME WHERE event_name LIKE 'wait/synch/mutex/innodb/%' ORDER BY sum_timer_wait DESC; SELECT VERSION();
    +-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+
    | EVENT_NAME                                            | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
    +-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+
    | wait/synch/mutex/innodb/log_sys_mutex                 |    6028421 |  9684615395000 |          16000 |        1606492 |   434683995000 |
    | wait/synch/mutex/innodb/kernel_mutex                  |    3461611 |  2536814237000 |          18000 |         732842 |   319867041500 |
    | wait/synch/mutex/innodb/rseg_mutex                    |   18687231 |  1281575383500 |          16000 |          68580 |   147625606500 |
    | wait/synch/mutex/innodb/buf_pool_mutex                |   23806676 |   925464560500 |          16000 |          38874 |    43657880000 |
    | wait/synch/mutex/innodb/fil_system_mutex              |     121766 |   108591217500 |          16000 |         891802 |    63475338000 |
    | wait/synch/mutex/innodb/thr_local_mutex               |      26960 |    29479666000 |          22000 |        1093459 |    23064617500 |
    | wait/synch/mutex/innodb/srv_innodb_monitor_mutex      |      48246 |    20313040000 |          32500 |         421030 |       37742500 |
    | wait/synch/mutex/innodb/flush_list_mutex              |     142085 |    10038950000 |          18000 |          70654 |       26608000 |
    | wait/synch/mutex/innodb/purge_sys_mutex               |      70764 |     8173063000 |          18000 |         115497 |       57581000 |
    | wait/synch/mutex/innodb/trx_doublewrite_mutex         |      61135 |     7949625000 |          16000 |         130033 |       69697500 |
    | wait/synch/mutex/innodb/log_flush_order_mutex         |      40712 |     6417210500 |          18000 |         157624 |       56099000 |
    | wait/synch/mutex/innodb/mutex_list_mutex              |      14984 |     3427428500 |          18000 |         228739 |       56302500 |
    | wait/synch/mutex/innodb/ios_mutex                     |      17069 |     1917432500 |          18000 |         112334 |        4155000 |
    | wait/synch/mutex/innodb/dict_sys_mutex                |       7459 |     1481463000 |          20000 |         198614 |      127897500 |
    | wait/synch/mutex/innodb/innobase_share_mutex          |       3358 |      905327500 |          35000 |         269603 |        1647500 |
    | wait/synch/mutex/innodb/file_format_max_mutex         |       1683 |      482172500 |          32500 |         286495 |         695000 |
    | wait/synch/mutex/innodb/trx_undo_mutex                |       2508 |      280055500 |          22000 |         111664 |         610000 |
    | wait/synch/mutex/innodb/autoinc_mutex                 |        575 |       92394500 |          30000 |         160686 |         537500 |
    | wait/synch/mutex/innodb/recv_sys_mutex                |        366 |       42597500 |          22000 |         116386 |         607500 |
    | wait/synch/mutex/innodb/rw_lock_list_mutex            |       1082 |       36132000 |          22000 |          33393 |         530000 |
    | wait/synch/mutex/innodb/srv_dict_tmpfile_mutex        |          1 |         427500 |         427500 |         427500 |         427500 |
    | wait/synch/mutex/innodb/ibuf_mutex                    |          1 |          45000 |          45000 |          45000 |          45000 |
    | wait/synch/mutex/innodb/syn_arr_mutex                 |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/srv_monitor_file_mutex        |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/srv_misc_tmpfile_mutex        |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/rw_lock_mutex                 |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/mem_pool_mutex                |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/commit_cond_mutex             |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/prepare_commit_mutex          |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/btr_search_enabled_mutex      |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/buf_pool_zip_mutex            |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/cache_last_read_mutex         |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/dict_foreign_err_mutex        |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/hash_table_mutex              |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/ibuf_bitmap_mutex             |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/ibuf_pessimistic_insert_mutex |          0 |              0 |              0 |              0 |              0 |
    | wait/synch/mutex/innodb/commit_threads_m              |          0 |              0 |              0 |              0 |              0 |
    +-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+
    37 rows in set (0.00 sec)
    
    +--------------+
    | VERSION()    |
    +--------------+
    | 5.5.6-rc-log |
    +--------------+
    1 row in set (0.00 sec)
    

Got something to say?