Skip to content

Commit e86580c

Browse files
committed
MDEV-11552 Queries executed by event scheduler are written to slow log incorrectly or not written at all
because thd->update_server_status() is used to measure the query time for the slow log (not only to set protocol level flags), it needs to be called also when the server isn't going to send anything to the client.
1 parent 211cf93 commit e86580c

File tree

3 files changed

+45
-5
lines changed

3 files changed

+45
-5
lines changed

mysql-test/r/events_slowlog.result

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,12 @@
1+
set @event_scheduler_save= @@global.event_scheduler;
2+
set @slow_query_log_save= @@global.slow_query_log;
3+
set global event_scheduler= on;
4+
set global slow_query_log= on;
5+
set global long_query_time=0.2;
6+
create table t1 (i int);
7+
insert into t1 values (0);
8+
create event ev on schedule at CURRENT_TIMESTAMP + INTERVAL 1 second do update t1 set i=1+sleep(0.5);
9+
drop table t1;
10+
set global event_scheduler= @event_scheduler_save;
11+
set global slow_query_log= @slow_query_log_save;
12+
set global long_query_time= @@session.long_query_time;

mysql-test/t/events_slowlog.test

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,28 @@
1+
--source include/not_embedded.inc
2+
#
3+
# MDEV-11552 Queries executed by event scheduler are written to slow log incorrectly or not written at all
4+
#
5+
set @event_scheduler_save= @@global.event_scheduler;
6+
set @slow_query_log_save= @@global.slow_query_log;
7+
8+
set global event_scheduler= on;
9+
set global slow_query_log= on;
10+
set global long_query_time=0.2;
11+
12+
create table t1 (i int);
13+
insert into t1 values (0);
14+
create event ev on schedule at CURRENT_TIMESTAMP + INTERVAL 1 second do update t1 set i=1+sleep(0.5);
15+
16+
--let wait_condition= select i from t1 where i > 0
17+
--source include/wait_condition.inc
18+
19+
--let SEARCH_FILE = `SELECT @@slow_query_log_file`
20+
--let SEARCH_PATTERN= update t1 set i=1
21+
--let SEARCH_RANGE= -1000
22+
--source include/search_pattern_in_file.inc
23+
24+
drop table t1;
25+
26+
set global event_scheduler= @event_scheduler_save;
27+
set global slow_query_log= @slow_query_log_save;
28+
set global long_query_time= @@session.long_query_time;

sql/sp_head.cc

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -3146,18 +3146,18 @@ sp_instr_stmt::execute(THD *thd, uint *nextp)
31463146
thd->query_length()) <= 0)
31473147
{
31483148
res= m_lex_keeper.reset_lex_and_exec_core(thd, nextp, FALSE, this);
3149+
bool log_slow= !res && thd->enable_slow_log;
31493150

3150-
if (thd->stmt_da->is_eof())
3151-
{
3152-
/* Finalize server status flags after executing a statement. */
3151+
/* Finalize server status flags after executing a statement. */
3152+
if (log_slow || thd->stmt_da->is_eof())
31533153
thd->update_server_status();
31543154

3155+
if (thd->stmt_da->is_eof())
31553156
thd->protocol->end_statement();
3156-
}
31573157

31583158
query_cache_end_of_result(thd);
31593159

3160-
if (!res && unlikely(thd->enable_slow_log))
3160+
if (log_slow)
31613161
log_slow_statement(thd);
31623162
}
31633163
else

0 commit comments

Comments
 (0)