Hi Axel, thanks for testing and interesting results. Though our results diverge a lot, generally I confirm that PFS is eating up 10-20% of performance and we're still slower than 5.6. But in my scenario even single thread is about 10% slower than in 5.6. Further comments/questions inline. 16.08.2013, в 18:11, Axel Schwenke <axel@askmonty.org> написал(а):
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? Mainly array of plugins and array of shared objects containing these plugins, but see below.
- 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. Nope. It is just split into multiple table caches (or partitioned), protected by LOCK_table_cache and LOCK_open. I guess we have some optimization for THR_LOCK::mutex which Oracle doesn't.
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 | +---------------------------------------------+------------+-----------------+
Indeed, strange that THD_LOCK::mutex takes so much time, never seen it in my tests. As well as strange that MDL_map::mutex is acquired 121 342 times whereas LOCK_table_cache is acquired 3 397 786 (they're almost identical in my tests).
MariaDB-10.0.3
+------------------------------------------------+------------+-----------------+ | event_name | count_star | sum_timer_wait | +------------------------------------------------+------------+-----------------+ | wait/synch/mutex/sql/LOCK_open | 3334966 | 251668176449112 | | wait/synch/mutex/mysys/THR_LOCK::mutex | 2206782 | 2761461343332 | | wait/synch/mutex/sql/LOCK_plugin | 2540899 | 1471913471196 | | wait/synch/mutex/sql/THD::LOCK_thd_data | 6485120 | 770989733856 | | wait/synch/rwlock/innodb/hash table locks | 3315788 | 674878255920 | | wait/synch/rwlock/innodb/btr_search_latch | 1358771 | 540950632524 | | wait/synch/mutex/innodb/trx_sys_mutex | 380210 | 245662486416 | | wait/synch/rwlock/sql/MDL_lock::rwlock | 191698 | 125257499748 | | wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data | 1067704 | 95258676492 | | wait/synch/mutex/mysys/THR_LOCK_lock | 157621 | 52329482172 | | wait/synch/mutex/mysys/BITMAP::mutex | 154870 | 49415303736 | | wait/synch/mutex/sql/MDL_map::mutex | 79173 | 41936664096 | | wait/synch/mutex/innodb/fil_system_mutex | 129610 | 40258209024 | | wait/synch/mutex/innodb/lock_mutex | 93667 | 26848457928 | | wait/synch/mutex/innodb/trx_mutex | 94131 | 11398946760 | | wait/synch/mutex/innodb/buf_pool_mutex | 12672 | 571983480 | | wait/synch/mutex/innodb/buf_dblwr_mutex | 9152 | 312365052 | | wait/synch/mutex/innodb/log_sys_mutex | 456 | 138632868 | | wait/synch/mutex/innodb/flush_list_mutex | 480 | 109226268 | | wait/synch/mutex/innodb/os_mutex | 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 | +---------------------------------------------+------------+-----------------+
From the above I'd say: 911 928 - number of executed queries (1x LOCK_tdc per query) 1 835 243 / 911 928= ~2 - LOCK_open was acquired 2x per query 4 194 896 / 911 928= ~4 - LOCK_plugin was acquired 4x per query Most probably it means that table definition cache is full and every query reopens table (at least 1x LOCK_plugin), evicts some old table from cache (at least 1x LOCK_plugin). It may be a bug in new code. From 5.6 and 10.0.3 metrics I can say that they're not running out of table cache. If the above is true, more complex code path is executed under LOCK_open and may give less optimal number.
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 | +---------------------------------------------+------------+-----------------+------------+-----------------+------------+-----------------+
<files.zip>
Would be nice to include LOCK_table_cache here. Just for your reference, here is command that I use to gather stats (gives seconds out of the box): select EVENT_NAME,COUNT_STAR,ROUND(SUM_TIMER_WAIT/1000000000000,2) AS SECONDS,SUM_TIMER_WAIT,MIN_TIMER_WAIT,AVG_TIMER_WAIT,MAX_TIMER_WAIT from performance_schema.events_waits_summary_global_by_event_name order by sum_timer_wait desc limit 20 Regards, Sergey