Bug #76429 Performance schema instrument 'stage/sql/copy to tmp table' is not working
Submitted: 22 Mar 2015 18:38 Modified: 30 Apr 2015 13:29
Reporter: Marco Tusa Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S2 (Serious)
Version:5.7.6-m16-log MySQL Community Server (GP OS:Any
Assigned to: Marc Alff CPU Architecture:Any
Tags: instruments, perfromance_schema, temporary tables

[22 Mar 2015 18:38] Marco Tusa
Description:
During an alter table from Innodb to myisam the instrument is not reporting the information at all.

How to repeat:
(root@localhost) [performance_schema]>\s
--------------
/opt/mysql_templates/mysql-57M16/bin/mysql  Ver 14.14 Distrib 5.7.6-m16, for linux-glibc2.5 (x86_64) using  EditLine wrapper

Connection id:		7
Current database:	performance_schema
Current user:		root@localhost
SSL:			Not in use
Current pager:		stdout
Using outfile:		''
Using delimiter:	;
Server version:		5.7.6-m16-log MySQL Community Server (GPL)
Protocol version:	10
Connection:		Localhost via UNIX socket
Server characterset:	latin1
Db     characterset:	utf8
Client characterset:	utf8
Conn.  characterset:	utf8
UNIX socket:		/opt/mysql_instances/server57/mysql.sock
Uptime:			4 hours 1 min 18 sec

Threads: 8  Questions: 473911  Slow queries: 0  Opens: 147  Flush tables: 1  Open tables: 124  Queries per second avg: 32.733

(root@localhost) [test]>alter table test.tbtest_child1 engine=myisam;
(root@localhost) [performance_schema]>show processlist;
+----+-----------------+------------------+--------------------+-------------+-------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
| Id | User            | Host             | db                 | Command     | Time  | State                                                         | Info                                                                                                 |
+----+-----------------+------------------+--------------------+-------------+-------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
|  1 | event_scheduler | localhost        | NULL               | Daemon      | 14023 | Waiting on empty queue                                        | NULL                                                                                                 |
|  5 | replication     | 10.0.0.13:45544  | NULL               | Binlog Dump | 13971 | Master has sent all binlog to slave; waiting for more updates | NULL                                                                                                 |
|  6 | replication     | 10.0.0.12:36452  | NULL               | Binlog Dump | 13971 | Master has sent all binlog to slave; waiting for more updates | NULL                                                                                                 |
|  7 | root            | localhost        | performance_schema | Query       |     0 | starting                                                      | show processlist                                                                                     |
| 88 | stress          | 10.0.0.151:53653 | test               | Sleep       |     1 |                                                               | NULL                                                                                                 |
| 90 | stress          | 10.0.0.151:53655 | test               | Query       |     4 | update                                                        | insert INTO tbtest5 (uuid,date,a,b,c,counter,partitionid,strrecordtype) VALUES(UUID(),'2015-03-29',1 |
| 92 | stress          | 10.0.0.151:53657 | test               | Query       |     1 | updating                                                      | DELETE FROM tbtest4 where a between  227342 and 228342                                               |
| 96 | root            | localhost        | test               | Query       |    13 | copy to tmp table                                             | alter table test.tbtest_child1 engine=myisam                                                         |
+----+-----------------+------------------+--------------------+-------------+-------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+

(root@localhost) [performance_schema]>select ISPL.HOST,ISPL.DB,ISPL.User,ISPL.ID,ESH.*, SUBSTR(ISPL.Info,1,20) SQLT from information_schema.processlist ISPL JOIN threads TH on ISPL.ID=TH.PROCESSLIST_ID JOIN events_stages_current ESH ON TH.THREAD_ID=ESH.THREAD_ID  Where  ISPL.User='root'  order by TIMER_START DESC;
+-----------+--------------------+------+----+-----------+----------+--------------+------------------------+---------------------+-------------------+-----------+------------+----------------+----------------+------------------+--------------------+----------------------+
| HOST      | DB                 | User | ID | THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME             | SOURCE              | TIMER_START       | TIMER_END | TIMER_WAIT | WORK_COMPLETED | WORK_ESTIMATED | NESTING_EVENT_ID | NESTING_EVENT_TYPE | SQLT                 |
+-----------+--------------------+------+----+-----------+----------+--------------+------------------------+---------------------+-------------------+-----------+------------+----------------+----------------+------------------+--------------------+----------------------+
| localhost | performance_schema | root |  7 |        38 |   398561 |         NULL | stage/sql/Sending data | sql_executor.cc:193 | 14130036996678000 |      NULL |       NULL |           NULL |           NULL |           398547 | STATEMENT          | select ISPL.HOST,ISP |
+-----------+--------------------+------+----+-----------+----------+--------------+------------------------+---------------------+-------------------+-----------+------------+----------------+----------------+------------------+--------------------+----------------------+
1 row in set (0.00 sec)

(root@localhost) [performance_schema]>select ISPL.HOST,ISPL.DB,ISPL.User,ISPL.ID,ESH.*, SUBSTR(ISPL.Info,1,20) SQLT from information_schema.processlist ISPL JOIN threads TH on ISPL.ID=TH.PROCESSLIST_ID JOIN events_stages_history ESH ON TH.THREAD_ID=ESH.THREAD_ID  Where  ISPL.User='root' and info is not null AND id=96  order by TIMER_START DESC;
Empty set (0.00 sec)
(root@localhost) [performance_schema]>select * from setup_instruments where name like '%tmp%' and ENABLED='YES';

+------------------------------------------------+---------+-------+
| NAME                                           | ENABLED | TIMED |
+------------------------------------------------+---------+-------+
| stage/sql/Copying to tmp table                 | YES     | YES   | <-------- all active
| stage/sql/copy to tmp table                    | YES     | YES   | <-------- all active
| stage/sql/Creating tmp table                   | YES     | YES   | <-------- all active
| stage/sql/removing tmp table                   | YES     | YES   | <-------- all active
+------------------------------------------------+---------+-------+

(root@localhost) [performance_schema]>select * from setup_consumers;
+----------------------------------+---------+
| NAME                             | ENABLED |
+----------------------------------+---------+
| events_stages_current            | YES     | <-------- all active
| events_stages_history            | YES     | <-------- all active
| events_stages_history_long       | YES     | <-------- all active
| events_statements_current        | YES     |
| events_statements_history        | YES     |
| events_statements_history_long   | YES     |
| events_transactions_current      | YES     |
| events_transactions_history      | NO      |
| events_transactions_history_long | NO      |
| events_waits_current             | NO      |
| events_waits_history             | NO      |
| events_waits_history_long        | NO      |
| global_instrumentation           | YES     |
| thread_instrumentation           | YES     |
| statements_digest                | YES     |
+----------------------------------+---------+

How to replicate
1) Enable the instruments for tmp table
2) run an alter like alter table test.tbtest_child1 engine=myisam;
3) Check information in current and history table
[31 Mar 2015 13:29] Marc Alff
The data posted is incomplete, as nothing is said about THREAD_ID 96,
and whether it is instrumented or not.

Considering that this report was entered right at the same moment than bug#76428, which disabled root@localhost for any new sessions (so there is a chance session 96 would not be instrumented), this can actually be the expected result : threads not instrumented produce no data.

Please make sure the running thread is instrumented to collect data,
and inspect the content performance_schema tables directly (no joins).

Note:

When the ALTER is still running, the stage progress will be visible in events_stages_current.

*After* the stage is complete, will historical stages be visible in events_stages_history (up to 10 records), or events_stages_history_long.

Inspecting events_stages_history while the ALTER table is still running will not display any stage information about 'stage/sql/copy to tmp table', as expected, because this stage is not completed yet.
[1 May 2015 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".