Bug #52419 x86 assembly based atomic CAS causes test failures
Submitted: 28 Mar 2010 18:54 Modified: 3 Oct 2010 1:25
Reporter: Joerg Bruehe Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: General Severity:S2 (Serious)
Version:5.5.3-m3 OS:Linux (x86 icc)
Assigned to: Davi Arnaut
Triage: Needs Triage: D3 (Medium) / R6 (Needs Assessment) / E6 (Needs Assessment)

[28 Mar 2010 18:54] Joerg Bruehe
Description:
New test failure in the build of 5.5.3-m3,
specific to an ICC build on x86.

Not only does this test fail, it also leaves the DB in a different state than expected, causing several subsequent tests ti also fail -
some with a similar symptom,
others just because of the unexpected (non)existence of tables.

Trouble starts like this:

=====
binlog.binlog_stm_mix_innodb_myisam 'stmt' [ retry-fail ]
        Test ended at YYYY-MM-DD HH:MM:SS

CURRENT_TEST: binlog.binlog_stm_mix_innodb_myisam
--- /PATH/mysql-test/suite/binlog/r/binlog_stm_mix_innodb_myisam.result
+++ /PATH/mysql-test/suite/binlog/r/binlog_stm_mix_innodb_myisam.reject
@@ -15,7 +15,7 @@
 master-bin.000001  #   Query   #   #   BEGIN
 master-bin.000001  #   Query   #   #   use `test`; insert into t1 values(1)
 master-bin.000001  #   Query   #   #   use `test`; insert into t2 select * from t1
-master-bin.000001  #   Xid #   #   COMMIT /* XID */
+master-bin.000001  #   Query   #   #   COMMIT
 delete from t1;
 delete from t2;
 reset master;
@@ -24,8 +24,11 @@
 insert into t2 select * from t1;
 Warnings:
 Note   1592    Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT. Reason for unsafeness: Non-transactional reads or writes are unsafe if they occur after transactional reads or writes inside a transaction.
+Note   1592    Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT. Reason for unsafeness: Non-transactional reads or writes are unsafe if they occur after transactional reads or writes inside a transaction.
 rollback;
 Warnings:
+Note   1592    Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT. Reason for unsafeness: Non-transactional reads or writes are unsafe if they occur after transactional reads or writes inside a transaction.
+Note   1592    Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT. Reason for unsafeness: Non-transactional reads or writes are unsafe if they occur after transactional reads or writes inside a transaction.
 Warning    1196    Some non-transactional changed tables couldn't be rolled back
 show binlog events from <binlog_start>;
 Log_name   Pos Event_type  Server_id   End_log_pos Info
...
(more differences)
=====

Later, the server becomes schizophrenic about table "t2":
=====
@@ -306,15 +336,23 @@
 ERROR 23000: Duplicate entry '1' for key 'PRIMARY'
 DROP TABLE if exists t2;
 Warnings:
+Error  1062    Duplicate entry '1' for key 'PRIMARY'
 Note   1051    Unknown table 't2'
 INSERT INTO t1 values (3,3);
 CREATE TEMPORARY TABLE t2 (primary key (a)) engine=innodb select * from t1;
 ERROR 23000: Duplicate entry '1' for key 'PRIMARY'
 ROLLBACK;
 Warnings:
+Error  1062    Duplicate entry '1' for key 'PRIMARY'
+Note   1051    Unknown table 't2'
+Error  1062    Duplicate entry '1' for key 'PRIMARY'
 Warning    1196    Some non-transactional changed tables couldn't be rolled back
 DROP TABLE IF EXISTS t2;
 Warnings:
+Error  1062    Duplicate entry '1' for key 'PRIMARY'
+Note   1051    Unknown table 't2'
+Error  1062    Duplicate entry '1' for key 'PRIMARY'
+Warning    1196    Some non-transactional changed tables couldn't be rolled back
 Note   1051    Unknown table 't2'
 CREATE TABLE t2 (a int, b int, primary key (a)) engine=innodb;
 INSERT INTO t1 VALUES (4,4);
@@ -334,6 +372,14 @@
 INSERT INTO t1 values (7,7);
 ROLLBACK;
 Warnings:
+Error  1062    Duplicate entry '1' for key 'PRIMARY'
+Note   1051    Unknown table 't2'
+Error  1062    Duplicate entry '1' for key 'PRIMARY'
+Warning    1196    Some non-transactional changed tables couldn't be rolled back
+Note   1051    Unknown table 't2'
+Note   1050    Table 't2' already exists
+Error  1062    Duplicate entry '1' for key 'PRIMARY'
+Error  1062    Duplicate entry '1' for key 'PRIMARY'
 Warning    1196    Some non-transactional changed tables couldn't be rolled back
 INSERT INTO t1 values (8,8);
 CREATE TEMPORARY TABLE IF NOT EXISTS t2 (primary key (a)) engine=innodb select * from t1;
