MySQL Performance Schema (5)
This is #5 in a series of blog postings about MySQL Performance Schema.
I mentioned the PERFORMANCE_SCHEMA.SETUP_INSTRUMENTS table in an earlier post. Recently I saw a bug report where I could actually use it in a meaningful way. So today I can talk about SETUP_INSTRUMENTS and with a “realistic” example.
The table has three columns: NAME, ENABLED, TIMED.
mysql> SELECT column_name,column_type FROM information_schema.columns WHERE table_name=’setup_instruments’;
+-------------+------------------+
| column_name | column_type |
+-------------+------------------+
| NAME | varchar(128) |
| ENABLED | enum('YES','NO') |
| TIMED | enum('YES','NO') |
+-------------+------------------+
3 rows in set (0.00 sec)
The NAME column corresponds to the NAME column in EVENTS_WAITS_CURRENT.
The ENABLED column is ‘YES’ to enable instrumenting, ‘NO’ to disable.
The TIMED column is ‘YES’ to enable timing, ‘NO’ to disable.
The ENABLED and TIMED columns are updatable by people with UPDATE privileges.
The table has two uses:
* It’s a list of all the instruments, with their current states.
* It’s a way to set “flag” values.
An early idea was that ENABLED and TIMED values would be variables and one would have to say
SET @@instrumentname1_enabled=’YES’,@@instrumentname2_enabled=’NO’, …;
But this just becomes too unwieldy when there are hundreds of instruments. Especially when we want to enable/disable groups of instruments. Also, we want changes to instruments to have immediate effect on all connections, and that doesn’t happen with flag variables that one changes with SET statements.
There are two ways to restrict the Niagara of events that come to EVENTS_WAITS_… tables. “Post-filtering”: This is the use of WHERE clauses when SELECTing, and we recommend it. “Pre-filtering”: This is the use of SET ENABLED=… clauses in SETUP_INSTRUMENTS, and we recommend it too, but only for a limited set of circumstances. (There are other ways to pre-filter, for example to focus only on particular users, but that’s not in WL#2360.)
The times when one might want to consider pre-filtering are:
* The instrumenting overhead is too high or you conclude all instrumenting is useless. As I indicated in a previous post, this doesn’t appear terribly likely to me. But Performance Schema is very dependent on the characteristic of the chip (or chips) and the operating system. Until it’s out in the field we don’t know where this might be necessary. In this case you just don’t turn anything on in the first place, or you turn everything off explicitly thus
UPDATE performance_schema.setup_instruments SET enabled = ‘NO’;
Alternatively, if it turns out that counting events is good but the timer is in the way, turn on all the instruments but without the timers thus
UPDATE performance_schema.setup_instruments SET enabled = ‘YES’, timed = ‘NO’;
* There’s a specific problem to diagnose, probably in single-user mode, and we want to focus on very few instruments. Remember that the size of EVENTS_WAITS_HISTORY_… tables is limited, so some events might disappear because all the other events crowd them out. In such cases post-filtering is not going to be good enough. To enable only one instrument, but disable all others, I prefer to use a single UPDATE statement with a CASE clause:
UPDATE performance_schema.setup_instruments SET enabled = CASE WHEN name LIKE ‘%things we want%’ THEN ‘YES’ ELSE ‘NO’ END;
But others might find it looks clearer to turn everything off, then turn one instrument on.
UPDATE performance_schema.setup_instruments SET enabled = ‘NO’, timed = ‘NO’;
UPDATE performance_schema.setup_instruments SET enabled = ‘YES’, timed = ‘YES’ WHERE name LIKE ‘%things we want%’;
Now let’s look at that “realistic” example. I’m not claiming it’s “useful” or even “welcome”, but it’s real in the sense that we’re looking at a situation that other people found in the field, which we thought we could shed some light on. It’s not a situation that we imagined for some test/demonstration purpose. It’s Bug #42649 “THR_LOCK_charset global mutex abused by InnoDB”. The scenario is: one of our Lithuanian support people noticed (perhaps with DTrace or strace or one of many operating-system-specific tools) that InnoDB is causing several applications of a mutex named THR_LOCK_charset. One of our Brazilian verifiers was able to confirm this with a debugger. We’ve commented: there’s another way to find this out now, in SQL, with SQL result tables, tied to particular statements. We can show with Performance Schema that the number of invocations for the THR_Lock_charset mutex is between 2 and 10 per INSERT, something which we do not see with other storage engines. In our opinion using Performance Schema is less unwieldy and more informative than other methods. Others will say otherwise. Decide for yourself.
This is all we did:
USE test
DELIMITER //
UPDATE performance_schema.setup_instruments
SET enabled = CASE WHEN name LIKE ‘%THR_LOCK_charset’ THEN ‘YES’ ELSE ‘NO’ END//
DROP TABLE IF EXISTS tb//
DROP PROCEDURE IF EXISTS p//
CREATE TABLE `tb` (
`col1` varchar(200) DEFAULT NULL,
KEY `col1` (`col1`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8//
CREATE PROCEDURE p ()
BEGIN
DECLARE iteration_number INT DEFAULT 1;
DECLARE last_timer_start BIGINT;
WHILE iteration_number <= 30 DO
SET last_timer_start = (SELECT MAX(timer_end) FROM performance_schema.events_waits_current);
INSERT INTO tb VALUES (REPEAT(’a',200));
SELECT iteration_number, event_id, source, timer_wait
FROM performance_schema.events_waits_history
WHERE timer_start > last_timer_start;
SET iteration_number = iteration_number + 1;
END WHILE;
END//
CALL p()//
Explanation: the above code disables every instrument except the one associated with THR_LOCK_charset, then creates a procedure which says INSERT thirty times. Each time, it displays which iteration it’s on, and the events which have happened since the last INSERT, including the source line number and the elapsed time.
The following is a sample run taken today with SUSE 10 x86-32. The results should be repeatable on other machines but of course the values in the TIMER_WAIT column (which is in “picoseconds”) will vary.
The rest of this blog article is a sample run.
linux:/usr/local/mysql/var # /usr/local/mysql/bin/mysql --user=root
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 6.0.10-alpha-perfschema Source distribution
Type 'help;' or '\h' for help. Type '\c' to clear the buffer.
mysql> USE test
Database changed
mysql> DELIMITER //
mysql> UPDATE performance_schema.setup_instruments
-> SET enabled = CASE WHEN name LIKE '%THR_LOCK_charset' THEN 'YES' ELSE 'NO' END//
Query OK, 238 rows affected (0.00 sec)
Rows matched: 239 Changed: 238 Warnings: 0
mysql> DROP TABLE IF EXISTS tb//
Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql> DROP PROCEDURE IF EXISTS p//
Query OK, 0 rows affected, 1 warning (0.01 sec)
mysql> CREATE TABLE `tb` (
-> `col1` varchar(200) DEFAULT NULL,
-> KEY `col1` (`col1`)
-> ) ENGINE=InnoDB DEFAULT CHARSET=utf8//
Query OK, 0 rows affected, 1 warning (0.09 sec)
mysql> CREATE PROCEDURE p ()
-> BEGIN
-> DECLARE iteration_number INT DEFAULT 1;
-> DECLARE last_timer_start BIGINT;
-> WHILE iteration_number <= 30 DO
-> SET last_timer_start = (SELECT MAX(timer_end) FROM performance_schema.events_waits_current);
-> INSERT INTO tb VALUES (REPEAT('a',200));
-> SELECT iteration_number, event_id, source, timer_wait
-> FROM performance_schema.events_waits_history
-> WHERE timer_start > last_timer_start;
-> SET iteration_number = iteration_number + 1;
-> END WHILE;
-> END//
Query OK, 0 rows affected (0.00 sec)
mysql> CALL p()//
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 1 | 131 | charset.c:529 | 44446 |
| 1 | 132 | charset.c:529 | 44446 |
| 1 | 133 | charset.c:529 | 44446 |
| 1 | 134 | charset.c:529 | 44446 |
| 1 | 135 | charset.c:529 | 44446 |
| 1 | 136 | charset.c:529 | 44446 |
| 1 | 137 | charset.c:529 | 44446 |
| 1 | 138 | charset.c:529 | 44446 |
| 1 | 139 | charset.c:529 | 44446 |
| 1 | 140 | charset.c:529 | 44446 |
+------------------+----------+---------------+------------+
10 rows in set (0.00 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 2 | 141 | charset.c:529 | 209084 |
| 2 | 142 | charset.c:529 | 74494 |
+------------------+----------+---------------+------------+
2 rows in set (0.02 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 3 | 143 | charset.c:529 | 826946 |
| 3 | 144 | charset.c:529 | 68234 |
| 3 | 145 | charset.c:529 | 55088 |
+------------------+----------+---------------+------------+
3 rows in set (0.03 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 4 | 146 | charset.c:529 | 293594 |
| 4 | 147 | charset.c:529 | 68234 |
| 4 | 148 | charset.c:529 | 55088 |
| 4 | 149 | charset.c:529 | 58218 |
+------------------+----------+---------------+------------+
4 rows in set (0.05 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 5 | 151 | charset.c:529 | 75746 |
| 5 | 152 | charset.c:529 | 55088 |
| 5 | 153 | charset.c:529 | 55088 |
| 5 | 154 | charset.c:529 | 55088 |
| 5 | 150 | charset.c:529 | 632886 |
+------------------+----------+---------------+------------+
5 rows in set (0.06 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 6 | 155 | charset.c:529 | 267302 |
| 6 | 156 | charset.c:529 | 85762 |
+------------------+----------+---------------+------------+
2 rows in set (0.08 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 7 | 157 | charset.c:529 | 639146 |
| 7 | 158 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.09 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 8 | 159 | charset.c:529 | 223482 |
| 8 | 160 | charset.c:529 | 83258 |
+------------------+----------+---------------+------------+
2 rows in set (0.11 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 9 | 161 | charset.c:529 | 701746 |
| 9 | 162 | charset.c:529 | 74494 |
+------------------+----------+---------------+------------+
2 rows in set (0.12 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 10 | 163 | charset.c:529 | 283578 |
| 10 | 164 | charset.c:529 | 85762 |
+------------------+----------+---------------+------------+
2 rows in set (0.14 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 11 | 165 | charset.c:529 | 595326 |
| 11 | 166 | charset.c:529 | 70738 |
+------------------+----------+---------------+------------+
2 rows in set (0.15 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 12 | 167 | charset.c:529 | 607846 |
| 12 | 168 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.16 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 13 | 169 | charset.c:529 | 262294 |
| 13 | 170 | charset.c:529 | 85136 |
+------------------+----------+---------------+------------+
2 rows in set (0.18 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 14 | 171 | charset.c:529 | 551506 |
| 14 | 172 | charset.c:529 | 74494 |
+------------------+----------+---------------+------------+
2 rows in set (0.19 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 15 | 173 | charset.c:529 | 443208 |
| 15 | 174 | charset.c:529 | 86388 |
+------------------+----------+---------------+------------+
2 rows in set (0.20 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 16 | 175 | charset.c:529 | 639146 |
| 16 | 176 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.22 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 17 | 177 | charset.c:529 | 405022 |
| 17 | 178 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.23 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 18 | 179 | charset.c:529 | 526466 |
| 18 | 180 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.25 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 19 | 321 | charset.c:529 | 55088 |
| 19 | 322 | charset.c:529 | 55088 |
| 19 | 323 | charset.c:529 | 55088 |
| 19 | 324 | charset.c:529 | 55088 |
| 19 | 325 | charset.c:529 | 55088 |
| 19 | 326 | charset.c:529 | 55088 |
| 19 | 317 | charset.c:529 | 55088 |
| 19 | 318 | charset.c:529 | 55088 |
| 19 | 319 | charset.c:529 | 55088 |
| 19 | 320 | charset.c:529 | 55088 |
+------------------+----------+---------------+------------+
10 rows in set (0.26 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 20 | 327 | charset.c:529 | 411282 |
| 20 | 328 | charset.c:529 | 83258 |
+------------------+----------+---------------+------------+
2 rows in set (0.28 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 21 | 329 | charset.c:529 | 614106 |
| 21 | 330 | charset.c:529 | 74494 |
+------------------+----------+---------------+------------+
2 rows in set (0.29 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 22 | 331 | charset.c:529 | 339292 |
| 22 | 332 | charset.c:529 | 84510 |
+------------------+----------+---------------+------------+
2 rows in set (0.31 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 23 | 333 | charset.c:529 | 589066 |
| 23 | 334 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.32 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 24 | 335 | charset.c:529 | 197190 |
| 24 | 336 | charset.c:529 | 83258 |
+------------------+----------+---------------+------------+
2 rows in set (0.34 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 25 | 337 | charset.c:529 | 833206 |
| 25 | 338 | charset.c:529 | 72616 |
+------------------+----------+---------------+------------+
2 rows in set (0.35 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 26 | 339 | charset.c:529 | 632886 |
| 26 | 340 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.36 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 27 | 341 | charset.c:529 | 313626 |
| 27 | 342 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.38 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 28 | 343 | charset.c:529 | 589066 |
| 28 | 344 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.39 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 29 | 345 | charset.c:529 | 310496 |
| 29 | 346 | charset.c:529 | 85762 |
+------------------+----------+---------------+------------+
2 rows in set (0.40 sec)
+------------------+----------+---------------+------------+
| iteration_number | event_id | source | timer_wait |
+------------------+----------+---------------+------------+
| 30 | 347 | charset.c:529 | 789386 |
| 30 | 348 | charset.c:529 | 68234 |
+------------------+----------+---------------+------------+
2 rows in set (0.42 sec)
Query OK, 0 rows affected (0.42 sec)
Leave a Reply