Bug #29971 status.test fails
Submitted: 23 Jul 2007 8:00 Modified: 18 Jun 2009 15:00
Reporter: Ingo Strüwing Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Locking Severity:S2 (Serious)
Version:5.1.27 + Cluster 6.3.17 OS:Any
Assigned to: Philip Stoev CPU Architecture:Any
Tags: pbfail

[23 Jul 2007 8:00] Ingo Strüwing
Description:
main.status                    [ fail ]

Errors are (from /Users/henry/pb/mysql-5.1-engines/216/mysql-5.1.21-beta-pb216/mysql-test/var-ps_stm-6/log/mysqltest-time) :
mysqltest: Result content mismatch
(the last lines may be the most important ones)
Below are the diffs between actual and expected results:
-------------------------------------------------------
*** /Users/henry/pb/mysql-5.1-engines/216/mysql-5.1.21-beta-pb216/mysql-test/r/status.result	Mon Jul 23 04:55:22 2007
--- /Users/henry/pb/mysql-5.1-engines/216/mysql-5.1.21-beta-pb216/mysql-test/r/status.reject	Mon Jul 23 07:05:52 2007
***************
*** 18,29 ****
  unlock tables;
  show status like 'Table_lock%';
  Variable_name	Value
! Table_locks_immediate	3
! Table_locks_waited	1
  select * from information_schema.session_status where variable_name like 'Table_lock%';
  VARIABLE_NAME	VARIABLE_VALUE
! TABLE_LOCKS_IMMEDIATE	3
! TABLE_LOCKS_WAITED	1
  drop table t1;
  select 1;
  1
--- 18,29 ----
  unlock tables;
  show status like 'Table_lock%';
  Variable_name	Value
! Table_locks_immediate	4
! Table_locks_waited	0
  select * from information_schema.session_status where variable_name like 'Table_lock%';
  VARIABLE_NAME	VARIABLE_VALUE
! TABLE_LOCKS_IMMEDIATE	4
! TABLE_LOCKS_WAITED	0
  drop table t1;
  select 1;
  1
-------------------------------------------------------
Please follow the instructions outlined at

How to repeat:
See push Mon Jul 23 03:28:26 2007 istruewing, platform 'powermacg5' -max, on https://intranet.mysql.com/secure/pushbuild/showdir.pl?dir=mysql-5.1-engines
[24 Jul 2007 12:20] Evgeny Potemkin
Tested on the build that failed test.
Host - powermacg5.

main.ssl_connect               [ pass ]           7086
main.status                    [ pass ]           8335
main.strict                    [ pass ]           2858
[5 Sep 2008 9:28] Joerg Bruehe
A single test run is not sufficient to set a sporadic failure to "can't repeat".

In the builds of Cluster 6.3.17, whose main server code is based on 5.1.27, I had these failures (which IMO are all just variations of the original report in this bug):

=====
main.status                    [ fail ]

--- /PATH/mysql-test/r/status.result
+++ /PATH/mysql-test/r/status.reject
@@ -20,7 +20,7 @@
 unlock tables;
 show status like 'Table_locks_waited';
 Variable_name  Value
-Table_locks_waited     1
+Table_locks_waited     2
 drop table t1;
 set global general_log = @old_general_log;
 select 1;

mysqltest: Result content mismatch
=====
12 occurrences, most of them in RPM build for SuSE 9 / x86 (32)

=====
main.status                    [ fail ]

--- /PATH/mysql-test/r/status.result
+++ /PATH/mysql-test/r/status.reject
@@ -5,7 +5,7 @@
 Table_locks_waited     0
 select * from information_schema.session_status where variable_name like 'Table_lock%';
 VARIABLE_NAME  VARIABLE_VALUE
-TABLE_LOCKS_IMMEDIATE  2
+TABLE_LOCKS_IMMEDIATE  3
 TABLE_LOCKS_WAITED     0
 SET SQL_LOG_BIN=0;
 set @old_general_log = @@global.general_log;

mysqltest: Result content mismatch
=====
3 occurrences on Solaris 9: 2 on Sparc-64, 1 on x86.

=====
main.status                    [ fail ]

--- /PATH/mysql-test/r/status.result
+++ /PATH/mysql-test/r/status.reject
@@ -1,11 +1,11 @@
 flush status;
 show status like 'Table_lock%';
 Variable_name  Value
-Table_locks_immediate  1
+Table_locks_immediate  2
 Table_locks_waited     0
 select * from information_schema.session_status where variable_name like 'Table_lock%';
 VARIABLE_NAME  VARIABLE_VALUE
-TABLE_LOCKS_IMMEDIATE  2
+TABLE_LOCKS_IMMEDIATE  3
 TABLE_LOCKS_WAITED     0
 SET SQL_LOG_BIN=0;
 set @old_general_log = @@global.general_log;

mysqltest: Result content mismatch
=====
1 occurrence: RPM on RedHat 4, x86_64

See also bug#29307, which also was reported for 5.1.21.
I have not seen this in builds of 5.1.22 to 5.1.27,
but the test failure seems to depend on timing and is a sporadic one.
[13 Nov 2008 14:41] Sven Sandberg
xref: http://tinyurl.com/5cvj79
[9 Jun 2009 10:47] Philip Stoev
------------------------------------------------------------
revno: 2875
committer: Philip Stoev <pstoev@mysql.com>
branch nick: 5.1-bugteam
timestamp: Tue 2009-06-09 13:31:41 +0300
message:
  Bug #29971 status.test fails

  This test uses SHOW STATUS and the like, which may be unstable in the face
  of logging to table, since the CSV handler is actively executing operations
  and thus incrementing the counters.

  Fixed by disabling logging to table for the duration of the test and restoring
  it afterwards. This causes various counters to properly start counting from zero
  and never advance due to CSV operations.

