Re: [Maria-developers] MariaDB mutex contention (was: Re: MariaDB 10.0 benchmarks on upcoming IVB-EP processors ...)

22 Aug 2013

      Hi Monty,

me and Axel did additional analysis of LOCK_open wait time in 10.0.4.
Below are a few interesting things that we discovered:

- with 1 CPU LOCK_open and THR_LOCK::mutex wait times are very close
- with 4 CPU LOCK_open wait time is about 5.5 * THR_LOCK::mutex wait time
- 5.6 with 4 CPU and table-cache-instances=1THR_LOCK::mutex wait time
  is about 1.7% of execution time, with table-cache-instances=16 it is 9.8%
- tc_acquire_table/tc_release_table update 3 lists each, which is ~20 pointer updates
  per query
- thr_lock/thr_unlock seem to do less pointer updates under read-only load

I guess every pointer update invalidates corresponding CPU cache lines of
other CPU's and causing expensive main memory reads.

So now I'm trying to find alternative cache algorithm that will either read or
update less pointers.

Regards,
Sergey

16.08.2013, в 18:11, Axel Schwenke  написал(а):
...
Hi,
Michael Widenius wrote:
...
10.0.4 should be very soon ready for benchmarking (Tuesday or
Wednesday). We are in the final stage of fixing the failing test cases
after our last merge with MySQL 5.6 GA.
I would just prefer to see Sergei Vojtovich push his code that changes
how the table cache works.
This solves the same problem as the split table cache in 5.6,
but is a much simpler and better implementation.
After this, I would expect that MariaDB 10.0 performance would be
closer to 5.6 performance for this benchmark.
...
Axel, could you at some point run the same benchmark with MariaDB
10.0.4 and MySQL 5.6 with gprof to see where time is spent?
I have now beefed up my knowledge of performance_schema and used it to look
at Mutex/RW-lock contention for readonly OLTP benchmark.
-----
TL;DR: 10.0.4 spends very long time in LOCK_PLUGIN, LOCK_OPEN is indeed much
better than 10.0.3 but not(?) nearly as good as MySQL-5.6.
-----
Contestants:
- MySQL-5.6.13 (release)
- MariaDB-10.0.3 (release)
- MariaDB-10.0 r3799 (bzr trunk)
all 3 compiled from source on benchmark machine using the same build script
Environment:
- many core machine (32 cores, 64 threads)
- sysbench-0.5 OLTP readonly, 10M rows, single table
- mysqld bound to 48 cores (sysbench to the other 8)
- tested with 64 threads (this is the sweet spot)
- using tcmalloc (preloaded)
- mutexes and rw locks fully instrumented via performance_schema, see my.cnf
Benchmark results (transactions per second):
P_S on		P_S off
MySQL:	~15K		~18K
10.0.3:	~7K		~7.5K
10.0.4:	~6.5K		~9K
After stabilizing I took 3 probes from P_S, sorting by sum_timer_wait desc.
Times shown by P_S are picoseconds. If this were seconds, the decimal point
would be in the column between "m" and "_" in "sum_timer_wait". So i.e.
10.0.4 waited 242 seconds for LOCK_PLUGIN during the 10 second measurement
interval. Since we have 48 cores, there are total 480 seconds and 10.0.4
wasted about 50% of that.
Questions:
- what is protected by LOCK_PLUGIN?
- how is LOCK_OPEN split in MySQL-5.6?If some of that is now covered by
THR_LOCK::mutex, then it would explain why this is the busiest mutex in
MySQL-5.6.
Let me know if you need more data from me or if you have ideas what else I
should test.
XL
Top 20 Mutexes/RW-locks
MySQL-5.6.13
+---------------------------------------------+------------+-----------------+
| event_name                                  | count_star | sum_timer_wait  |
+---------------------------------------------+------------+-----------------+
| wait/synch/mutex/mysys/THR_LOCK::mutex      |    3397732 | 123367802416236 |
| wait/synch/rwlock/innodb/btr_search_latch   |    1632176 |  22207357475142 |
| wait/synch/rwlock/sql/LOCK_grant            |    1682983 |   1526912505972 |
| wait/synch/mutex/sql/LOCK_table_cache       |    3397786 |   1247140492941 |
| wait/synch/mutex/sql/THD::LOCK_thd_data     |    9219327 |   1076510130276 |
| wait/synch/rwlock/innodb/hash_table_locks   |    4086413 |   1026755227155 |
| wait/synch/mutex/innodb/trx_sys_mutex       |     364146 |    639270297372 |
| wait/synch/mutex/innodb/os_mutex            |     149491 |    630758755641 |
| wait/synch/rwlock/innodb/index_tree_rw_lock |    1016436 |    344264365074 |
| wait/synch/rwlock/sql/MDL_lock::rwlock      |     242778 |    183463650006 |
| wait/synch/mutex/sql/MDL_map::mutex         |     121342 |     69121460394 |
| wait/synch/mutex/mysys/BITMAP::mutex        |     242667 |     54426177477 |
| wait/synch/mutex/innodb/fil_system_mutex    |     179586 |     20229032103 |
| wait/synch/mutex/sql/LOCK_plugin            |     121352 |     15004585617 |
| wait/synch/mutex/innodb/trx_mutex           |     121475 |     13105527141 |
| wait/synch/mutex/innodb/lock_mutex          |     121374 |     12627692868 |
| wait/synch/mutex/innodb/buf_pool_mutex      |       2240 |       228234006 |
| wait/synch/mutex/innodb/log_sys_mutex       |        540 |       119752122 |
| wait/synch/mutex/innodb/flush_list_mutex    |        704 |        86802870 |
| wait/synch/mutex/innodb/buf_dblwr_mutex     |        640 |        30728817 |
+---------------------------------------------+------------+-----------------+
MariaDB-10.0.3
+--------------------------------------- | event_name +--------------------------------------- | wait/synch/mutex/sql/LOCK_open | wait/synch/mutex/mysys/THR_LOCK::mutex | wait/synch/mutex/sql/LOCK_plugin | wait/synch/mutex/sql/THD::LOCK_thd_data | wait/synch/rwlock/innodb/hash table locks | wait/synch/rwlock/innodb/btr_search_latch | wait/synch/mutex/innodb/trx_sys_mutex | wait/synch/rwlock/sql/MDL_lock::rwlock | wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data | | wait/synch/mutex/mysys/THR_LOCK_lock | wait/synch/mutex/mysys/BITMAP::mutex | wait/synch/mutex/sql/MDL_map::mutex | wait/synch/mutex/innodb/fil_system_mutex | wait/synch/mutex/innodb/lock_mutex | wait/synch/mutex/innodb/trx_mutex | wait/synch/mutex/innodb/buf_pool_mutex | wait/synch/mutex/innodb/buf_dblwr_mutex | wait/synch/mutex/innodb/log_sys_mutex | wait/synch/mutex/innodb/flush_list_mutex | wait/synch/mutex/innodb/os_mutex +---------------------------------------

