Query_time is increasing for every query a stored procedure logs to the slow log

[Aleksandr Kuzminsky]

Percona-Server 12.5 on Centos 5, 64 bit.

When logging all queries a stored procedure executes, mysqld logs incrorrect Query_time:.

Query execution time is not reset and every next Query_time: is logged as accumulated value:

cat slow.log
...
# Query_time: 0.000530 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Query_time: 0.595670 Lock_time: 0.000621 Rows_sent: 0 Rows_examined: 233664 Rows_affected: 0 Rows_read: 0
...
# Query_time: 128.371195 Lock_time: 128.371085 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
...
# User@Host: [root] @ localhost []
# Thread_id: 1 Schema: xxx Last_errno: 0 Killed: 0
# Query_time: 128.371250 Lock_time: 128.371085 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 11 Tmp_tables: 9 Tmp_disk_tables: 0 Tmp_table_sizes: 1023104
# InnoDB_trx_id: 222F
# QC_Hit: No Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: No
# Filesort: Yes Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 30497
SET timestamp=1297780057;
CALL XXX();

mysql> show variables like '%slow%';
+---------------------------------------+--------------------------------+
| Variable_name | Value |
+---------------------------------------+--------------------------------+
| log_slow_filter | |
| log_slow_queries | OFF |
| log_slow_rate_limit | 1 |
| log_slow_slave_statements | OFF |
| log_slow_sp_statements | ON |
| log_slow_timestamp_every | OFF |
| log_slow_verbosity | microtime,query_plan,innodb |
| slow_launch_time | 2 |
| slow_query_log | OFF |
| slow_query_log_file | /var/lib/mysql/sm1u02-slow.log |
| slow_query_log_microseconds_timestamp | OFF |
| use_global_log_slow_control | none |
+---------------------------------------+--------------------------------+
12 rows in set (0.00 sec)

mysql>

[Aleksandr Kuzminsky (akuzminsky)]

Workaround:

f=slow.log
qts=`grep "Query_time" $f | awk '{ print $3}'`
last_time=0.0
scale=6
for t in $qts
do
        real_tq=`echo "scale=$scale;$t-$last_time" | bc -l| sed 's/^\./0./'`
        echo $real_tq
        cat $f | sed "s/# Query_time: $t Lock_time:/# Query_time: $real_tq Lock_time:/" > tmp
        mv tmp $f
        last_time=$t
done

[Aurimas Mikalauskas (aurimas-mikalauskas)]

Would be great to have this fixed, just wasted few hours with customer chasing ghosts.

[Stewart Smith (stewart)]

hrm... that to me indicates that we should raise priority of the bug.

[Oleg Tsarev (tsarev)]

Valentine,

Please add suitable test-case for this problem.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-468