Bug #84241 Potential Race Condition
Submitted: 16 Dec 2016 23:53 Modified: 16 Jan 2017 12:13
Reporter: Rui Gu Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7.15 OS:Ubuntu (16.04)
Assigned to: CPU Architecture:Any
Tags: race

[16 Dec 2016 23:53] Rui Gu
Description:
Description:
Our tool detects a potential race may occur in
https://github.com/mysql/mysql-server/blob/5.7/storage/innobase/handler/ha_innodb.cc
The following is the Valgrind(Helgrind) race detection report to
indicate the location.

==9586== ----------------------------------------------------------------            
==9586==                                                                        
==9586== Possible data race during write of size 8 at 0x2F21518 by thread #27   
==9586== Locks held: none                                                       
==9586==    at 0x1B928B0: innobase_active_small() (ha_innodb.cc:1756)           
==9586==    by 0x1B6D9E3: ha_innobase::write_row(unsigned char*) (ha_innodb.cc:7599)
==9586==    by 0xEDEEEC: handler::ha_write_row(unsigned char*) (handler.cc:7890)
==9586==    by 0x18D41DD: write_record(THD*, TABLE*, COPY_INFO*, COPY_INFO*) (sql_insert.cc:1860)
==9586==    by 0x18D1858: Sql_cmd_insert::mysql_insert(THD*, TABLE_LIST*) (sql_insert.cc:780)
==9586==    by 0x18D8C51: Sql_cmd_insert::execute(THD*) (sql_insert.cc:3092)    
==9586==    by 0x165113A: mysql_execute_command(THD*, bool) (sql_parse.cc:3554) 
==9586==    by 0x164C068: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5559)  
==9586==    by 0x1649705: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1427)
==9586==    by 0x164B5B3: do_command(THD*) (sql_parse.cc:995)                   
==9586==    by 0x179E3BF: handle_connection (connection_handler_per_thread.cc:300)
==9586==    by 0x1AD2C6B: pfs_spawn_thread (pfs.cc:2188)                        
==9586==                                                                        
==9586== This conflicts with a previous write of size 8 by thread #26           
==9586== Locks held: none                                                       
==9586==    at 0x1B928B0: innobase_active_small() (ha_innodb.cc:1756)           
==9586==    by 0x1B6D9E3: ha_innobase::write_row(unsigned char*) (ha_innodb.cc:7599)
==9586==    by 0xEDEEEC: handler::ha_write_row(unsigned char*) (handler.cc:7890)
==9586==    by 0x18D41DD: write_record(THD*, TABLE*, COPY_INFO*, COPY_INFO*) (sql_insert.cc:1860)
==9586==    by 0x18D1858: Sql_cmd_insert::mysql_insert(THD*, TABLE_LIST*) (sql_insert.cc:780)
==9586==    by 0x18D8C51: Sql_cmd_insert::execute(THD*) (sql_insert.cc:3092)    
==9586==    by 0x165113A: mysql_execute_command(THD*, bool) (sql_parse.cc:3554) 
==9586==    by 0x164C068: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5559)  
==9586==  Address 0x2f21518 is 0 bytes inside data symbol "_ZL23innobase_active_counter"
==9586==                                                                        
==9586== ----------------------------------------------------------------            

How to repeat:
How to repeat:
The command we're using is
./mysql-test-run.pl suite/binlog/t/binlog_mts_logical_clock.test

Our tool uses LLDB debugger to verify race first. The debugger will set
thread-specific breakpoints on the racing locations and check if when
two breakpoints are hit simultaneously, they access the same memory
location. The following link in github contains the screenshot of our
race verification result. The screenshot indicates that the two racing
instructions can indeed be reached simultaneously and they're accessing
the same memory address.

https://github.com/ruigulala/concurrency-exploits/blob/master/mysql-5.7.15/Screenshot%20fr...

For this race condition, srv_active_wake_master_thread() may be invoked in a
much less frequency when thread numbers are high.
[16 Jan 2017 12:13] Bogdan Kecman
Hi,

Thanks for the report