MySQL Bugs: #27060: SQL Profile utility may not be reporting right duration for each step

Bug #27060	SQL Profile utility may not be reporting right duration for each step
Submitted:	12 Mar 2007 21:27	Modified:	6 Jul 2007 3:13
Reporter:	Robin Schumacher	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S3 (Non-critical)
Version:	5.0.37	OS:	Linux (Fedora core 4)
Assigned to:	Chad MILLER	CPU Architecture:	Any

Description:
Times for new profile utility may not show correct duration (and possibly other stats like CPU) for each step.  May actually report the time for the step before.  

How to repeat:
> mysql> set profiling=1;
> Query OK, 0 rows affected (0.00 sec)
>
> mysql> alter table bigtab engine=innodb;
> Query OK, 560250 rows affected (8.94 sec)
> Records: 560250  Duplicates: 0  Warnings: 0
>
> mysql> show profiles;
> +----------+------------+----------------------------------+
> | Query_ID | Duration   | Query                            |
> +----------+------------+----------------------------------+
> |        0 | 0.00008300 | set profiling=1                  |
> |        1 | 8.93046200 | alter table bigtab engine=innodb |
> +----------+------------+----------------------------------+
> 2 rows in set (0.00 sec)
>
> mysql> show profile cpu for query 1;
> +----------------------+------------+------------+------------+
> | Status               | Duration   | CPU_user   | CPU_system |
> +----------------------+------------+------------+------------+
> | checking permissions | 0.00003200 | 0.00000000 | 0.00000000 |
> | init                 | 0.00000800 | 0.00000000 | 0.00000000 |
> | Opening table        | 0.00004900 | 0.00000000 | 0.00000000 |
> | System lock          | 0.00000900 | 0.00000000 | 0.00000000 |
> | Table lock           | 0.00000600 | 0.00000000 | 0.00000000 |
> | setup                | 0.00000700 | 0.00000000 | 0.00000000 |
> | creating table       | 0.00004200 | 0.00000000 | 0.00000000 |
> | After create         | 0.03445100 | 0.00100000 | 0.00000000 |
> | copy to tmp table    | 0.00010000 | 0.00000000 | 0.00000000 |
> | rename result table  | 8.84259000 | 7.03793000 | 0.30595400 |
> | end                  | 0.05308700 | 0.00000000 | 0.02099700 |
> | query end            | 0.00005900 | 0.00000000 | 0.00000000 |
> | freeing items        | 0.00000700 | 0.00000000 | 0.00000000 |
> | cleaning up          | 0.00001500 | 0.00000000 | 0.00000000 |
> +----------------------+------------+------------+------------+
> 14 rows in set (0.00 sec)

Would the copy to the tmp table take the actual 8.8 seconds instead of the table rename?

Verified as described on Mac OS X and Linux.

A quick way of verifying this bug.

set profiling=1; 
drop table if exists t1;
create table t1 (i int, c longtext) engine=csv;
insert into t1 values (1, repeat('x', 1024*1024*15));
insert into t1 select * from t1;
insert into t1 select * from t1;
alter table t1 engine=myisam;
show profile; 
+----------------------+------------+
| Status               | Duration   |
+----------------------+------------+
| checking permissions | 0.00004000 |
| init                 | 0.00001200 | 
| Opening table        | 0.00007500 |
| System lock          | 0.00001300 |  
| Table lock           | 0.00000700 |
| setup                | 0.00000900 | 
| creating table       | 0.00002400 |
| After create         | 0.01282300 | 
| copy to tmp table    | 0.00024300 | 
| rename result table  | 2.32689700 | 
| end                  | 0.02777000 | 
| query end            | 0.00008500 | 
| freeing items        | 0.00001000 | 
| cleaning up          | 0.00001900 | 
+----------------------+------------+

Did more testing with two queries with the profiler.

The first query used two subqueries/inline views whereas the second one uses just one.  Seems like the profiler reports accurate times and counts in this case - would you agree?  See below.  Only other thing I've noticed is I never get any block IO counts.  

mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql> select  b.client_id,
    ->         b.client_first_name,
    ->         b.client_last_name,
    ->        (select sum(number_of_units * price)
    ->  from client_transaction c where c.action = 'buy' and
    ->  c.client_id = b.client_id) -
    ->         case
    ->          (select sum(number_of_units * price)
    ->          from client_transaction d
    ->          where d.action = 'sell' and d.client_id = b.client_id)
    ->  when NULL then 0
    ->  else
    ->          (select sum(number_of_units * price)
    ->          from client_transaction d
    ->          where d.action = 'sell' and d.client_id = b.client_id)
    ->  end
    ->  portfolio_value
    -> from    client_transaction a,
    ->         client b
    -> where   a.client_id = b.client_id
    -> group by b.client_id,
    ->         b.client_first_name,
    ->         b.client_last_name
    -> having portfolio_value > 1000000;
+-----------+-------------------+------------------+-----------------+
| client_id | client_first_name | client_last_name | portfolio_value |
+-----------+-------------------+------------------+-----------------+
|         5 | ABNER             | ROSSELLETT       |      1252115.50 |
|       500 | CANDICE           | BARTLETT         |      1384877.50 |
+-----------+-------------------+------------------+-----------------+
2 rows in set (6.36 sec)

mysql> select state,count(*) numb_ops,
    -> round(sum(duration),5) sum_dur, round(avg(duration),5) avg_dur,
    -> round(sum(cpu_user),5) sum_cpu, round(avg(cpu_user),5) avg_cpu
    -> from information_schema.profiling
    -> where query_id = 1
    -> group by state
    -> order by state;
