| 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: | |
| Category: | MySQL Server: General | Severity: | S2 (Serious) |
| Version: | 5.5.3-m3 | OS: | Linux (x86 icc) |
| Assigned to: | Davi Arnaut | CPU Architecture: | Any |
[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.
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.