Bug #55167 InnoDB: performance regression in sysbench OLTP_RO test
Submitted: 11 Jul 2010 17:23 Modified: 6 Feb 2013 1:18
Reporter: Alexey Stroganov Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.5.5 OS:Any
Assigned to: Sunny Bains CPU Architecture:Any

[11 Jul 2010 17:23] Alexey Stroganov 
Description:
While running sysbench tests for 5.5.5 release we've observed drop in OLTP_RO test for InnoDB engine.

Tests were run on two boxes: with 8(SUSE10/RHEL52) and 24(Fedora) cores. Regression is more notable in results from 24 cores box.

results for OLTP_RO/InnoDB - 8 cores:
#                  SuSE10                   RHEL52
#              5.5.4      5.5.5        5.5.4      5.5.5
# Thread      INNODB     INNODB       INNODB     INNODB
          4  2389.48    2366.50      2088.05    1998.30
         16  1744.46    1763.59      3730.92    3795.45
         64  1145.73     945.11      3888.85    3835.74
        128  1176.74    1067.70      3879.34    3555.93
        256  1227.07    1069.68      3866.58    3774.03

results for OLTP_RO/InnoDB - 24 cores:

#                554        555
# Thread      INNODB     INNODB
          4  1618.57    1663.55
         16  5241.08    5088.55
         64  7517.04    7206.80
        128  7180.72    6928.50
        256  7075.24    6703.99

PSE information for OLTP_RO/InnoDB with 256 threads on 24 core box

554
-----------------------------------------------------------+------------+-------------------+----------------+---------------
EVENT_NAME                                                 | COUNT_STAR | SUM_TIMER_WAIT    | MIN_TIMER_WAIT | AVG_TIMER_WAIT
-----------------------------------------------------------+------------+-------------------+----------------+---------------
wait/synch/mutex/sql/LOCK_open                             |   38749264 | 15712281134839900 |          41470 |      405485924
wait/synch/rwlock/innodb/btr_search_latch                  |   18604587 | 10862871814549690 |          37700 |      583881373
wait/synch/mutex/innodb/buf_pool_mutex                     |   46059453 |  9273736515359290 |          33930 |      201342740
wait/synch/mutex/mysys/THR_LOCK::mutex                     |   38744398 |  6911669640629910 |          45240 |      178391457
wait/synch/mutex/innodb/kernel_mutex                       |    4152928 |  5703127827811440 |          33930 |     1373278763
wait/io/file/innodb/innodb_data_file                       |      27639 |  3015813163621830 |         897260 |   109114409480
wait/synch/mutex/innodb/log_flush_order_mutex              |    8165150 |  1249492198008730 |          33930 |      153027464
wait/synch/cond/sql/COND_thread_cache                      |         27 |   307562812187150 |    10419284720 | 11391215266190
wait/synch/rwlock/sql/LOCK_grant                           |   18897618 |   287713786379240 |          52780 |       15224870
wait/synch/mutex/mysys/THR_LOCK_lock                       |    2767463 |   251904835883350 |          45240 |       91023741
wait/synch/mutex/mysys/BITMAP::mutex                       |    2767462 |   248153834998160 |          41470 |       89668380
wait/synch/rwlock/sql/MDL_lock::rwlock                     |    2772080 |   196061060268060 |          49010 |       70727057
wait/synch/mutex/sql/LOCK_plugin                           |    1388009 |   102446052610200 |          45240 |       73807916
wait/synch/mutex/sql/MDL_map::mutex                        |    1388353 |    78729233895780 |          49010 |       56706928
wait/synch/mutex/sql/THD::LOCK_thd_data                    |  118410317 |    16706881834110 |          41470 |         141093
wait/io/file/innodb/innodb_log_file                        |        973 |      542638033860 |       21221330 |      557695821
wait/synch/mutex/sql/LOCK_thread_count                     |       1116 |      364029258450 |          41470 |      326191091
wait/synch/mutex/sql/LOCK_global_system_variables          |        888 |       64631281520 |          45240 |       72782974
wait/synch/mutex/innodb/fil_system_mutex                   |      85021 |       35719890440 |          33930 |         420130

