Description:
I am playing with PERFORMANCE_SCHEMA as a replacement for SHOW PROFILE (that is deprecated and may disappear in MySQL 5.7+). In the process I've noted one strange difference:
C:\Program Files\MySQL\MySQL Server 5.6\bin>mysql -uroot -proot -P3314
Warning: Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.6.14-log 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> use performance_schema
Database changed
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql> select sql_no_cache id1, max(id2) from test.tgb where id1=6783 and id2<10
000 group by id1;
+------+----------+
| id1 | max(id2) |
+------+----------+
| 6783 | 9971 |
+------+----------+
1 row in set (0.06 sec)
mysql> show profile for query 1;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000488 |
| checking permissions | 0.000141 |
| Opening tables | 0.031805 |
| init | 0.000154 |
| System lock | 0.000035 |
| optimizing | 0.000071 |
| statistics | 0.029156 |
| preparing | 0.000148 |
| executing | 0.000011 |
| Sending data | 0.000215 |
| end | 0.000018 |
| query end | 0.000022 |
| closing tables | 0.000035 |
| freeing items | 0.000300 |
| cleaning up | 0.000066 |
+----------------------+----------+
15 rows in set, 1 warning (0.00 sec)
Now, same query again, but "profile" is taken from P_S:
mysql> set profiling=0;
Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql> select sql_no_cache id1, max(id2) from test.tgb where id1=6783 and id2<10
000 group by id1;
+------+----------+
| id1 | max(id2) |
+------+----------+
| 6783 | 9971 |
+------+----------+
1 row in set (0.00 sec)
mysql> SELECT event_name, timer_wait/1000000000 wait_ms
-> FROM events_stages_history_long AS stages
-> JOIN (SELECT event_id
-> FROM events_statements_history_long
-> ORDER BY event_id DESC limit 1) AS statements
-> ON stages.nesting_event_id = statements.event_id
-> ORDER BY stages.event_id;
+--------------------------------+---------+
| event_name | wait_ms |
+--------------------------------+---------+
| stage/sql/init | 0.2351 |
| stage/sql/checking permissions | 0.0133 |
| stage/sql/Opening tables | 0.0513 |
| stage/sql/init | 0.0780 |
| stage/sql/System lock | 0.0267 |
| stage/sql/optimizing | 0.0421 |
| stage/sql/statistics | 0.4106 |
| stage/sql/preparing | 0.0924 |
| stage/sql/executing | 0.0041 |
| stage/sql/Sending data | 0.2351 |
| stage/sql/end | 0.0072 |
| stage/sql/query end | 0.0144 |
| stage/sql/closing tables | 0.0236 |
| stage/sql/freeing items | 0.2679 |
| stage/sql/cleaning up | 0.0103 |
+--------------------------------+---------+
15 rows in set (0.01 sec)
Same 15 stages with clear match in the names for all, but "starting".
I can assume it's the one that matches first "stage/sql/init" in the query, but anyway, why "two stage/sql/init" in the output above and what "starting" stage from SHOW PROFILE corresponds to in P_S?
How to repeat:
In the system, with only one session working, after clean MySQL restart load tgb2.sql from bug #71199 to test database, enable everything as usual:
UPDATE performance_schema.setup_consumers SET ENABLED = 'Yes';
UPDATE performance_schema.setup_instruments SET ENABLED = 'Yes', TIMED = 'Yes';
then open new session and run the following queries:
use performance_schema
set profiling=1;
select sql_no_cache id1, max(id2) from test.tgb where id1=6783 and id2<10000 group by id1;
show profile for query 1;
set profiling=1;
select sql_no_cache id1, max(id2) from test.tgb where id1=6783 and id2<10000 group by id1;
SELECT event_name, timer_wait/1000000000 wait_ms
FROM events_stages_history_long AS stages
JOIN (SELECT event_id
FROM events_statements_history_long
ORDER BY event_id DESC limit 1) AS statements
ON stages.nesting_event_id = statements.event_id
ORDER BY stages.event_id;
Compare stages reported (and time spent on each stage, if you care).
If my test above is wrong, suggest proper way to use P_S to get the same results as with SHOW PROFILES + SHOW PROFILE FOR QUERY # easily.
Suggested fix:
As you are planning to replace SHOW PROFILE, make sure that new solution is compatible to the previous or clearly document all the differences and changes.
Description: I am playing with PERFORMANCE_SCHEMA as a replacement for SHOW PROFILE (that is deprecated and may disappear in MySQL 5.7+). In the process I've noted one strange difference: C:\Program Files\MySQL\MySQL Server 5.6\bin>mysql -uroot -proot -P3314 Warning: Using a password on the command line interface can be insecure. Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 2 Server version: 5.6.14-log 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> use performance_schema Database changed mysql> set profiling=1; Query OK, 0 rows affected, 1 warning (0.00 sec) mysql> select sql_no_cache id1, max(id2) from test.tgb where id1=6783 and id2<10 000 group by id1; +------+----------+ | id1 | max(id2) | +------+----------+ | 6783 | 9971 | +------+----------+ 1 row in set (0.06 sec) mysql> show profile for query 1; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000488 | | checking permissions | 0.000141 | | Opening tables | 0.031805 | | init | 0.000154 | | System lock | 0.000035 | | optimizing | 0.000071 | | statistics | 0.029156 | | preparing | 0.000148 | | executing | 0.000011 | | Sending data | 0.000215 | | end | 0.000018 | | query end | 0.000022 | | closing tables | 0.000035 | | freeing items | 0.000300 | | cleaning up | 0.000066 | +----------------------+----------+ 15 rows in set, 1 warning (0.00 sec) Now, same query again, but "profile" is taken from P_S: mysql> set profiling=0; Query OK, 0 rows affected, 1 warning (0.00 sec) mysql> select sql_no_cache id1, max(id2) from test.tgb where id1=6783 and id2<10 000 group by id1; +------+----------+ | id1 | max(id2) | +------+----------+ | 6783 | 9971 | +------+----------+ 1 row in set (0.00 sec) mysql> SELECT event_name, timer_wait/1000000000 wait_ms -> FROM events_stages_history_long AS stages -> JOIN (SELECT event_id -> FROM events_statements_history_long -> ORDER BY event_id DESC limit 1) AS statements -> ON stages.nesting_event_id = statements.event_id -> ORDER BY stages.event_id; +--------------------------------+---------+ | event_name | wait_ms | +--------------------------------+---------+ | stage/sql/init | 0.2351 | | stage/sql/checking permissions | 0.0133 | | stage/sql/Opening tables | 0.0513 | | stage/sql/init | 0.0780 | | stage/sql/System lock | 0.0267 | | stage/sql/optimizing | 0.0421 | | stage/sql/statistics | 0.4106 | | stage/sql/preparing | 0.0924 | | stage/sql/executing | 0.0041 | | stage/sql/Sending data | 0.2351 | | stage/sql/end | 0.0072 | | stage/sql/query end | 0.0144 | | stage/sql/closing tables | 0.0236 | | stage/sql/freeing items | 0.2679 | | stage/sql/cleaning up | 0.0103 | +--------------------------------+---------+ 15 rows in set (0.01 sec) Same 15 stages with clear match in the names for all, but "starting". I can assume it's the one that matches first "stage/sql/init" in the query, but anyway, why "two stage/sql/init" in the output above and what "starting" stage from SHOW PROFILE corresponds to in P_S? How to repeat: In the system, with only one session working, after clean MySQL restart load tgb2.sql from bug #71199 to test database, enable everything as usual: UPDATE performance_schema.setup_consumers SET ENABLED = 'Yes'; UPDATE performance_schema.setup_instruments SET ENABLED = 'Yes', TIMED = 'Yes'; then open new session and run the following queries: use performance_schema set profiling=1; select sql_no_cache id1, max(id2) from test.tgb where id1=6783 and id2<10000 group by id1; show profile for query 1; set profiling=1; select sql_no_cache id1, max(id2) from test.tgb where id1=6783 and id2<10000 group by id1; SELECT event_name, timer_wait/1000000000 wait_ms FROM events_stages_history_long AS stages JOIN (SELECT event_id FROM events_statements_history_long ORDER BY event_id DESC limit 1) AS statements ON stages.nesting_event_id = statements.event_id ORDER BY stages.event_id; Compare stages reported (and time spent on each stage, if you care). If my test above is wrong, suggest proper way to use P_S to get the same results as with SHOW PROFILES + SHOW PROFILE FOR QUERY # easily. Suggested fix: As you are planning to replace SHOW PROFILE, make sure that new solution is compatible to the previous or clearly document all the differences and changes.