Bug #37798 main.log_tables fails randomly on powermacg5 and windows
Submitted: 2 Jul 2008 9:45 Modified: 10 Nov 2008 17:39
Reporter: Alexander Nozdrin Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Server Severity:S3 (Non-critical)
Version:5.1-bugteam,6.0-BK OS:Any
Assigned to: Patrick Crews CPU Architecture:Any
Tags: pushbuild, sporadic, test failure

[2 Jul 2008 9:45] Alexander Nozdrin
Description:
Symptom 1:
------------------------------------------------------------------------
@@ -318,8 +318,10 @@
 TIMESTAMP	USER_HOST	THREAD_ID	1	Query	rename table general_log TO renamed_general_log, general_log_new TO general_log
 select * from slow_log;
 start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text
+TIMESTAMP	USER_HOST	00:00:01	00:00:00	0	0	mysql	0	0	1	rename table slow_log TO renamed_slow_log, slow_log_new TO slow_log
 select * from renamed_slow_log;
 start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text
+TIMESTAMP	USER_HOST	00:00:01	00:00:00	0	0	mysql	0	0	1	create table slow_log_new like slow_log
 set global general_log='OFF';
 RENAME TABLE general_log TO general_log2;
 set global slow_query_log='OFF';
------------------------------------------------------------------------

Symptom 2:
------------------------------------------------------------------------
@@ -320,6 +320,7 @@
 start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text
 select * from renamed_slow_log;
 start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text
+TIMESTAMP	USER_HOST	00:00:01	00:00:00	0	0	mysql	0	0	1	create table slow_log_new like slow_log
 set global general_log='OFF';
 RENAME TABLE general_log TO general_log2;
 set global slow_query_log='OFF';
------------------------------------------------------------------------

How to repeat:
https://intranet.mysql.com/secure/pushbuild/xref.pl?startdate=&enddate=&dir=&plat=&testtyp...
[22 Jul 2008 9:37] Georgi Kodinov
Observed in 5.1-bugteam also (http://tinyurl.com/5sa9yl).
[20 Sep 2008 7:28] Patrick Crews
I suspect that this is a case of not cleaning up properly after playing with the long_query_time value.

Patch will be coming once I have tested this theory out a bit more.
[20 Sep 2008 8:26] Bugs System
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/54403

2744 Patrick Crews	2008-09-20
      Bug#37798 main.log_tables fails randomly on powermacg5 and windows
      
      Found that long_query_time was left set to 1 at the end of a subtest.
      Added a cleanup line to reset to default (10s)
      Cannot definitively say that this will work on a busy machine, but I expect this will correct the random failures.
      Re-recorded .result file to account for cleanup SET statement.
[29 Sep 2008 20:31] Bugs System
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/54700

2746 Patrick Crews	2008-09-29
      Bug#37798: main.log_tables fails randomly on powermacg5 and windows
      
      Found that the long_query_time wasn't being reset to default and suspect that this 
      could be causing the failures on Pushbuild machines.
      
      Couldn't duplicate original failure, but having the long_query_time set so low (0 or 1)
      gives a high chance of result variation.
      
      Re-recorded .result file and also made minor adjustments to have pre and post test variables match
      (only set log_output to FILE only rather than FILE+TABLE)
[8 Oct 2008 13:07] Matthias Leich
Content of the review email sent 2008-09-30
-------------------------------------------
Hi Patrick,

I have already read the email by Horst.

http://bugs.mysql.com/37798  main.log_tables

- My understanding is that the failures reported within the bug report
  are caused by: Low value of @@session.long_query_time meets overloaded
  Pushbuild boxes
- The subtest for the historical bugs #17544 #21785 (~ line 300 -
  380)
  - expect to get empty result sets for select * from slow_log
  - do not check anything around the current value of
    @@session.long_query_time
