MySQL Bugs: #68097: Manual does not explain that some P_S instruments must be enabled at startup

Bug #68097	Manual does not explain that some P_S instruments must be enabled at startup
Submitted:	16 Jan 2013 15:58	Modified:	6 Sep 2016 9:32
Reporter:	Valeriy Kravchuk	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Performance Schema	Severity:	S4 (Feature request)
Version:	5.6.9, 5.6.12	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	innodb, missing manual, mutex, performance_schema, setup_instruments

Description:
Manual pages like:

http://dev.mysql.com/doc/refman/5.6/en/setup-instruments-table.html

or 

http://dev.mysql.com/doc/refman/5.6/en/performance-schema-filtering.html

say that:

"Modifications to the setup_instruments table affect monitoring immediately."

But this is not the case for many (but not all) important instruments related to waits, like the following:

wait/synch/mutex/innodb/os_mutex
wait/synch/mutex/innodb/trx_sys_mutex
wait/synch/mutex/innodb/buf_pool_mutex
wait/synch/mutex/innodb/mutex_list_mutex
wait/synch/mutex/innodb/rw_lock_list_mutex
...

They can be enabled only upon startup using options like:

--performance_schema_instrument='wait/synch/mutex/innodb/%=on'

How to repeat:
Start MySQL 5.6.9, check that performance_schema is enabled and then try to enable instruments (and don't forget consumers) "by the manual":

UPDATE performance_schema.setup_instruments SET enabled = 'YES', timed = 'YES' WHERE name LIKE 'wait/synch/mutex/innodb/%';
UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name like 'events_waits%';

Run any load that involve concurrent access to buffer pool from more than one thread and check mutex waits:

select event_name, count_star, sum_timer_wait from performance_schema.events_waits_summary_global_by_event_name where event_name like 'wait/synch/mutex/innodb%' and count_star > 0 order by sum_timer_wait desc limit 10;

Make your own conclusions.

Suggested fix:
Please, document all major instruments in details, including if they can be enabled at runtime. Their set is well defined at RC stage I assume.

Alternatively, explain in the manual how one can find out from the source code if specific instrument can be enabled only upon startup.

Thanks Valeriy !

5 months passed and there is no obvious progress here. Is it really that hard to document what was really implemented?

"Is it really that hard to document what was really implemented?"

Working on it. It's not trivial.

It seems as of 5.6.12 we still have a problem (tested on Windows, but should it really matter?):

C:\Program Files\MySQL\MySQL Server 5.5\bin>mysql -uroot -proot -P3314 test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 14
Server version: 5.6.12 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 'performance_schema';
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| performance_schema | ON    |
+--------------------+-------+
1 row in set (0.19 sec)

mysql> UPDATE performance_schema.setup_instruments SET enabled = 'YES', timed =
'YES' WHERE name LIKE 'wait/synch/mutex/innodb/%';
Query OK, 47 rows affected (0.55 sec)
Rows matched: 47  Changed: 47  Warnings: 0

mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name
like 'events_waits%';
Query OK, 3 rows affected (0.07 sec)
Rows matched: 3  Changed: 3  Warnings: 0

mysql> CREATE TABLE `task` (
    -> `sys_id` char(32) NOT NULL DEFAULT '',
    -> `u_root_cause` char(32) DEFAULT NULL,
    -> `u_business_impact_description` mediumtext,
    -> `u_business_impact_category` mediumtext,
    -> PRIMARY KEY (`sys_id`)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
Query OK, 0 rows affected (0.97 sec)

mysql> insert into task(sys_id) values(rand()*1000000);
Query OK, 1 row affected (0.50 sec)

mysql> insert into task(sys_id) select rand()*1000000 from task;
Query OK, 1 row affected (0.08 sec)
Records: 1  Duplicates: 0  Warnings: 0

mysql> insert into task(sys_id) select rand()*1000000 from task;
Query OK, 2 rows affected (0.07 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> insert into task(sys_id) select rand()*1000000 from task;
Query OK, 4 rows affected (0.04 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql> insert into task(sys_id) select rand()*1000000 from task;
Query OK, 8 rows affected (0.06 sec)
Records: 8  Duplicates: 0  Warnings: 0

...

mysql> insert into task(sys_id) select rand()*1000000 from task;
Query OK, 2048 rows affected (0.72 sec)
Records: 2048  Duplicates: 0  Warnings: 0

mysql> exit
Bye

C:\Program Files\MySQL\MySQL Server 5.5\bin>mysqlslap -uroot -proot --port=3314
--create_schema=test --iterations=2 --no-drop --concurrency=2 --number-of-querie
s=100 --query="select * from task where sys_id=rand()*1000000;"
Benchmark
        Average number of seconds to run all queries: 5.011 seconds
        Minimum number of seconds to run all queries: 4.356 seconds
        Maximum number of seconds to run all queries: 5.667 seconds
        Number of clients running queries: 2
        Average number of queries per client: 50

C:\Program Files\MySQL\MySQL Server 5.5\bin>mysqlslap -uroot -proot --port=3314
--create_schema=test --iterations=2 --no-drop --concurrency=4 --number-of-querie
s=100 --query="select * from task where sys_id=rand()*1000000;"
Benchmark
        Average number of seconds to run all queries: 4.043 seconds
        Minimum number of seconds to run all queries: 4.028 seconds
        Maximum number of seconds to run all queries: 4.059 seconds
        Number of clients running queries: 4
        Average number of queries per client: 25

C:\Program Files\MySQL\MySQL Server 5.5\bin>mysql -uroot -proot -P3314 test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 29
Server version: 5.6.12 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 engine innodb mutex;
+--------+-------------------------+-------------+
| Type   | Name                    | Status      |
+--------+-------------------------+-------------+
| InnoDB | dict0dict.cc:887        | os_waits=5  |
| InnoDB | trx0sys.cc:594          | os_waits=1  |
| InnoDB | log0log.cc:737          | os_waits=76 |
| InnoDB | buf0buf.cc:1290         | os_waits=5  |
| InnoDB | buf0buf.cc:1242         | os_waits=59 |
| InnoDB | fil0fil.cc:1682         | os_waits=2  |
| InnoDB | combined buf0buf.cc:992 | os_waits=1  |
| InnoDB | dict0dict.cc:2434       | os_waits=1  |
| InnoDB | dict0dict.cc:896        | os_waits=3  |
| InnoDB | log0log.cc:799          | os_waits=25 |
| InnoDB | hash0hash.cc:392        | os_waits=1  |
| InnoDB | hash0hash.cc:392        | os_waits=1  |
| InnoDB | hash0hash.cc:392        | os_waits=1  |
| InnoDB | combined buf0buf.cc:993 | os_waits=33 |
+--------+-------------------------+-------------+
14 rows in set (0.16 sec)

mysql> select event_name, count_star, sum_timer_wait from performance_schema.eve
nts_waits_summary_global_by_event_name where event_name like 'wait/synch/mutex/i
nnodb%' and count_star > 0 order by sum_timer_wait desc limit 10;
+----------------------------------------+------------+----------------+
| event_name                             | count_star | sum_timer_wait |
+----------------------------------------+------------+----------------+
| wait/synch/mutex/innodb/trx_mutex      |       9384 |     1668719840 |
| wait/synch/mutex/innodb/trx_undo_mutex |       6685 |     1524624182 |
+----------------------------------------+------------+----------------+
2 rows in set (20.41 sec)

So, statement at http://dimitrik.free.fr/blog/archives/07-01-2013_07-31-2013.html#170:

"ALL PFS instrumentation is completely dynamic"

seems not 100% true, and, surely, we still have something to document here :)

Added 5.6.12 as version affected.

Added tag.

Any ideas on when we can expect this documented finally?

Apparently the same is true for *disabling* instruments:

MySQL [performance_schema]> select @@version;
+--------------+
| @@version    |
+--------------+
| 5.6.23-debug |
+--------------+
1 row in set (0.00 sec)

MySQL [performance_schema]> select @@performance_schema;
+----------------------+
| @@performance_schema |
+----------------------+
|                    1 |
+----------------------+
1 row in set (0.00 sec)

MySQL [performance_schema]> 
MySQL [performance_schema]> use performance_schema;
Database changed
MySQL [performance_schema]> 
MySQL [performance_schema]> update setup_consumers set enabled= 'YES';
Query OK, 12 rows affected (0.00 sec)
Rows matched: 12  Changed: 12  Warnings: 0

MySQL [performance_schema]> update setup_instruments set enabled= 'YES', timed= 'YES';
Query OK, 559 rows affected (0.03 sec)
Rows matched: 559  Changed: 559  Warnings: 0

MySQL [performance_schema]> update setup_objects set enabled= 'YES', timed= 'YES';
Query OK, 4 rows affected (0.00 sec)
Rows matched: 4  Changed: 4  Warnings: 0

MySQL [performance_schema]> 
MySQL [performance_schema]> create table test.t1 (i int);
Query OK, 0 rows affected (0.52 sec)

MySQL [performance_schema]> insert into test.t1 values (1),(2);
Query OK, 2 rows affected (0.06 sec)
Records: 2  Duplicates: 0  Warnings: 0

MySQL [performance_schema]> drop table test.t1;
Query OK, 0 rows affected (0.51 sec)

MySQL [performance_schema]> 
MySQL [performance_schema]> select count(*) from events_waits_summary_global_by_event_name where count_star > 0 order by event_name;
+----------+
| count(*) |
+----------+
|       15 |
+----------+
1 row in set (0.02 sec)

MySQL [performance_schema]> 
MySQL [performance_schema]> update setup_consumers set enabled= 'NO';
Query OK, 12 rows affected (0.00 sec)
Rows matched: 12  Changed: 12  Warnings: 0

MySQL [performance_schema]> update setup_instruments set enabled= 'NO', timed= 'NO';
Query OK, 559 rows affected (0.03 sec)
Rows matched: 559  Changed: 559  Warnings: 0

MySQL [performance_schema]> update setup_objects set enabled= 'NO', timed= 'NO';
Query OK, 4 rows affected (0.00 sec)
Rows matched: 4  Changed: 4  Warnings: 0

MySQL [performance_schema]> 
MySQL [performance_schema]> truncate table events_waits_summary_global_by_event_name;
Query OK, 0 rows affected (0.01 sec)

MySQL [performance_schema]> 
MySQL [performance_schema]> select sleep(2);
+----------+
| sleep(2) |
+----------+
|        0 |
+----------+
1 row in set (2.00 sec)

MySQL [performance_schema]> select * from events_waits_summary_global_by_event_name where count_star > 0 order by event_name;
+---------------------------------------------+------------+----------------+----------------+----------------+----------------+
| EVENT_NAME                                  | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
+---------------------------------------------+------------+----------------+----------------+----------------+----------------+
| idle                                        |         78 | 11084192000000 |       19000000 |   142105000000 | 10954914000000 |
| wait/synch/mutex/innodb/trx_mutex           |        286 |      808631824 |        1932560 |        2827384 |       65206442 |
| wait/synch/mutex/innodb/trx_undo_mutex      |         18 |       48393170 |        2536688 |        2688126 |        3114832 |
| wait/synch/mutex/mysys/THR_LOCK::mutex      |          2 |        4690518 |        1985340 |        2345056 |        2705178 |
| wait/synch/rwlock/innodb/dict_table_stats   |          8 |       39865546 |        2834286 |        4982838 |        9014418 |
| wait/synch/rwlock/innodb/fil_space_latch    |          9 |       30852752 |        2514764 |        3427858 |        5401018 |
| wait/synch/rwlock/innodb/index_tree_rw_lock |          3 |       10133760 |        2929696 |        3377920 |        3758342 |
| wait/synch/rwlock/sql/MDL_lock::rwlock      |          4 |        9130940 |        2042586 |        2282532 |        2483502 |
+---------------------------------------------+------------+----------------+----------------+----------------+----------------+
8 rows in set (0.01 sec)

It turns out that from a docs standpoint, there is not much that can be done here. I have modified
http://dev.mysql.com/doc/refman/5.6/en/performance-schema-pre-filtering.html
to point out that not all instrument changes affect monitoring immediately:

"
Modifications to any of these tables affect monitoring immediately, with some exceptions:

* Modifications to some instruments in the setup_instruments table are effective only at server startup; changing them at runtime has no effect. This affects primarily mutexes, conditions, and rwlocks in the server, although there may be other instruments for which this is true.

* Modifications to the setup_actors table affect only foreground threads created subsequent to the modification, not existing threads.
"

I am changing this bug from a docs bug to a feature request. The request is that there be a way for users to determine, for any given instrument, whether changes at runtime will have an effect on monitoring. That will enable users to tell which must be changed at startup.