=== modified file 'mysql-test/r/status.result'
--- mysql-test/r/status.result  2009-02-05 16:48:47 +0000
+++ mysql-test/r/status.result  2009-06-09 10:31:41 +0000
@@ -1,13 +1,15 @@
 set @old_concurrent_insert= @@global.concurrent_insert;
 set @@global.concurrent_insert= 0;
+SET @old_log_output = @@global.log_output;
+SET GLOBAL LOG_OUTPUT = 'FILE';
 flush status;
 show status like 'Table_lock%';
 Variable_name  Value
-Table_locks_immediate  1
+Table_locks_immediate  0
 Table_locks_waited     0
 select * from information_schema.session_status where variable_name like 'Table_lock%';
 VARIABLE_NAME  VARIABLE_VALUE
-TABLE_LOCKS_IMMEDIATE  2
+TABLE_LOCKS_IMMEDIATE  0
 TABLE_LOCKS_WAITED     0
 # Switched to connection: con1
 set sql_log_bin=0;
@@ -154,7 +156,7 @@
 Com_show_status        3
 show status like 'hand%write%';
 Variable_name  Value
-Handler_write  5
+Handler_write  0
 show status like '%tmp%';
 Variable_name  Value
 Created_tmp_disk_tables        0
@@ -162,7 +164,7 @@
 Created_tmp_tables     0
 show status like 'hand%write%';
 Variable_name  Value
-Handler_write  7
+Handler_write  0
 show status like '%tmp%';
 Variable_name  Value
 Created_tmp_disk_tables        0
@@ -237,3 +239,4 @@
 DROP PROCEDURE p1;
 DROP FUNCTION f1;
 set @@global.concurrent_insert= @old_concurrent_insert;
+SET GLOBAL log_output = @old_log_output;

=== modified file 'mysql-test/t/status.test'
--- mysql-test/t/status.test    2009-03-06 14:56:17 +0000
+++ mysql-test/t/status.test    2009-06-09 10:31:41 +0000
@@ -12,6 +12,12 @@
 set @old_concurrent_insert= @@global.concurrent_insert;
 set @@global.concurrent_insert= 0;

+# Disable logging to table, since this will also cause table locking and unlocking, which will
+# show up in SHOW STATUS and may cause sporadic failures
+
+SET @old_log_output = @@global.log_output;
+SET GLOBAL LOG_OUTPUT = 'FILE';
+
 # PS causes different statistics
 --disable_ps_protocol

@@ -350,6 +356,7 @@
 # Restore global concurrent_insert value. Keep in the end of the test file.
 --connection default
 set @@global.concurrent_insert= @old_concurrent_insert;
+SET GLOBAL log_output = @old_log_output;

 # Wait till we reached the initial number of concurrent sessions
 --source include/wait_until_count_sessions.inc
[9 Jun 2009 13:16] Bernt Marius Johnsen
ok to push, although I am suprised that the time running this test varies from 44ms to 1200ms on my laptop....
[12 Jun 2009 3:37] 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/76155

2934 Philip Stoev	2009-06-10
      Bug #29971 status.test fails
      
      This test uses SHOW STATUS and the like, which may be unstable in the face
      of logging to table, since the CSV handler is actively executing operations
      and thus incrementing the counters.
      
      Fixed by disabling logging to table for the duration of the test and restoring
      it afterwards. This causes various counters to properly start counting from zero
      and never advance due to CSV operations.
[12 Jun 2009 3:37] 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/76157

2875 Philip Stoev	2009-06-09
      Bug #29971 status.test fails
      
      This test uses SHOW STATUS and the like, which may be unstable in the face
      of logging to table, since the CSV handler is actively executing operations
      and thus incrementing the counters.
      
      Fixed by disabling logging to table for the duration of the test and restoring
      it afterwards. This causes various counters to properly start counting from zero
      and never advance due to CSV operations.
[16 Jun 2009 11:03] Bugs System
Pushed into 5.1.36 (revid:joro@sun.com-20090616102155-3zhezogudt4uxdyn) (version source revid:pstoev@mysql.com-20090610085836-2fwbqou6ftta10fb) (merge vers: 5.1.36) (pib:6)
[16 Jun 2009 13:44] Paul DuBois
Test case changes. No changelog entry needed.

Setting report to NDI pending push into 5.4.x.
[17 Jun 2009 19:21] Bugs System
Pushed into 5.4.4-alpha (revid:alik@sun.com-20090616183122-chjzbaa30qopdra9) (version source revid:davi.arnaut@sun.com-20090610124320-yfjmokbkly12brvi) (merge vers: 5.4.4-alpha) (pib:11)
[18 Jun 2009 15:00] Paul DuBois
Test case changes. No changelog entry needed.
[26 Aug 2009 13:45] Bugs System
Pushed into 5.1.37-ndb-7.0.8 (revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)
[26 Aug 2009 13:46] Bugs System
Pushed into 5.1.37-ndb-6.3.27 (revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (version source revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (merge vers: 5.1.37-ndb-6.3.27) (pib:11)
[26 Aug 2009 13:48] Bugs System
Pushed into 5.1.37-ndb-6.2.19 (revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (version source revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (merge vers: 5.1.37-ndb-6.2.19) (pib:11)
[27 Aug 2009 16:32] Bugs System
Pushed into 5.1.35-ndb-7.1.0 (revid:magnus.blaudd@sun.com-20090827163030-6o3kk6r2oua159hr) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)