Details
Description
Found on stackoverflow:
http://stackoverflow.com/questions/41099516/huge-time-in-slow-query-log-mariadb
Slow queries are not written to the slow log when they are executed via events.
Queries not using indexes are written to the slow log (if the corresponding option is set), but the timestamp and query execution time are corrupt.
Test case |
set @event_scheduler.save= @@global.event_scheduler; |
set @log_queries_not_using_indexes.save= @@global.log_queries_not_using_indexes; |
set @slow_query_log.save= @@global.slow_query_log; |
|
set global event_scheduler= on; |
set global slow_query_log= on; |
set global log_queries_not_using_indexes= on; |
--let $slowlog = `SELECT @@slow_query_log_file`
|
|
create table t1 (i int); |
insert into t1 values (0),(0); |
create event ev on schedule at CURRENT_TIMESTAMP + INTERVAL 1 second do update t1 set i=1; |
sleep 2;
|
--echo #
|
--echo # Queries not using indexes are logged, but time is off:
|
--echo #
|
--cat_file $slowlog
|
--echo
|
|
set global log_queries_not_using_indexes= off; |
set global long_query_time=0.2; |
set global event_scheduler=off; |
set global event_scheduler=on; |
|
--echo
|
--echo #
|
--echo # Slow queries are not logged at all:
|
--echo #
|
create event ev on schedule at CURRENT_TIMESTAMP + INTERVAL 1 second do update t1 set i=sleep(0.5); |
sleep 2;
|
--cat_file $slowlog
|
--echo
|
|
drop table t1; |
|
set global event_scheduler= @event_scheduler.save; |
set global log_queries_not_using_indexes= @log_queries_not_using_indexes.save; |
set global slow_query_log= @slow_query_log.save; |
set global long_query_time= @@session.long_query_time; |
Log contents:
/data/src/5.5-bug/sql/mysqld, Version: 5.5.54-MariaDB-debug (Source distribution). started with:
|
Tcp port: 16000 Unix socket: /data/src/5.5-bug/mysql-test/var/tmp/mysqld.1.sock
|
Time Id Command Argument
|
# Time: 571004 12:33:04
|
# User@Host: root[root] @ localhost [localhost]
|
# Thread_id: 4 Schema: test QC_hit: No
|
# Query_time: 11936127050132.482422 Lock_time: 0.002233 Rows_sent: 0 Rows_examined: 2
|
use test;
|
SET timestamp=11937608616784;
|
update t1 set i=1;
|
Only the first query was written, and Query_time and timestamp show huge values.
Not reproducible on MySQL 5.5-5.7 – either it's been fixed there, or the problem was introduced in MariaDB.