+----------------------+----------+---------+---------+---------+---------+
| state                | numb_ops | sum_dur | avg_dur | sum_cpu | avg_cpu |
+----------------------+----------+---------+---------+---------+---------+
| cleaning up          |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
| closing tables       |        1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| Copying to tmp table |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| Creating tmp table   |        1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| end                  |        2 | 0.00019 | 0.00009 | 0.00000 | 0.00000 |
| executing            |    56026 | 6.11108 | 0.00011 | 5.97510 | 0.00011 |
| freeing items        |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
| init                 |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| logging slow query   |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| Opening tables       |        1 | 0.00015 | 0.00015 | 0.00000 | 0.00000 |
| optimizing           |        4 | 0.00021 | 0.00005 | 0.00000 | 0.00000 |
| preparing            |        4 | 0.00007 | 0.00002 | 0.00000 | 0.00000 |
| query end            |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| removing tmp table   |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
| Sending data         |    56026 | 0.24661 | 0.00000 | 0.09698 | 0.00000 |
| Sorting result       |        1 | 0.00116 | 0.00116 | 0.00100 | 0.00100 |
| statistics           |        4 | 0.00005 | 0.00001 | 0.00000 | 0.00000 |
| System lock          |        1 | 0.00003 | 0.00003 | 0.00000 | 0.00000 |
| Table lock           |        1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
+----------------------+----------+---------+---------+---------+---------+
19 rows in set (1.25 sec)

mysql> select  b.client_id,
    ->         b.client_first_name,
    ->         b.client_last_name,
    ->         sum(number_of_units * price)  -
    ->         case
    ->          (select sum(number_of_units * price)
    ->          from client_transaction d
    ->          where d.action = 'sell' and d.client_id = b.client_id)
    ->  when NULL then 0
    ->  else    (select sum(number_of_units * price)
    ->          from client_transaction d
    ->          where d.action = 'sell' and d.client_id = b.client_id)
    ->  end
    ->  portfolio_value
    -> from    client_transaction a,
    ->         client b
    -> where   a.client_id = b.client_id and
    ->  action = 'buy'
    -> group by b.client_id,
    ->         b.client_first_name,
    ->         b.client_last_name
    -> having portfolio_value > 1000000;
+-----------+-------------------+------------------+-----------------+
| client_id | client_first_name | client_last_name | portfolio_value |
+-----------+-------------------+------------------+-----------------+
|         5 | ABNER             | ROSSELLETT       |      1252115.50 |
|       500 | CANDICE           | BARTLETT         |      1384877.50 |
+-----------+-------------------+------------------+-----------------+
2 rows in set (0.48 sec)

mysql> select state,count(*) numb_ops,
    -> round(sum(duration),5) sum_dur, round(avg(duration),5) avg_dur,
    -> round(sum(cpu_user),5) sum_cpu, round(avg(cpu_user),5) avg_cpu
    -> from information_schema.profiling
    -> where query_id = 3
    -> group by state
    -> order by state;
+----------------------+----------+---------+---------+---------+---------+
| state                | numb_ops | sum_dur | avg_dur | sum_cpu | avg_cpu |
+----------------------+----------+---------+---------+---------+---------+
| cleaning up          |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
| closing tables       |        1 | 0.00003 | 0.00003 | 0.00000 | 0.00000 |
| Copying to tmp table |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
| Creating tmp table   |        1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| end                  |        2 | 0.00291 | 0.00146 | 0.00300 | 0.00150 |
| executing            |    11193 | 0.42349 | 0.00004 | 0.37494 | 0.00003 |
| freeing items        |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
| init                 |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| logging slow query   |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| Opening tables       |        1 | 0.00015 | 0.00015 | 0.00000 | 0.00000 |
| optimizing           |        3 | 0.00020 | 0.00006 | 0.00000 | 0.00000 |
| preparing            |        3 | 0.00006 | 0.00002 | 0.00000 | 0.00000 |
| query end            |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| removing tmp table   |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| Sending data         |    11193 | 0.05427 | 0.00000 | 0.02600 | 0.00000 |
| Sorting result       |        1 | 0.00369 | 0.00369 | 0.00400 | 0.00400 |
| statistics           |        3 | 0.00004 | 0.00001 | 0.00000 | 0.00000 |
| System lock          |        1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| Table lock           |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
+----------------------+----------+---------+---------+---------+---------+
19 rows in set (1.11 sec)

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/21961

ChangeSet@1.2421, 2007-03-14 20:20:42-04:00, cmiller@zippy.cornsilk.net +1 -0
  Bug#27060: SQL Profile utility may not be reporting right duration \
  	for each step
  
  Whenever the profiler is reset at the beginning of a query, there's
  a "hidden" profiling entry that represents that point in time.  It 
  has no status description, as those are set by state changes and no
  such point has yet been encountered.  That profiling entry is not
  in the list of entries generated when we change states.
  
  The profiling code had the problem that each step of printing 
  profiling data subtracted the previous "step"'s data, but gave the
  label to that data of the current step, which is wrong.  The label/
  state refers to the period beginning with that profiling data, not
  ending with it.
  
  Now, give a label to the first profiling pseudo-entry, so that we 
  have a name to assign to the period that ends with the first state 
  change.  Now also use the state name of the previous step in showing 
  the delta values that end with this step.

Applied to community tree ONLY, v5.0.45.

Noted in 5.0.45 changelog.

Times displayed by SHOW PROFILE were incorrectly associated with the
profile entry one later than the corrrect one.