- Your fix repairs the problem to about 99.9%
  But
  - The default or startup value of @@session.long_query_time could
    be less than 10 seconds in future.
  - PB could be (I hope not) weaker in future
  - Like Horst mentioned the @@session.long_query_time value from
    beginning of the tests might be different than default in future
    (imagine mysql-test-run.pl uses somewhere because of whatever reason
     non default values).
    The resettings of @@session.long_query_time to startup value is
    not strict needed, because the next test(script) gets a new session.
    But somebody else might put a new subtest into the same script and
    wonder why we have non default|startup values.

  What about 99.999 % ?  ;-) 
  -------------------------
  Around line 160:
  truncate table mysql.slow_log;
  set session long_query_time=1;
  select sleep(2);
  set session long_query_time = <value from beginning of the test>;
              # Set it already here because the
              # next SQL statement could have misfortune in PB.
  --replace_column 1 TIMESTAMP 2 USER_HOST 3 QUERY_TIME
  select * from mysql.slow_log;
  ....
  Around line 300 - 380 (subtest for bug #17544,#21785) are the next
  SELECT's (=the critical ones).
  set session long_query_time = 1000;
  <The existing subtest>
  set session long_query_time = <value from beginning of the test>

Regards,

Matthias
[8 Oct 2008 21:03] Bugs System
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/55829

2765 Patrick Crews	2008-10-08
      Bug#37798:  main.log_table fails randomly on powermacg5 and windows
      
      Revised test file:
      Pulled capturing of initial system variable values to the start of the test -
      Found subtests that were doing this didn't always clean up, etc and was causing
      bad (not initial) values to propagate.  Placed a cleanup section at the end of the test
      to ensure proper exit of the test
      
      Included review suggestions into the .test file as well
      
      Re-recorded .result file to accomodate .test changes.
[20 Oct 2008 21:22] Bugs System
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/56630

2675 Patrick Crews	2008-10-20
      Bug#37798: main.log_tables fails randomly on powermacg5 and windows.
      
      Cleanup of test case - captured manipulated variables' start values at beginning of test
      and placed final cleanup / reset at very end of test.
      
      Removed intermediate captures to prevent erroneous variable settings.
      
      Found that long_query_time was stuck at '1' for a large portion of the test and the likely culprit
      
      Re-recorded .result file to account for changes in .test file.
[20 Oct 2008 21:27] Bugs System
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/56631

2884 Patrick Crews	2008-10-20 [merge]
      Bug#37798 Merge 5.1 -> 6.0
[20 Oct 2008 22:41] Bugs System
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/56640

2675 Patrick Crews	2008-10-20
      Bug#37798 main.log_tables fails randomly on powermacg5 and windows
      
      Fixed .test file, re-recorded .result file
      
      Ensured reset of system variables at the end of subtests.
[10 Nov 2008 10:51] Bugs System
Pushed into 6.0.8-alpha  (revid:patrick.crews@sun.com-20081020224119-a8mapamqrnca0lpk) (version source revid:kgeorge@mysql.com-20081021085131-2v86qbmg27inufx2) (pib:5)
[10 Nov 2008 11:35] Bugs System
Pushed into 5.1.30  (revid:patrick.crews@sun.com-20081020224119-a8mapamqrnca0lpk) (version source revid:kgeorge@mysql.com-20081021080008-9xhs5h7niqdhfz4h) (pib:5)
[10 Nov 2008 17:39] Paul DuBois
Test case changes. No changelog entry needed.
[19 Jan 2009 11:27] Bugs System
Pushed into 5.1.31-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090119095303-uwwvxiibtr38djii) (version source revid:tomas.ulin@sun.com-20090108105244-8opp3i85jw0uj5ib) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)
[19 Jan 2009 13:05] Bugs System
Pushed into 5.1.31-ndb-6.3.21 (revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (version source revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (merge vers: 5.1.31-ndb-6.3.21) (pib:6)
[19 Jan 2009 16:11] Bugs System
Pushed into 5.1.31-ndb-6.4.1 (revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (version source revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (merge vers: 5.1.31-ndb-6.4.1) (pib:6)