MySQL Bugs: #70819: SHOW ENGINE INNODB MUTEX does NOT work with timed

Bug #70819	SHOW ENGINE INNODB MUTEX does NOT work with timed_mutex properly
Submitted:	5 Nov 2013 11:55	Modified:	22 Oct 2014 15:30
Reporter:	Valeriy Kravchuk	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.6.14	OS:	Any
Assigned to:	Stefan Hinz	CPU Architecture:	Any
Tags:	debug, regression, timed_mutexes

Description:
According to the manual:

http://dev.mysql.com/doc/refman/5.6/en/server-system-variables.html#sysvar_timed_mutexes

and 

http://dev.mysql.com/doc/refman/5.6/en/show-engine.html

we still should be able to get additional information about mutexes in -debug builds (including os_wait_times when timed_mutexes=1). This is how it looks in 5.5.34:

mysql> show engine innodb mutex;
+--------+-------------------------------------------+-------------------------------------------------------------------------------------+
| Type   | Name                                      | Status                                                                              |
+--------+-------------------------------------------+-------------------------------------------------------------------------------------+
| InnoDB | &recv_sys->mutex:log0recv.c               | count=307, spin_waits=6, spin_rounds=90, os_waits=3, os_yields=3, os_wait_times=8   |
| InnoDB | &log_sys->log_flush_order_mutex:log0log.c | count=41533, spin_waits=2, spin_rounds=30, os_waits=1, os_yields=1, os_wait_times=0 |
| InnoDB | &log_sys->mutex:log0log.c                 | count=47132, spin_waits=2, spin_rounds=30, os_waits=1, os_yields=1, os_wait_times=0 |
| InnoDB | &kernel_mutex:srv0srv.c                   | count=25347, spin_waits=2, spin_rounds=30, os_waits=1, os_yields=1, os_wait_times=0 |
| InnoDB | log0log.c:832                             | os_waits=8                                                                          |
| InnoDB | combined buf0buf.c:938                    | os_waits=2                                                                          |
| InnoDB | rw_lock_mutexes                           | count=0, spin_waits=0, spin_rounds=0, os_waits=0, os_yields=0, os_wait_times=0      |
+--------+-------------------------------------------+-------------------------------------------------------------------------------------+
7 rows in set (0.01 sec)

But in -debug builds of 5.6.14 most of this information is missing:

openxs@ao756:~/dbs/5.6$ bin/mysql --no-defaults -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.6.14-debug MySQL Community Server (GPL)

Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show variables like 'version%';
+-------------------------+------------------------------+
| Variable_name           | Value                        |
+-------------------------+------------------------------+
| version                 | 5.6.14-debug                 |
| version_comment         | MySQL Community Server (GPL) |
| version_compile_machine | x86_64                       |
| version_compile_os      | Linux                        |
+-------------------------+------------------------------+
4 rows in set (0,00 sec)

mysql> show variables like 'timed%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| timed_mutexes | ON    |
+---------------+-------+
1 row in set (0,00 sec)

mysql> show engine innodb mutex;
+--------+-------------------------+--------------------------------------------------------------------------------+
| Type   | Name                    | Status                                                                         |
+--------+-------------------------+--------------------------------------------------------------------------------+
| InnoDB | log0log.cc:737          | os_waits=5                                                                     |
| InnoDB | buf0buf.cc:1242         | os_waits=6                                                                     |
| InnoDB | fil0fil.cc:1690         | os_waits=55                                                                    |
| InnoDB | dict0dict.cc:896        | os_waits=4                                                                     |
| InnoDB | log0log.cc:799          | os_waits=7                                                                     |
| InnoDB | combined buf0buf.cc:993 | os_waits=3                                                                     |
| InnoDB | rw_lock_mutexes         | count=0, spin_waits=0, spin_rounds=0, os_waits=0, os_yields=0, os_wait_times=0 |
+--------+-------------------------+--------------------------------------------------------------------------------+
7 rows in set (0,00 sec)

Where are the details for other mutexes but rw_lock_mutexes?

How to repeat:
Built MySQL 5.6 with debug option: -DWITH_DEBUG=ON, like this:

cd ~/bzr/mysql-5.5
bzr pull
cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_DEBUG=ON -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DWITH_EMBEDDED_SERVER=OFF -DCMAKE_INSTALL_PREFIX=/home/openxs/dbs/5.5
make clean
make
make install && make clean

then start it with timed_mutexes=1, like this:

cd ~/dbs/5.5
scripts/mysql_install_db --no-defaults
bin/mysqld_safe --no-defaults --timed_mutexes &

and load test case (see file test.sql.gz) from Bug #68079, for example:

bin/mysql --no-defaults -uroot test < /tmp/test.sql

Then check the output of SHOW ENGINE INNODB MUTEX. Compare to the same output for the same steps with MySQL 5.5.

Suggested fix:
I understand that this may be "by design" because of PERFORMANCE_SCHEMA etc, but then document this change properly. Otherwise just fix it, looks like a genuine regression for now.

Ran a couple of test cases and got the same results.

Hence, verified as described ...

Deserves one of the actions as proposed by the reporter.

timed_mutex was a hack that was eventually moved under debug code. I can't imagine in their right mind profiling for performance with InnoDB debug mode enabled. Please fix the documentation.

Remove this feature (providing extra information in debug builds) entirely even in 5.6+, I don't mind (not sure if this idea follows deprecation process properly though). 

But then remove it everywhere and document properly, explaining in details how to get the same information via PERFORMANCE_SCHEMA and what are performance implications in both cases.

In the meantime I still consider current state:

mysql> show engine innodb mutex;
+--------+-------------------------+--------------------------------------------------------------------------------+
| Type   | Name                    | Status
                                            |
+--------+-------------------------+--------------------------------------------------------------------------------+
| InnoDB | log0log.cc:737          | os_waits=5
                                            |
| InnoDB | buf0buf.cc:1242         | os_waits=6
                                            |
| InnoDB | fil0fil.cc:1690         | os_waits=55
                                            |
| InnoDB | dict0dict.cc:896        | os_waits=4
                                            |
| InnoDB | log0log.cc:799          | os_waits=7
                                            |
| InnoDB | combined buf0buf.cc:993 | os_waits=3
                                            |
| InnoDB | rw_lock_mutexes         | count=0, spin_waits=0,
spin_rounds=0, os_waits=0, os_yields=0, os_wait_times=0 |
+--------+-------------------------+--------------------------------------------------------------------------------+
7 rows in set (0,00 sec)

a regression and half-removed feature. I see the bug to fix, not something to just document. I wonder what text may explain in a polite way why for rw_lock_mutexes the (useless) information is still produced while for majority of cases it is no longer produced and collected...

Most SHOW MUTEX output was removed in 5.6.14, and was removed entirely in 5.7.2. This change was implemented when InnoDB mutex code was refactored as part of a server cleanup effort. 

A removal notice has been added to the MySQL 5.6 and 5.7 What's New documentation and to the SHOW ENGINE documentation. The notice will appear soon, with the next published documentation build.

Under "Removed Features".
http://dev.mysql.com/doc/refman/5.6/en/mysql-nutshell.html
http://dev.mysql.com/doc/refman/5.7/en/mysql-nutshell.html

https://dev.mysql.com/doc/refman/5.6/en/show-engine.html
https://dev.mysql.com/doc/refman/5.7/en/show-engine.html