Bug #54726 Inconsistent reporting between mutex and RW lock spin rounds
Submitted: 23 Jun 2010 9:28 Modified: 1 Dec 2010 20:01
Reporter: Mark Leith Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.5 OS:Any
Assigned to: Mark Leith
Triage: Triaged: D3 (Medium) / R1 (None/Negligible) / E1 (None/Negligible)

[23 Jun 2010 9:28] Mark Leith
Description:
The plugin now outputs the following line:

Spin rounds per wait: 31.23 mutex, 17.82 RW-shared, 13.71 RW-excl

These are the ratios between spin rounds to spin waits. For mutexes we report each data point, as such:

Mutex spin waits 187325, rounds 5849403, OS waits 4117

However for RW locks, we do not expose the rounds variables (though the are still tracked internally);

RW-shared spins 23255, OS waits 11027; RW-excl spins 16989, OS waits 4809

To be more consistent across all, we should expose spin rounds for each RW lock type too.

How to repeat:
N/A

Suggested fix:
=== modified file 'storage/innobase/sync/sync0sync.c'
--- storage/innobase/sync/sync0sync.c   revid:vasil.dimov@oracle.com-20100617095953-0v2pan110jlxpeor
+++ storage/innobase/sync/sync0sync.c   2010-06-23 09:17:42 +0000
@@ -1492,14 +1492,16 @@
 
        fprintf(file,
                "Mutex spin waits %llu, rounds %llu, OS waits %llu\n"
-               "RW-shared spins %llu, OS waits %llu;"
-               " RW-excl spins %llu, OS waits %llu\n",
+               "RW-shared spins %llu, rounds %llu, OS waits %llu\n"
+               "RW-excl spins %llu, rounds %llu, OS waits %llu\n",
                mutex_spin_wait_count,
                mutex_spin_round_count,
                mutex_os_wait_count,
                rw_s_spin_wait_count,
+               rw_s_spin_round_count,
                rw_s_os_wait_count,
                rw_x_spin_wait_count,
+               rw_x_spin_round_count,
                rw_x_os_wait_count);
 
        fprintf(file,
[30 Jun 2010 9:13] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/112530

3129 Mark Leith	2010-06-30
      Bug#54726 - Inconsistent reporting between mutex and RW lock spin rounds
       - Add round counts to the output for RW s/x locks
[30 Jun 2010 9:21] Mark Leith
Pushed to mysql-trunk-innodb:

3129 Mark Leith	2010-06-30
     Bug#54726 - Inconsistent reporting between mutex and RW lock spin rounds
      - Add round counts to the output for RW s/x locks

   modified:
     storage/innobase/sync/sync0sync.c
[4 Aug 2010 7:49] Bugs System
Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100630093149-wmc37t128gic933v) (merge vers: 5.1.49) (pib:18)
[4 Aug 2010 8:02] Bugs System
Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100630093149-wmc37t128gic933v) (merge vers: 5.1.49) (pib:18)
[4 Aug 2010 8:18] Bugs System
Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804081533-c1d3rbipo9e8rt1s) (version source revid:marko.makela@oracle.com-20100630093149-wmc37t128gic933v) (merge vers: 5.1.49) (pib:18)
[4 Aug 2010 9:01] Bugs System
Pushed into mysql-next-mr (revid:alik@ibmvm-20100804081630-ntapn8bf9pko9vj3) (version source revid:marko.makela@oracle.com-20100630093149-wmc37t128gic933v) (pib:20)
[17 Aug 2010 20:22] John Russell
As this isn't a fix to functionality, and this particular message seems to be fairly deep in the internals, I'm going to close without adding an entry to the change log in the doc.
[18 Aug 2010 11:14] Mark Leith
Actually, this changes the output of SHOW ENGINE INNODB STATUS, so it should be documented, and the documentation that has any SHOW ENGINE INNODB STATUS output within it should be updated to reflect it. 

Before this change:

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 491, signal count 485
Mutex spin waits 785, rounds 11067, OS waits 123
RW-shared spins 163, OS waits 177; RW-excl spins 2, OS waits 170
Spin rounds per wait: 14.10 mutex, 34.42 RW-shared, 2655.00 RW-excl

After this change:

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2, signal count 2
Mutex spin waits 0, rounds 0, OS waits 0
RW-shared spins 2, rounds 60, OS waits 2
RW-excl spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 mutex, 30.00 RW-shared, 0.00 RW-excl
[18 Aug 2010 16:22] John Russell
Added to change log for 5.5.6:

The output from the SHOW ENGINE INNODB STATUS command now includes
information about "spin rounds" for RW-locks (both shared and
exclusive locks).

Leaving the bug in documenting status for the moment, because instances of SHOW ENGINE INNODB STATUS have not been updated yet. Also, need to ensure there is a good explanation of the idea of "spin" terms such as spin rounds in the doc.
[1 Dec 2010 20:00] John Russell
Only one example showing this level of detail in the Ref Man. Updated per Mark's example.