Bug #22011 Timing feedback of statements in stored procedure is incorrect

• Submitted: 5 Sep 2006 10:15
• Modified: 5 Dec 2007 18:55
• Reporter: Andre Timmer
• Status: Verified
• Category: MySQL Server: Command-line Clients
• Severity: S3 (Non-critical)
• Version: 5.0.25-BK, 5.0.18
• OS: Linux (Linux)
• CPU Architecture: Any
• Tags: qc

[5 Sep 2006 10:15] Andre Timmer

Description:
Timing feedback of statements in stored procedure is incorrect.

How to repeat:
drop procedure if exists p_test;

delimiter //

create procedure p_test()
begin
   declare v_cnt integer default 0;
   
   l1: 
   loop
      set v_cnt = v_cnt+1;
         
      select 'test';
         
      if (v_cnt > 100) then
         leave l1;
      end if;
    end loop;
end;
//

delimiter ;

call p_test();

Suggested fix:
Fist select gives:
+------+
| test |
+------+
| test |
+------+
1 row in set (0.00 sec)

Last select gives:
+------+
| test |
+------+
| test |
+------+
1 row in set (0.08 sec)

'Stopwatch' is apparently pressed at start of procedure call.
Not at start of the select statement itself.

[5 Sep 2006 11:25] Valeriy Kravchuk

Thank you for a bug report. Verified just as described.

[26 Sep 2006 9:00] Konstantin Osipov

The timing is done in the command line client. The result is wrong for any multi-result-set statement, not just for a stored procedure. The offending code is in client/mysql.cc:com_go, start_timer, mysql_end_timer: the timer is started at start of the query but is not restarted in case of a multiple result set. 
Apparently, in order to handle multiple-result-set queries properly we need two timers: one to measure time to execute the whole query, and another for each result set. Having two timers, we can output the total execution time for a multiple-result-queries on a separate line.