Query_time is increasing for every query a stored procedure logs to the slow log
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona Server moved to https://jira.percona.com/projects/PS |
Fix Released
|
High
|
Alexey Kopytov | ||
5.1 |
Fix Released
|
High
|
Alexey Kopytov | ||
5.5 |
Fix Released
|
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_
# InnoDB_
SET timestamp=
CALL XXX();
mysql> show variables like '%slow%';
+------
| Variable_name | Value |
+------
| log_slow_filter | |
| log_slow_queries | OFF |
| log_slow_rate_limit | 1 |
| log_slow_
| log_slow_
| log_slow_
| log_slow_verbosity | microtime,
| slow_launch_time | 2 |
| slow_query_log | OFF |
| slow_query_log_file | /var/lib/
| slow_query_
| use_global_
+------
12 rows in set (0.00 sec)
mysql>
Related branches
- Alexey Kopytov (community): Approve
- Laurynas Biveinis (community): Needs Fixing
- Stewart Smith (community): Approve
- Sergei Glushchenko (community): Approve (g2)
-
Diff: 77 lines (+35/-0)2 files modifiedPercona-Server/sql/sp_head.cc (+20/-0)
Percona-Server/sql/sql_class.h (+15/-0)
- Alexey Kopytov (community): Approve
- Laurynas Biveinis (community): Needs Fixing
- Stewart Smith (community): Approve
- Sergei Glushchenko (community): Approve (g2)
-
Diff: 78 lines (+36/-0)2 files modifiedPercona-Server/sql/sp_head.cc (+20/-0)
Percona-Server/sql/sql_class.h (+16/-0)
Changed in percona-server: | |
status: | New → Confirmed |
Changed in percona-server: | |
importance: | Undecided → Medium |
status: | Confirmed → Triaged |
Changed in percona-server: | |
assignee: | nobody → Oleg Tsarev (tsarev) |
Changed in percona-server: | |
status: | Triaged → In Progress |
tags: | added: slow-extended |
Changed in percona-server: | |
assignee: | Oleg Tsarev (tsarev) → Valentine Gostev (longbow) |
status: | In Progress → Triaged |
Changed in percona-server: | |
assignee: | Valentine Gostev (longbow) → nobody |
Workaround:
f=slow.log
real_tq= `echo "scale= $scale; $t-$last_ time" | bc -l| sed 's/^\./0./'`
last_time= $t
qts=`grep "Query_time" $f | awk '{ print $3}'`
last_time=0.0
scale=6
for t in $qts
do
echo $real_tq
cat $f | sed "s/# Query_time: $t Lock_time:/# Query_time: $real_tq Lock_time:/" > tmp
mv tmp $f
done