Bug #37424 Considerable performance degradation in Falcon from 6.0.4 to 6.0.5
Submitted: 16 Jun 2008 8:20 Modified: 26 May 2010 17:50
Reporter: Philip Stoev Email Updates:
Status: Unsupported Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:6.0.5 OS:Any
Assigned to: Kelly Long CPU Architecture:Any
Tags: F_PERFORMANCE
Triage: Triaged: D2 (Serious)

[16 Jun 2008 8:20] Philip Stoev
Description:
When running sysbench on 6.0.5, the numbers are a considerably smaller than they are for 6.0.4.

This is on a 2-core machine, debug binary, falcon_lock_wait_timeout=0, 720-second test with 10 threads:

6.0.4:
    transactions:                        67852  (94.23 per sec.)
    deadlocks:                           32844  (45.61 per sec.)
    read/write requests:                 1815620 (2521.53 per sec.)
6.0.5:
    transactions:                        28845  (40.05 per sec.)
    deadlocks:                           13293  (18.46 per sec.)
    read/write requests:                 760609 (1055.98 per sec.)

Innodb does not exhibit this regression. Both debug and non-debug binaries were tested on both 2-core and 8-core machines. Both 10 and 100 threads were tested and both 10-minute and 3-hour tests were performed with various table sizes.

Oprofile shows the following as being the most used functions:

For 6.0.4:

samples  %        image name               symbol name
509411   41.4194  no-vmlinux               (no symbols)
46598     3.7888  mysqld                   Record::addRef()
36387     2.9586  mysqld                   my_hash_sort_simple
30671     2.4938  mysqld                   SyncObject::lock(Sync*, LockType, int)
19435     1.5802  mysqld                   SyncObject::unlock(Sync*, LockType)
16090     1.3083  mysqld                   Table::fetch(int)
16077     1.3072  libc-2.8.so              malloc
15162     1.2328  mysqld                   _db_enter_
14907     1.2121  mysqld                   IndexPage::findNodeInLeaf(IndexKey*, IndexKey*)
14682     1.1938  libpthread-2.8.so        pthread_getspecific
14212     1.1556  mysqld                   Bitmap::nextSet(int)
14200     1.1546  mysqld                   code_state

For 6.0.5:

samples  %        image name               symbol name
338705   26.1383  no-vmlinux               (no symbols)
127634    9.8497  mysqld                   Record::addRef()
113885    8.7887  mysqld                   SyncObject::lock(Sync*, LockType, int)
84493     6.5204  mysqld                   SyncObject::unlock(Sync*, LockType)
51897     4.0050  mysqld                   Table::fetch(int)
40054     3.0910  mysqld                   RecordVersion::fetchVersion(Transaction*)
38903     3.0022  mysqld                   Bitmap::nextSet(int)
30008     2.3158  mysqld                   IndexRootPage::scanIndex(Dbb*, int, int, IndexKey*, IndexKey*, int, unsigned int, Bitmap*)
28264     2.1812  mysqld                   Record::release()
26865     2.0732  mysqld                   Bitmap::set(int)
26419     2.0388  mysqld                   Record::poke()
25459     1.9647  mysqld                   Sync::lock(LockType)
22700     1.7518  mysqld                   StorageDatabase::nextIndexed(StorageTable*, void*, int, bool)
14938     1.1528  mysqld                   my_hash_sort_simple
14269     1.1012  libpthread-2.8.so        pthread_mutex_lock
14268     1.1011  mysqld                   RecordLeaf::fetch(int)
11725     0.9048  [vdso] (tgid:26275 range:0x110000-0x111000) (no symbols)
11605     0.8956  libpthread-2.8.so        __pthread_mutex_unlock_usercnt
11138     0.8595  mysqld                   Sync::Sync(SynchronizationObject*, char const*)
10459     0.8071  mysqld                   Bitmap::decompose(int, unsigned int*)
8485      0.6548  mysqld                   Sync::~Sync()
8352      0.6445  libc-2.8.so              malloc
8267      0.6380  mysqld                   code_state

Please note how many Falcon functions have risen to the top of the report at the expense of non-Falcon functions, such as my_hash_sort_simple, malloc, and code_state.

How to repeat:
Run sysbench against 6.0.5

Suggested fix:
It seems to me there is a compilation issue.
[16 Jun 2008 12:26] Philip Stoev
720-second sysbench test with 10 users, falcon_lock_wait_timeout=0:

build-team 6.0.4 debug		read/write requests: 3570408 (4958.49 per sec.)
build-team 6.0.4 nondebug	read/write requests: 3540522 (4917.05 per sec.)
build-team 6.0.5 debug		read/write requests: 688736 (956.21 per sec.)
build-team 6.0.5 nondebug	read/write requests: 714368 (991.55 per sec.)
self-compiled 6.0.5 debug	read/write requests: 690032 (957.96 per sec.)
self-compiled 6.0.5 nondebug	read/write requests: 681630 (946.31 per sec.)
self-compiled 6.0-falcon nondbg read/write requests: 713676 (990.77 per sec.)

The -03 flag appears to kick in properly for all nondebug builds.
[19 Jun 2008 7:49] Mats Kindahl
From looking at the description of the bug, there are a few things that
I find strange (and hints that it is not a compiler problem).

- The two functions SyncObject::lock() and ::unlock() have risen
  significantly. Now, I don't know what the sync object does, but I
  assume that it is some form of mutex. The fact that they have risen,
  hints at some kind of congestion on the locks, which can be caused by
  a number of factors, including at least:

  - Wrong phase of the moon. Just bad luck with this run, is it
    repeatable? Given enough time, even unlikely events happen.

  - Competing for memory or disk. Now, it is hard to tell since I don't
    know if the figures are real time, or CPU time. It would be nice to
    have the real time, but also the user time and system time since
    that helps identify if this is an OS issue (e.g., thrashing on
    disk) or other issues.

  - Bad use of locks that prevents the system from leaving the
    pathological state once it's there.

- The ::addRef() and ::lock() and ::unlock() has risen together. Since I
  cannot envision that the addRef() does anything complicated that can
  cause an increase in CPU usage, I draw the conclusion that the the
  figures are based on the real time, not CPU time.

  This hints at some form of memory (or disk) convoying/caravaning where
  the same memory is being accessed by several threads.

  The relatively small increase suggests that it is memory that is the
  accessed resource, not disk.

- The fact that some record manipulation functions has entered the arena
  hints at memory (or disk) convoying/caravaning as well.

- This is not related to the problem at hand, but what on earth are the
  Bitmap manipulation functions doing in the list?  They should be
  inlined because they are usually small and executed often. Are the
  definitions available in the header files so that the compiler has a
  chance to inline them?

- Also note that the index scanning function have appeared at the list.

If it is a compiler problem, you are likely to see a repeatable
degradation. Compilers are pretty predictable in this aspect: they will
follow the same rules when generating the code, so there is no
randomness involved. Considering that you have supplied -O3, I would
rule out code generation issues as a performance degradation of this level.
[1 Jul 2008 19:16] Kelly Long
---- summary -----
I did some comparisons on this to find the changeset that caused the slow down.  Vlad will look at this next.  The change set causing this slow down:

         revno: 2597.22.1
         revision-id: sp1r-vvaintroub@wva.-20080328064007-14330
         parent: sp1r-hakank/hakan@lu0011.(none)-20080322192653-14335
         committer: vvaintroub@wva.
         timestamp: Fri 2008-03-28 07:40:07 +0100
         message:
           WL#3763: Supernodes
           - If insert is done in decreasing order of values, no supernodes were
           created. Now fixed - if index node is inserted at the start
           of the page, next node can become supernode, if the gap between the
           start of the page and first supernode is too large.
           - Allow supernode on duplicate keys.
           - Do not always delete supernode if previous node is deleted, but check
             whether saving it makes sense.

---- detail -----
Below you'll find a list of revision ids followed by one of the results from the sysbench test.  All results are similar to the one I choose to list.  For the revisions I tested there is a line below the revision with the results.  There is also a degradation issue as the test continues.  You can see this in the locations I ran the test 3 times witout restarting the database.  The results below a "no supernodes" comment are a slightly modifed code base where I turned off the supernodes (always return false in the checkAddSupernode() routine).

cd mysql-6.0
bzr log --show-ids | egrep 'revision-id:|tags:' > /tmp/bzr-6.0-logs-show-ids.2

revision-id: sp1r-cbell/Chuck@mysql_cab_desk.-20080411171935-14416
#    transactions:                        31029  (43.08 per sec.)
    revision-id: sp1r-hakank/hakan@lu0011.(none)-20080410190122-10487
--- cut ---
    revision-id: sp1r-hakank/hakan@lu0011.(none)-20080330122626-54363
    revision-id: sp1r-hakank/hakan@lu0011.(none)-20080330095349-54376
#    transactions:                        30751  (42.69 per sec.)
        revision-id: sp1r-hakank/hakan@lu0011.(none)-20080330094706-53538
        revision-id: sp1r-hakank/hakan@lu0011.(none)-20080330090700-53665
    revision-id: sp1r-hakank/hakan@lu0011.(none)-20080330095259-57282
    revision-id: sp1r-cpowers@xeno.mysql.com-20080330072429-57288
    revision-id: sp1r-cpowers@xeno.mysql.com-20080329182218-57524
    revision-id: sp1r-cpowers@xeno.mysql.com-20080328232654-57519
    revision-id: sp1r-cpowers@xeno.mysql.com-20080328224644-57519
        revision-id: sp1r-cpowers@xeno.mysql.com-20080328224436-22681
    revision-id: sp1r-hakank/hakan@lu0011.(none)-20080328201039-56444