-----------------------------------------------------------+------------+-------------------+----------------+---------------
EVENT_NAME                                                 | COUNT_STAR | SUM_TIMER_WAIT    | MIN_TIMER_WAIT | AVG_TIMER_WAIT
-----------------------------------------------------------+------------+-------------------+----------------+---------------
wait/synch/mutex/innodb/buf_pool_mutex                     |   52601661 | 14768462649368880 |          30080 |      280760386
wait/synch/rwlock/innodb/btr_search_latch                  |   21770192 | 12348868811045840 |          33840 |      567237478
wait/synch/mutex/innodb/kernel_mutex                       |    4852197 |  8269525496176560 |          30080 |     1704284779
wait/synch/mutex/sql/LOCK_open                             |   45259953 |  7979908151321920 |          41360 |      176312780
wait/synch/mutex/mysys/THR_LOCK::mutex                     |   45252774 |  6776374383220800 |          45120 |      149744950
wait/io/file/innodb/innodb_data_file                       |      27639 |  2634221718294000 |         834720 |    95308141332
wait/synch/rwlock/sql/LOCK_grant                           |   22204016 |   319546103784000 |          48880 |       14391365
wait/synch/rwlock/sql/MDL_lock::rwlock                     |    3236964 |   307198891504720 |          48880 |       94903400
wait/synch/cond/sql/COND_thread_cache                      |         28 |   305555951187600 |    10456011040 | 10912712542414
wait/synch/mutex/mysys/BITMAP::mutex                       |    3232346 |   301030615396320 |          41360 |       93130690
wait/synch/mutex/mysys/THR_LOCK_lock                       |    3232347 |   279076711092960 |          41360 |       86338722
wait/synch/mutex/sql/MDL_map::mutex                        |    1620795 |   124778076531520 |          48880 |       76985724
wait/synch/mutex/sql/LOCK_plugin                           |    1620455 |    93265324482000 |          41360 |       57555022
wait/synch/mutex/sql/THD::LOCK_thd_data                    |  136539711 |    18610879764400 |          41360 |         136303
wait/synch/mutex/sql/LOCK_thread_count                     |       1120 |      972573432720 |          41360 |      868369136
wait/io/file/innodb/innodb_log_file                        |        980 |      539175145200 |       20405520 |      550178719
wait/synch/mutex/innodb/log_sys_mutex                      |      22723 |       31094173520 |          30080 |        1368400

How to repeat:
Run sysbench OLTP_RO test(1M rows) for InnoDB 5.5.4/5.5.5
[14 Jul 2010 14:34] Mikhail Izioumtchenko 
it would be interesting to try multiple buffer pools.
Say innodb-buffer-pool-instances=16. innodb-buffer-pool-size has to be 1G or more
or else innodb-buffer-pool-instances is ignored. 
We could tolerate some single buffer pool regressions if multiple buffer
pools show coniderable improvement.
16 was the value I noticed best results on an 8 core machine.
[3 Aug 2010 18:12] Inaam Rana 
Some explanation needed. For 554 we see flush_order_mutex being acquired 8 million times. This is strange. flush_order_mutex is typically acquired when we are trying to insert dirty pages into the flush list. In this case the workload is readonly. What are we inserting into the flush_list? Is it possible that the 554 perf schema output is somehow screwed? (for example, the numbers include the database build phase as well as the benchmark run phase).
[19 Aug 2010 13:39] Inaam Rana 
Ranger,

Any update on this?
[6 Feb 2013 1:18] Omer Barnir 
This was observer over two years ago. Closing as 'Can't Repeat'. If will be observed with current versions will be re-poend