=====

See the combination of "Unknown table 't2'" and "Table 't2' already exists" !

Still later, table "t1" also is mentioned with unexpected (non)existence:
=====
+Note   1051    Unknown table 't1'
=====

In total, the output about just this one test is 518 lines.

Then, subsequent tests also fail -
some report similar problems:
    binlog.binlog_stm_unsafe_warning 'stmt'
    binlog.binlog_row_mix_innodb_myisam 'row'
    binlog.binlog_statement_insert_delayed 'stmt'
    rpl.rpl_concurrency_error 'stmt'

Others just report differences about tables "t1" and/or "t2" (or others) which I attribute to an unexpected state of the database caused by the error reported here:
    binlog.binlog_row_ctype_cp932 'row'
    binlog.binlog_stm_blackhole 'stmt' + 'mix'
    binlog.binlog_stm_ctype_cp932 'stmt'
    rpl.rpl_auto_increment 'row' + 'stmt' + 'mix'
    rpl.rpl_mixed_binlog_max_cache_size 'mix'
    rpl.rpl_row_binlog_max_cache_size 'row' +  'stmt'
    rpl.rpl_timezone 'row' + 'stmt' + 'mix'
    funcs_1.is_columns_memory
    funcs_1.is_columns_myisam
    funcs_1.memory_func_view
    funcs_1.memory_storedproc_02
    funcs_1.memory_storedproc_03
    funcs_1.memory_storedproc_06
    funcs_1.memory_storedproc_07
    funcs_1.memory_storedproc_08
    funcs_1.memory_storedproc_10
    parts.partition_mgm_lc1_memory
    parts.partition_mgm_lc1_myisam
    parts.partition_recover_myisam
    parts.partition_alter1_1_2_myisam
    parts.partition_alter1_1_myisam
    parts.partition_alter1_2_myisam
    parts.partition_alter2_1_myisam
    parts.partition_alter2_2_myisam
    parts.partition_alter4_myisam
    parts.partition_auto_increment_archive
    jp.jp_create_tbl_sjis
    jp.jp_create_tbl_ucs2
    jp.jp_create_tbl_ujis
    jp.jp_create_tbl_utf8
    main.ctype_latin1_de
    main.ctype_ucs2_def
    main.ctype_ldml
    main.innodb_mysql
    main.myisam-blob
    main.key_cache
    main.union
    main.warnings
    main.partition

Or there just is different cache use than expected:
    binlog.binlog_row_innodb_stat 'row' + 'stmt'

How to repeat:
Found while running the test suite.
[13 Sep 2010 8:29] Magne Mæhre
It looks that the test is run with MyISAM instead of InnoDB as the default storage engine.  I'm puzzled about why this happens with ICC build.   In the server, the default storage engine is set to InnoDB _unless_ EMBEDDED_LIBRARY is defined

#ifdef EMBEDDED_LIBRARY
  default_storage_engine= const_cast<char *>("MyISAM");
#else
  default_storage_engine= const_cast<char *>("InnoDB");
#endif
[17 Sep 2010 16:55] 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/118512

3207 Davi Arnaut	2010-09-17
      Bug#52419: Test "binlog_stm_mix_innodb_myisam" fails, complains about non-transactional
      
      The problem was that the x86 ASM atomic compare and swap
      could copy the wrong value to the ebx register, where the
      cmpxchg8b expects to see part of the "comparand" value.
      Since the original value in the ebx register is saved in
      the stack (that is, the push instruction causes the stack
      pointer to change), a wrong offset could be used if the
      compiler decides to put the source of the comparand value
      in the stack.
      
      The solution is to copy the comparand value directly from
      memory. Since the comparand value is 64-bits wide, it is
      copied in two steps over to the ebx and ecx registers.
[17 Sep 2010 18:23] Davi Arnaut
Changed synopsis to better reflect the problem. Was: Test "binlog_stm_mix_innodb_myisam" fails, complains about non-transactional
[17 Sep 2010 20:34] 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/118524

