MySQL Bugs: #77314: Missing mutex metrics in 5.7.7

Bug #77314	Missing mutex metrics in 5.7.7
Submitted:	11 Jun 2015 11:28	Modified:	29 Jun 2015 18:17
Reporter:	Károly Nagy	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.7.7-rc	OS:	Linux
Assigned to:	MySQL Verification Team	CPU Architecture:	Any
Tags:	innodb, metrics, mutex, spin wait

Description:
Mutex spin waits. rounds and OS waits are all showing 0 even though the server is actively running. The RW- metrics are showing realistic numbers:

Mutex spin waits 0, rounds 0, OS waits 0
RW-shared spins 1063527, rounds 1514670, OS waits 451143
RW-excl spins 162226, rounds 38489157559, OS waits 23980
RW-sx spins 1596, rounds 26563, OS waits 654

How to repeat:
Run SHOW ENGINE INNODB STATUS\G

Suggested fix:
Make the metrics count properly.

Or alternetively remove the line from show engine innodb status if the metrics are obsoleted by some others.

Example output from 5.6.24:

Mutex spin waits 4154227, rounds 5925250, OS waits 81856
RW-shared spins 412151, rounds 5669562, OS waits 84611
RW-excl spins 189538, rounds 3258856, OS waits 37439

Functionality has been like this since 5.7.2.
On current 5.7 sources, we can see variable 'mutex_spin_wait_count' is never incremented.

E:\git\mysql-5.7\storage\innobase>grep -r "mutex_spin_wait_count" .
./include/sync0sync.h:extern mutex_counter_t    mutex_spin_wait_count;
./include/sync0sync.h:ib_uint64_t mutex_spin_wait_count_get();
./sync/sync0sync.cc:mutex_counter_t     mutex_spin_wait_count;
./sync/sync0sync.cc:            (ib_uint64_t) mutex_spin_wait_count,
./sync/sync0sync.cc:            (mutex_spin_wait_count_get() ? mutex_spin_wait_count_get() : 1),
./sync/sync0sync.cc:mutex_spin_wait_count_get()
./sync/sync0sync.cc:    return(mutex_spin_wait_count);

On 5.7.1:

F:\ade\mysql_archives\5.7\5.7.1\mysql-5.7.1-m11\storage\innobase>grep -r "mutex_spin_wait_count" .
./sync/sync0sync.cc:static ib_counter_t<ib_int64_t, IB_N_SLOTS> mutex_spin_wait_count;
./sync/sync0sync.cc:    mutex_spin_wait_count.add(counter_index, 1);
./sync/sync0sync.cc:            (ib_uint64_t) mutex_spin_wait_count,
./sync/sync0sync.cc:            (mutex_spin_wait_count ? mutex_spin_wait_count : 1),

On 5.7.8 we can get the spins like this, however 'show engine innodb status' still shows 0 for the Mutex spin waits.

mysql> show engine innodb mutex;
Empty set (0.00 sec)

mysql> SET GLOBAL innodb_monitor_enable="latch";
Query OK, 0 rows affected (0.00 sec)

mysql> show engine innodb mutex;
+--------+-------------------------+--------------------------+
| Type   | Name                    | Status                   |
+--------+-------------------------+--------------------------+
| InnoDB | BUF_POOL                | spins=49,waits=1,calls=2 |
| InnoDB | LOG_SYS                 | spins=39,waits=1,calls=2 |
| InnoDB | BUF_BLOCK_MUTEX         | spins=4,waits=0,calls=7  |
| InnoDB | DICT_SYS                | spins=2,waits=0,calls=4  |
| InnoDB | FIL_SYSTEM              | spins=9,waits=0,calls=22 |
| InnoDB | RW_LOCK_LIST            | spins=3,waits=0,calls=3  |
| InnoDB | TRX_POOL                | spins=1,waits=0,calls=1  |
| InnoDB | TRX                     | spins=2,waits=0,calls=3  |
| InnoDB | TRX_SYS                 | spins=11,waits=0,calls=5 |
| InnoDB | SRV_SYS_TASKS           | spins=3,waits=0,calls=5  |
| InnoDB | rwlock: fil0fil.cc:1333 | waits=22                 |
+--------+-------------------------+--------------------------+
11 rows in set (0.00 sec)

mysql> select version();
+-----------+
| version() |
+-----------+
| 5.7.8-rc  |
+-----------+
1 row in set (0.00 sec)

The information will be available via show engine innodb mutex. I will remove the mention of the variables from show status.

Posted by developer:
 
Fixed as of the upcoming 5.7.8, 5.8.0 releases, and here's the changelog entry:

SHOW ENGINE INNODB STATUS no longer reports mutex metrics. Mutex metrics
are now reported by SHOW ENGINE INNODB MUTEX.