Percona Server with XtraDB

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

Reported by Aleksandr Kuzminsky on 2011-02-15
16
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Percona Server
High
Alexey Kopytov
5.1
High
Alexey Kopytov
5.5
High
Alexey Kopytov

Bug Description

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>

Related branches

lp:~akopytov/percona-server/bug719386-5.1
Merged into lp:percona-server/5.1 at revision 502
Alexey Kopytov: Approve on 2012-10-26
Laurynas Biveinis: Needs Fixing on 2012-10-26
Stewart Smith (community): Approve on 2012-10-24
Sergei Glushchenko: Approve (g2) on 2012-10-23
lp:~akopytov/percona-server/bug719386-5.5
Merged into lp:percona-server/5.5 at revision 340
Alexey Kopytov: Approve on 2012-10-26
Laurynas Biveinis: Needs Fixing on 2012-10-26
Stewart Smith (community): Approve on 2012-10-24
Sergei Glushchenko: Approve (g2) on 2012-10-23

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

Stewart Smith (stewart) on 2011-05-19
Changed in percona-server:
status: New → Confirmed
Stewart Smith (stewart) on 2011-06-07
Changed in percona-server:
importance: Undecided → Medium
status: Confirmed → Triaged

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

Stewart Smith (stewart) wrote :

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

Changed in percona-server:
importance: Medium → Low
importance: Low → High
Oleg Tsarev (tsarev) on 2011-06-20
Changed in percona-server:
assignee: nobody → Oleg Tsarev (tsarev)
Oleg Tsarev (tsarev) on 2011-06-21
Changed in percona-server:
status: Triaged → In Progress
Oleg Tsarev (tsarev) on 2011-08-23
tags: added: slow-extended
Oleg Tsarev (tsarev) on 2012-01-03
Changed in percona-server:
assignee: Oleg Tsarev (tsarev) → Valentine Gostev (longbow)
status: In Progress → Triaged
Oleg Tsarev (tsarev) wrote :

Valentine,

Please add suitable test-case for this problem.

Stewart Smith (stewart) on 2012-05-17
Changed in percona-server:
assignee: Valentine Gostev (longbow) → nobody
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers