Bug #84450 incorrect info logged in slow_log for event_scheduer
Submitted: 10 Jan 2017 1:46 Modified: 10 Jan 2017 6:41
Reporter: Fungo Wang Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.6.35,5.7.17 OS:Any
Assigned to: CPU Architecture:Any
Tags: event_scheduler, slow_log

[10 Jan 2017 1:46] Fungo Wang
Description:
The query_time, lock_time, rows_sent and rows_examined info in slow_log is wrong for queries executed by event_scheduler.

How to repeat:
// testcase as below:

set global event_scheduler=on;
set global long_query_time=1;
set global log_output='table';

create table t1(id int, primary key(id)) engine=innodb;
insert into t1 values(1),(2);

delimiter //;
create event event1 on schedule every 10 second starts now() ends date_add(now(), interval 5 hour)
do begin
select sleep(2);
select * from t1;
select sleep(3);
end //
delimiter ;//

sleep 30;
select * from mysql.slow_log;

// result as below
start_time      user_host       query_time      lock_time       rows_sent       rows_examined   db      last_insert_id  insert_id       server_id       sql_text        thread_id
2017-01-10 04:40:54.167361      root[root] @ localhost [localhost]      00:00:02.001532 00:00:00.000475 1       0       test    0       0       1       select sleep(2) 6
2017-01-10 04:40:54.169232      root[root] @ localhost [localhost]      00:00:02.003403 00:00:02.002787 3       2       test    0       0       1       select * from t1        6
2017-01-10 04:40:57.169721      root[root] @ localhost [localhost]      00:00:05.003892 00:00:02.002787 4       2       test    0       0       1       select sleep(3) 6
2017-01-10 04:41:04.168250      root[root] @ localhost [localhost]      00:00:02.001680 00:00:00.000482 1       0       test    0       0       1       select sleep(2) 7
2017-01-10 04:41:04.169868      root[root] @ localhost [localhost]      00:00:02.003298 00:00:02.002719 3       2       test    0       0       1       select * from t1        7
2017-01-10 04:41:07.170370      root[root] @ localhost [localhost]      00:00:05.003800 00:00:02.002719 4       2       test    0       0       1       select sleep(3) 7
2017-01-10 04:41:14.168945      root[root] @ localhost [localhost]      00:00:02.001689 00:00:00.000519 1       0       test    0       0       1       select sleep(2) 9
2017-01-10 04:41:14.170520      root[root] @ localhost [localhost]      00:00:02.003264 00:00:02.002676 3       2       test    0       0       1       select * from t1        9
2017-01-10 04:41:17.171021      root[root] @ localhost [localhost]      00:00:05.003765 00:00:02.002676 4       2       test    0       0       1       select sleep(3) 9

These infos are incorrect
1. "select * from t1" should not be logged in slow log
2. query_time, lock time,  rows_sent and rows_examined of "select * from t1" and "select sleep(3)" are all wrong
[10 Jan 2017 6:41] Umesh Shastry
Hello Fungo Wang,

Thank you for the report and test case.
Verified as described.

Thanks,
Umesh