---------+------------+-----------------+ | count_star | sum_timer_wait  | ---------+------------+-----------------+ |    3334966 | 251668176449112 | |    2206782 |   2761461343332 | |    2540899 |   1471913471196 | |    6485120 |    770989733856 | |    3315788 |    674878255920 | |    1358771 |    540950632524 | |     380210 |    245662486416 | |     191698 |    125257499748 | 1067704 |     95258676492 | |     157621 |     52329482172 | |     154870 |     49415303736 | |      79173 |     41936664096 | |     129610 |     40258209024 | |      93667 |     26848457928 | |      94131 |     11398946760 | |      12672 |       571983480 | |       9152 |       312365052 | |        456 |       138632868 | |        480 |       109226268 | |        350 |        71117100 | ---------+------------+-----------------+
MariaDB-10.0-r3799
+---------------------------------------------+------------+-----------------+
| event_name                                  | count_star | sum_timer_wait  |
+---------------------------------------------+------------+-----------------+
| wait/synch/mutex/sql/LOCK_plugin            |    4194896 | 242595666533160 |
| wait/synch/mutex/sql/LOCK_open              |    1835243 |  33790056812460 |
| wait/synch/mutex/mysys/THR_LOCK::mutex      |    1835221 |   3136249420092 |
| wait/synch/rwlock/sql/LOCK_tdc              |     911928 |   1088553356028 |
| wait/synch/mutex/sql/THD::LOCK_thd_data     |    5766813 |    695664363024 |
| wait/synch/rwlock/innodb/hash table locks   |    2144715 |    513517462020 |
| wait/synch/rwlock/innodb/btr_search_latch   |     915043 |    399309801912 |
| wait/synch/rwlock/sql/MDL_lock::rwlock      |     131171 |    176610102480 |
| wait/synch/mutex/innodb/trx_sys_mutex       |     196751 |    154609451460 |
| wait/synch/rwlock/innodb/index_tree_rw_lock |     527543 |    137903039712 |
| wait/synch/mutex/sql/MDL_map::mutex         |     158268 |     95133455712 |
| wait/synch/mutex/innodb/fil_system_mutex    |      97493 |     27285605172 |
| wait/synch/mutex/mysys/BITMAP::mutex        |     131099 |     26589125196 |
| wait/synch/mutex/mysys/THR_LOCK_lock        |     131105 |     23952666708 |
| wait/synch/mutex/innodb/lock_mutex          |      65579 |     10355822676 |
| wait/synch/mutex/innodb/trx_mutex           |      65812 |      9790097724 |
| wait/synch/mutex/innodb/buf_pool_mutex      |      11550 |       644569236 |
| wait/synch/rwlock/innodb/checkpoint_lock    |          2 |       236298492 |
| wait/synch/mutex/innodb/buf_dblwr_mutex     |       3880 |       156907368 |
| wait/synch/mutex/innodb/flush_list_mutex    |        692 |       124740900 |
+---------------------------------------------+------------+-----------------+
Comparison
----------
MariaDB-10.0-r3799             MariaDB-10.0.3                 MySQL-5.6.13
+---------------------------------------------+------------+-----------------+------------+-----------------+------------+-----------------+
| event_name                                  | count_star | sum_timer_wait  | count_star | sum_timer_wait  | count_star | sum_timer_wait  |
+---------------------------------------------+------------+-----------------+------------+-----------------+------------+-----------------+
| wait/synch/mutex/sql/LOCK_plugin            |    4194896 | 242595666533160 |    2540899 |   1471913471196 |     121352 |     15004585617 |
| wait/synch/mutex/sql/LOCK_open              |    1835243 |  33790056812460 |    3334966 | 251668176449112 |
| wait/synch/mutex/mysys/THR_LOCK::mutex      |    1835221 |   3136249420092 |    2206782 |   2761461343332 |    3397732 | 123367802416236 |
| wait/synch/rwlock/sql/LOCK_tdc              |     911928 |   1088553356028 |
| wait/synch/mutex/sql/THD::LOCK_thd_data     |    5766813 |    695664363024 |    6485120 |    770989733856 |    9219327 |   1076510130276 |
| wait/synch/rwlock/innodb/hash table locks   |    2144715 |    513517462020 |    3315788 |    674878255920 |    4086413 |   1026755227155 |
| wait/synch/rwlock/innodb/btr_search_latch   |     915043 |    399309801912 |    1358771 |    540950632524 |    1632176 |  22207357475142 |
| wait/synch/rwlock/sql/MDL_lock::rwlock      |     131171 |    176610102480 |     191698 |    125257499748 |     242778 |    183463650006 |
| wait/synch/mutex/innodb/trx_sys_mutex       |     196751 |    154609451460 |     380210 |    245662486416 |     364146 |    639270297372 |
| wait/synch/rwlock/innodb/index_tree_rw_lock |     527543 |    137903039712 |                                   1016436 |    344264365074 |
| wait/synch/mutex/sql/MDL_map::mutex         |     158268 |     95133455712 |      79173 |     41936664096 |     121342 |     69121460394 |
| wait/synch/mutex/innodb/fil_system_mutex    |      97493 |     27285605172 |     129610 |     40258209024 |     179586 |     20229032103 |
| wait/synch/mutex/mysys/BITMAP::mutex        |     131099 |     26589125196 |     154870 |     49415303736 |     242667 |     54426177477 |
| wait/synch/mutex/mysys/THR_LOCK_lock        |     131105 |     23952666708 |     157621 |     52329482172 |
| wait/synch/mutex/innodb/lock_mutex          |      65579 |     10355822676 |      93667 |     26848457928 |     121374 |     12627692868 |
| wait/synch/mutex/innodb/trx_mutex           |      65812 |      9790097724 |      94131 |     11398946760 |     121475 |     13105527141 |
| wait/synch/mutex/innodb/buf_pool_mutex      |      11550 |       644569236 |      12672 |       571983480 |       2240 |       228234006 |
| wait/synch/rwlock/innodb/checkpoint_lock    |          2 |       236298492 |
| wait/synch/mutex/innodb/buf_dblwr_mutex     |       3880 |       156907368 |       9152 |       312365052 |        640 |        30728817 |
| wait/synch/mutex/innodb/flush_list_mutex    |        692 |       124740900 |        480 |       109226268 |        704 |        86802870 |
+---------------------------------------------+------------+-----------------+------------+-----------------+------------+-----------------+

Re: [Maria-developers] MariaDB mutex contention (was: Re: MariaDB 10.0 benchmarks on upcoming IVB-EP processors ...)

Sergey Vojtovich