#    transactions:                        96533  (134.06 per sec.)
#    transactions:                        61482  (85.39 per sec.)
#    transactions:                        45112  (62.63 per sec.)
###### no supernodes
#    transactions:                        128358 (178.27 per sec.)
#    transactions:                        128162 (178.00 per sec.)
#    transactions:                        129308 (179.59 per sec.)
    revision-id: sp1r-hakank/hakan@lu0011.(none)-20080328183802-56447
        revision-id: sp1r-hakank/hakan@lu0011.(none)-20080328182226-61590
    revision-id: sp1r-hakank/hakan@lu0011.(none)-20080328175251-56251
    revision-id: sp1r-hakank/hakan@lu0011.(none)-20080328174917-56243
        revision-id: sp1r-hakank/hakan@lu0011.(none)-20080328171351-61576
        revision-id: sp1r-hakank/hakan@lu0011.(none)-20080328164232-03126
    revision-id: sp1r-klewis@klewis-mysql.-20080328153527-21606
#    transactions:                        78300  (108.74 per sec.)
#    transactions:                        41569  (57.73 per sec.)
#    transactions:                        35202  (48.88 per sec.)
###### no supernodes 20080328153527
#    transactions:                        128828 (178.92 per sec.)
#    transactions:                        128891 (179.01 per sec.)
#    transactions:                        129209 (179.44 per sec.)
        revision-id: sp1r-vvaintroub@wva.-20080328065431-25981
        revision-id: sp1r-vvaintroub@wva.-20080328064007-14330
    revision-id: sp1r-klewis@klewis-mysql.-20080328042148-22090
#    transactions:                        142006 (197.21 per sec.)
        revision-id: sp1r-hakank/hakan@lu0011.(none)-20080327203449-26939
        revision-id: sp1r-hakank/hakan@lu0011.(none)-20080327114539-60369
        revision-id: sp1r-hakank/hakan@lu0011.(none)-20080326193327-64165
--- cut ---
    revision-id: sp1r-hakank/hakan@lu0011.(none)-20080313141037-15204
revision-id: sp1r-cbell/Chuck@mysql_cab_desk.-20080407153214-28468
#    transactions:                        152292 (211.50 per sec.)
[21 Jul 2008 15:12] Philip Stoev
Here are some more results with a freshly cloned mysql-6.0-falcon:

no supernodes:

    transactions:                        18326  (61.04 per sec.)
    deadlocks:                           7969   (26.54 per sec.)
    read/write requests:                 475194 (1582.86 per sec.)
    other operations:                    44621  (148.63 per sec.)

with supernodes:

    transactions:                        18259  (60.81 per sec.)
    deadlocks:                           8123   (27.05 per sec.)
    read/write requests:                 476286 (1586.17 per sec.)
    other operations:                    44641  (148.67 per sec.)
	
Notice there is no difference in the results and that they are somewhere between the "good" and the "bad" values reported initially in this report. All tests were done on the same machine.
[21 Jul 2008 17:07] Kevin Lewis
Philip,  Please try --falcon_user_supernodes=0 instead of --falcon_user_supernodes=off.
[21 Jul 2008 17:27] Philip Stoev
Result with --falcon_use_supernodes=0 --mysqld=--skip-falcon-use-supernodes:

    transactions:                        18390  (61.26 per sec.)
    deadlocks:                           7997   (26.64 per sec.)
    read/write requests:                 476912 (1588.58 per sec.)
    other operations:                    44777  (149.15 per sec.)
[21 Jul 2008 17:34] Philip Stoev
Same results were observed when running with just --falcon_use_supernodes=0
[21 Jul 2008 17:38] Kevin Lewis
Kelly, Please take another look.
[21 Jul 2008 17:57] Philip Stoev
A 720 second test with --falcon_use_supernodes=0 (previous tests were 600-second):

    transactions:                        28323  (39.32 per sec.)
    deadlocks:                           12303  (17.08 per sec.)
    read/write requests:                 734253 (1019.45 per sec.)
    other operations:                    68949  (95.73 per sec.)
[14 Nov 2008 11:19] Philip Stoev
Sysbench "classic" 0.4.8 was used for this bug, as downloadable from http://sourceforge.net/projects/sysbench , test name OLTP.
[14 Nov 2008 12:18] Philip Stoev
Command lines:

./mysql-test-run.pl \
--start-and-exit \
--mysqld=--log-output=file \
--mysqld-falcon_lock_wait_timeout=0

./sysbench \
--test=oltp \
--mysql-host=localhost\
--mysql-port=9306 \
--mysql-user=root \
--mysql-db=test \
--mysql-table-engine=Falcon \
--mysql-engine-trx=yes \
--oltp-table-size=100000 \
prepare

./sysbench \
--test=oltp \
--mysql-host=localhost \
--mysql-port=9306 \
--mysql-user=root \
--mysql-db=test \
--mysql-table-engine=Falcon \
--mysql-engine-trx=yes \
--max-requests=0 \
--max-time=720 \
--num-threads=10 \
run