MySQL Bugs: #52487: SHOW PROFILE duration time seems incorrect

Bug #52487	SHOW PROFILE duration time seems incorrect
Submitted:	30 Mar 2010 21:30	Modified:	31 Mar 2010 6:12
Reporter:	Peiran Song	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Information schema	Severity:	S3 (Non-critical)
Version:	5.1.42, 5.1. bzr	OS:	Any (OpenSolaris, Linux)
Assigned to:		CPU Architecture:	Any

Description:
I executed an alter table statement which ran for over 1 hour, the SHOW PROFILES reported the total duration correctly, but the breakdowns listed by SHOW PROFILE doesn't add up to the total number:

mysql> show profiles;
+----------+---------------+-------------------------------+
| Query_ID | Duration  |  Query                            |
+----------+---------------+-------------------------------+

|        5 | 4770.01299950 | alter table ...               | 
+----------+---------------+-------------------------------+

mysql> show profile for query 5;
+----------------------+------------+
| Status               | Duration   |
+----------------------+------------+
| starting             |   0.000063 | 
| checking permissions |   0.000006 | 
| checking permissions |   0.000009 | 
| init                 |   1.511332 | 
| Opening tables       |   0.000028 | 
| System lock          |   0.000007 | 
| Table lock           |   0.000009 | 
| setup                |   0.000093 | 
| creating table       |   0.019480 | 
| After create         |   0.000094 | 
| copy to tmp table    | 999.999999 | 
| rename result table  |   3.026547 | 
| end                  |   0.000022 | 
| query end            |   0.000007 | 
| freeing items        |   0.000104 | 
| cleaning up          |   0.000006 | 
+----------------------+------------+

The 999.999999 is suspicious... 

How to repeat:
Profile a long running query which executes for over 1000 seconds. 

Suggested fix:
Report correct duration time for each phrase.

Thank you for the report.

Verified as described. Not only "copy to tmp table" affected:

mysql> select sleep(1100);
+-------------+
| sleep(1100) |
+-------------+
|           0 |
+-------------+
1 row in set (18 min 20.00 sec)

mysql> show profiles;
+----------+---------------+--------------------+
| Query_ID | Duration      | Query              |
+----------+---------------+--------------------+
|        1 |   10.11582100 | select sleep(10)   |
|        2 | 1100.00622500 | select sleep(1100) |
+----------+---------------+--------------------+
2 rows in set (0.00 sec)

mysql> show profile for query 2;
+----------------------+------------+
| Status               | Duration   |
+----------------------+------------+
| starting             |   0.000953 |
| checking permissions |   0.000497 |
| Opening tables       |   0.000473 |
| init                 |   0.000333 |
| optimizing           |   0.000314 |
| executing            |   0.000328 |
| User sleep           | 999.999999 |
| end                  |   0.000695 |
| query end            |   0.000308 |
| freeing items        |   0.001013 |
| logging slow query   |   0.000572 |
| logging slow query   |   0.000342 |
| cleaning up          |   0.000338 |
+----------------------+------------+
13 rows in set (0.02 sec)

Also see: http://bugs.mysql.com/bug.php?id=52492