3093 Davi Arnaut	2010-09-17
      Bug#52419: x86 assembly based atomic CAS causes test failures
      
      The problem was that the x86 assembly based atomic CAS
      (compare and swap) implementation could copy the wrong
      value to the ebx register, where the cmpxchg8b expects
      to see part of the "comparand" value. Since the original
      value in the ebx register is saved in the stack (that is,
      the push instruction causes the stack pointer to change),
      a wrong offset could be used if the compiler decides to
      put the source of the comparand value in the stack.
      
      The solution is to copy the comparand value directly from
      memory. Since the comparand value is 64-bits wide, it is
      copied in two steps over to the ebx and ecx registers.
     @ include/atomic/x86-gcc.h
        For reference, an excerpt from a faulty binary follows.
        
        It is a disassembly of my_atomic-t, compiled at -O3 with
        ICC 11.0. Most of the code deals with preparations for
        a atomic cmpxchg8b operation. This instruction compares
        the value in edx:eax with the destination operand. If the
        values are equal, the value in ecx:ebx is stored in the
        destination, otherwise the value in the destination operand
        is copied into edx:eax.
        
        In this case, my_atomic_add64 is implemented as a compare
        and exchange. The addition is done over temporary storage
        and loaded into the destination if the original term value
        is still valid.
        
          volatile int64 a64;
          int64 b=0x1000200030004000LL;
          a64=0;
              mov    0xfffffda8(%ebx),%eax
              xor    %ebp,%ebp
              mov    %ebp,(%eax)
              mov    %ebp,0x4(%eax)
          my_atomic_add64(&a64, b);
              mov    0xfffffda8(%ebx),%ebp      # Load address of a64
              mov    0x0(%ebp),%edx             # Copy value
              mov    0x4(%ebp),%ecx
              mov    %edx,0xc(%esp)             # Assign to tmp var in the stack
              mov    %ecx,0x10(%esp)
              add    $0x30004000,%edx           # Sum values
              adc    $0x10002000,%ecx
              mov    %edx,0x8(%esp)             # Save part of result for later
              mov    0x0(%ebp),%esi             # Copy value of a64 again
              mov    0x4(%ebp),%edi
              mov    0xc(%esp),%eax             # Load the value of a64 used
              mov    0x10(%esp),%edx            # for comparison
              mov    %esi,(%esp)
              mov    %edi,0x4(%esp)
              push   %ebx                       # Push %ebx into stack. Changes esp.
              mov    0x8(%esp),%ebx             # Wrong restore of the result.
              lock cmpxchg8b 0x0(%ebp)
              sete   %cl
              pop    %ebx
[19 Sep 2010 20:04] Bugs System
Pushed into mysql-5.5 5.5.7-rc (revid:joerg@mysql.com-20100919200112-sandxxbu83pzc73w) (version source revid:joerg@mysql.com-20100919200112-sandxxbu83pzc73w) (merge vers: 5.5.7-rc) (pib:21)
[20 Sep 2010 12:00] Joerg Bruehe
Applying the patch does not only make this bug disappear,
it also helps for bug#56594 and bug#56602.

Setting those 2 as duplicates.
[22 Sep 2010 12:55] Joerg Bruehe
The patch is used in all possibly affected 5.5.6-rc binaries, including the RPMs.

However, there was a mishandling of source RPMs: The published ones are lacking the patch.
Other source formats (tar.gz, zip) are correct, include the patch.
[24 Sep 2010 13:25] Bugs System
Pushed into mysql-trunk 5.6.1-m4 (revid:kostja@sun.com-20100924132225-4q1jcqf55ktbsduz) (version source revid:kostja@sun.com-20100924132225-4q1jcqf55ktbsduz) (merge vers: 5.6.1-m4) (pib:21)
[24 Sep 2010 13:35] Bugs System
Pushed into mysql-next-mr (revid:kostja@sun.com-20100924133252-dayzhtbdbye7rwbp) (version source revid:kostja@sun.com-20100924133252-dayzhtbdbye7rwbp) (pib:21)
[27 Sep 2010 15:59] Paul Dubois
Noted in 5.5.7, 5.6.1 changelogs.

An atomic "compare and swap" operation using x86 assembler code (32
bit) could access incorrect data, which would make it work
incorrectly and lose the intended atomicity. This would in turn cause
the MySQL server to work on inconsistent data structures and return
incorrect data. That code part affected only 32-bit builds; the
effect has been observed when icc was used to build binaries. With
gcc, no incorrect results have been observed during tests, so this
fix is a proactive one. Other compilers do not use this assembler
code.
[29 Sep 2010 15:46] Davi Arnaut
FWIW, the first part of the changset comment has a typo, comparand is not quite the right word there.