MySQL Bugs: #18981: event_logs

Bug #18981	event_logs_tests failure
Submitted:	10 Apr 2006 19:10	Modified:	25 Jan 2007 8:23
Reporter:	Brian Pontz	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Stored Routines	Severity:	S3 (Non-critical)
Version:	5.1.9-pre	OS:	SunOS 5.10 , Linux X86 with ICC
Assigned to:	Andrey Hristov	CPU Architecture:	Any

Description:
events_logs_tests              [ fail ]

Errors are (from PATH/mysqltest-time) :
mysqltest: Result content mismatch
(the last lines may be the most important ones)
Below are the diffs between actual and expected results:
-------------------------------------------------------
*** r/events_logs_tests.result
--- r/events_logs_tests.reject
***************
*** 43,49
  0
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host     query_time      db      sql_text
! root[root] @ localhost []     00:00:03        events_test     SELECT SLEEP(3)
  TRUNCATE mysql.slow_log;
  CREATE TABLE slow_event_test (slo_val tinyint, val tinyint);
  "This won't go to the slow log"
--- 43,49
  0
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host     query_time      db      sql_text
! root[root] @ localhost []     00:00:04        events_test     SELECT SLEEP(3)
  TRUNCATE mysql.slow_log;
  CREATE TABLE slow_event_test (slo_val tinyint, val tinyint);
  "This won't go to the slow log"
----------------------------------------------------------------------------------------------------------------------------

events_logs_tests              [ fail ]

Errors are (from PATH/mysqltest-time) :
mysqltest: Result length mismatch
(the last lines may be the most important ones)
Below are the diffs between actual and expected results:
-------------------------------------------------------
*** r/events_logs_tests.result
--- r/events_logs_tests.reject
***************
*** 62,67
--- 62,68
  "Check slow log. Should not see anything because 3 is under the threshold of 4 for GLOBAL, though over SESSION which is 2"
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host     query_time      db      sql_text
+ root[root] @ localhost []     00:00:05        events_test     TRUNCATE mysql.slow_log
  "This should go to the slow log"
  SET SESSION long_query_time=10;
  DROP EVENT long_event;
***************
*** 75,80
--- 76,82
  "Check slow log. Should see 1 row because 5 is over the threshold of 4 for GLOBAL, though under SESSION which is 10"
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host     query_time      db      sql_text
+ root[root] @ localhost []     00:00:05        events_test     TRUNCATE mysql.slow_log
  root[root] @ localhost [localhost]    00:00:05        events_test     INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(5)
  DROP EVENT long_event2;
  SET GLOBAL  long_query_time =@old_global_long_query_time;
-------------------------------------------------------

How to repeat:
run test shown above on oses mentioned

I got a similar failure:

events_logs_tests              [ fail ]

Errors are (from /home/mydev/mysql-5.1-bug18129/tmp/test2/mysql-test/var/log/mysqltest-time) :
mysqltest: Result length mismatch
(the last lines may be the most important ones)
Below are the diffs between actual and expected results:
-------------------------------------------------------
*** r/events_logs_tests.result  2006-04-26 11:04:28.000000000 +0300
--- r/events_logs_tests.reject  2006-04-26 14:29:44.000000000 +0300
***************
*** 19,25 ****
  "Should see 3 rows - the 'SELect' is in the middle. The other two are selects from general_log"
  call select_general_log();
  user_host     argument
- root[root] @ localhost [localhost]    SELect 'alabala', sleep(3) from dual
  DROP PROCEDURE select_general_log;
  DROP EVENT log_general;
  SET GLOBAL event_scheduler=0;
--- 19,24 ----
-------------------------------------------------------

The particular problem that ingo reports is also seen frequently in pushbuild.

I investigated, and found that the problem is the following:

    SET GLOBAL event_scheduler=0;
    create event log_general on schedule every 1 minute do ....
    SET GLOBAL event_scheduler=1;
    sleep 2
    call select_general_log();

The problem that occurs is that the CREATE EVENT is scheduled to run at time t1 = NOW() and every 60 seconds after that. Then depending on timing, events are enabled at time t1 + 1 second. In this case the event is not scheduled for another 59 seconds.

That is not a bug, it is a problem in the test case. I think the event should be created after "SET GLOBAL event_scheduler=1".

Please see also bug: http://bugs.mysql.com/bug.php?id=20031
which was marked as duplicate of this one.

This should be fixed.

events_logs_tests              [ fail ]

Errors are (from /Users/henry/pb/mysql-5.1-new-rpl/142/mysql-5.1.15-beta-pb142/mysql-test/var-ps_stm-8/log/mysqltest-time) :
mysqltest: Result length mismatch
(the last lines may be the most important ones)
Below are the diffs between actual and expected results:
-------------------------------------------------------
*** r/events_logs_tests.result	Mon Dec 11 16:22:05 2006
--- r/events_logs_tests.reject	Mon Dec 11 17:43:39 2006
***************
*** 71,76 ****
--- 71,77 ----
  "Check slow log. Should not see anything because 1.5 is under the threshold of 300 for GLOBAL, though over SESSION which is 2"
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host	query_time	db	sql_text
+ root[root] @ localhost [localhost]	00:00:05	events_test	INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(1.5)
  "This should go to the slow log"
  DROP EVENT long_event;
  SET SESSION long_query_time=10;
***************
*** 85,90 ****
--- 86,92 ----
  "Check slow log. Should see 1 row because 4 is over the threshold of 3 for GLOBAL, though under SESSION which is 10"
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host	query_time	db	sql_text
+ USER_HOST	SLEEPVAL	events_test	INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(1.5)
  USER_HOST	SLEEPVAL	events_test	INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(2)
  DROP EVENT long_event2;
  "Make it quite long"

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/17582

ChangeSet@1.2369, 2007-01-03 14:09:31+01:00, andrey@example.com +2 -0
  fix for bug #18981 event_logs_tests failure
  On loaded boxes it is possible a INSERT with sleep of 1.5s to take
  more time.

Pushed into 5.1.15

Change in testing only, not visible to end users - closed without further action.