Description:
While working on a test case for bug #71201 I've noted that even in the cleanest test I was able to find, time reported for some stages is different in a way that is hard to explain. Look:
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 5
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> show profiles;
Empty set, 1 warning (0.00 sec)
mysql> use performance_schema;
Database changed
mysql> truncate table events_stages_history_long;
Query OK, 0 rows affected (0.00 sec)
mysql> truncate table events_statements_history_long;
Query OK, 0 rows affected (0.00 sec)
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.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.2833 |
| stage/sql/checking permissions | 0.0647 |
| stage/sql/Opening tables | 0.1519 |
| stage/sql/init | 0.1468 |
| stage/sql/System lock | 0.0554 |
| stage/sql/optimizing | 0.0842 |
| stage/sql/statistics | 0.2833 |
| stage/sql/preparing | 0.0616 |
| stage/sql/executing | 0.0062 |
| stage/sql/Sending data | 0.1642 |
| stage/sql/end | 0.0123 |
| stage/sql/query end | 0.0708 |
| stage/sql/closing tables | 0.0349 |
| stage/sql/freeing items | 0.2874 |
| stage/sql/cleaning up | 0.0051 |
+--------------------------------+---------+
15 rows in set (0.01 sec)
mysql> show profiles;
+----------+------------+-------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
-------+
| Query_ID | Duration | Query
|
+----------+------------+-------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
-------+
| 1 | 0.00170525 | select sql_no_cache id1, max(id2) from test.tgb where
id1=6783 and id2<10000 group by id1
|
| 2 | 0.00572600 | 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 |
+----------+------------+-------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
-------+
2 rows in set, 1 warning (0.00 sec)
mysql> show profile for query 1;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000225 |
| checking permissions | 0.000071 |
| Opening tables | 0.000151 |
| init | 0.000148 |
| System lock | 0.000058 |
| optimizing | 0.000083 |
| statistics | 0.000280 |
| preparing | 0.000065 |
| executing | 0.000008 |
| Sending data | 0.000160 |
| end | 0.000016 |
| query end | 0.000066 |
| closing tables | 0.000038 |
| freeing items | 0.000286 |
| cleaning up | 0.000051 |
+----------------------+----------+
15 rows in set, 1 warning (0.00 sec)
Check "preparing" stage, for example. It's 0.065 milliseconds in SHOW PROFILE, but 0.0616 milliseconds in P_S query output. For other stages, like "Opening tables", the difference is minor (0.151 vs 0.1519).
Questions are: what is the reason for this difference that is visible only for some stages of statement execution and what statements returns more precise/correct value (I assume 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;
truncate table events_stages_history_long;
truncate table events_statements_history_long;
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;
show profile for query 1;
Then compare the outputs for the corresponding stages.
Suggested fix:
Implement SHOW PROFILES via P_S queries internally?
Having different profiling methods resulting is somewhat different outputs is not any good, but simply deprecating SHOW PROFILE without providing alternative that is equally easy to use is also not a good way to "fix" the problem IMHO.
