| Bug #77866 | data race on innodb os_thread_count | ||
|---|---|---|---|
| Submitted: | 28 Jul 2015 20:35 | Modified: | 5 Jan 2016 14:41 |
| Reporter: | Richard Prohaska | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 5.7.10 | OS: | Linux |
| Assigned to: | CPU Architecture: | Any | |
[28 Jul 2015 20:35]
Richard Prohaska
[29 Jul 2015 11:20]
MySQL Verification Team
Hello Richard, Thank you for the report. Observed this with 5.7.7 builds. Thanks, Umesh
[29 Jul 2015 11:20]
MySQL Verification Team
## Source pulled from http://dev.mysql.com/downloads/mysql/ [umshastr@hod03]/export/umesh/server/source: md5sum mysql-5.7.7-rc.tar.gz 36a96021a93ca236e76f5c90ae19cd44 mysql-5.7.7-rc.tar.gz (patched mtr with https://github.com/prohaska7/mysql-server/commit/62ba491a8fe463453281d0b766f3fc85fd1c6cb5) [umshastr@hod03]/export/umesh/server/source/mysql-5.7.7-rc: cmake . -DDOWNLOAD_BOOST=1 -DWITH_BOOST=/tmp -DCMAKE_BUILD_TYPE=Debug [umshastr@hod03]/export/umesh/server/source/mysql-5.7.7-rc: make -j 16 [umshastr@hod03]/export/umesh/server/source/mysql-5.7.7-rc/mysql-test: ./mtr --debug --helgrind donothing Logging: ./mtr --debug --helgrind donothing MySQL Version 5.7.7 Turning on valgrind with helgrind for mysqld(s) Checking supported features... - SSL connections supported - binaries are debug compiled Collecting tests... Checking leftover processes... Removing old var directory... Creating var directory '/export/umesh/server/source/mysql-5.7.7-rc/mysql-test/var'... Installing system database... ============================================================================== TEST RESULT TIME (ms) or COMMENT -------------------------------------------------------------------------- worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009 worker[1] mysql-test-run: WARNING: Waited 60 seconds for /export/umesh/server/source/mysql-5.7.7-rc/mysql-test/var/mysqld.1/data/auto.cnf to be created, still waiting for 120 seconds... worker[1] mysql-test-run: WARNING: Check-testcase failed, this could also be caused by the previous test run by this worker thread main.donothing [ fail ] Test ended at 2015-07-29 11:45:59 CURRENT_TEST: main.donothing Timeout for 'check-testcase' expired after 90 secondsmysqltest failed but provided no output - the logfile can be found in '/export/umesh/server/source/mysql-5.7.7-rc/mysql-test/var/log/main.donothing/donothing.log' -------------------------------------------------------------------------- The servers were restarted 0 times Spent 0.000 of 188 seconds executing testcases Completed: Failed 1/1 tests, 0.00% were successful. Failing test(s): main.donothing The log files in var/log may give you some hint of what went wrong. If you want to report this error, please read first the documentation at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html mysql-test-run: *** ERROR: there were failing test cases [umshastr@hod03]/export/umesh/server/source/mysql-5.7.7-rc/mysql-test: ==11503== Possible data race during read of size 8 at 0x2C0DEA8 by thread #1 ==11503== Locks held: none ==11503== at 0x192785B: os_thread_create_func(void* (*)(void*), void*, unsigned long*) (os0thread.cc:183) ==11503== by 0x191041B: recv_recovery_rollback_active() (log0recv.cc:3624) ==11503== by 0x1A0F74B: innobase_start_or_create_for_mysql() (srv0start.cc:2289) ==11503== by 0x1878303: innobase_init(void*) (ha_innodb.cc:3464) ==11503== by 0xF6AD83: ha_initialize_handlerton(st_plugin_int*) (handler.cc:778) ==11503== by 0x158A9CD: plugin_initialize(st_plugin_int*) (sql_plugin.cc:1203) ==11503== by 0x158B1BF: plugin_init(int*, char**, int) (sql_plugin.cc:1456) ==11503== by 0xEFE2D7: init_server_components() (mysqld.cc:4091) ==11503== by 0xEFF2CE: mysqld_main(int, char**) (mysqld.cc:4676) ==11503== by 0xEF7C0F: main (main.cc:25) ==11503== ==11503== This conflicts with a previous write of size 8 by thread #10 ==11503== Locks held: 1, at address 0x2C0DE10 ==11503== at 0x192791E: os_thread_exit(void*) (os0thread.cc:210) ==11503== by 0x1A3D454: trx_rollback_or_clean_all_recovered (trx0roll.cc:817) ==11503== by 0x4C2CECD: ??? (in /usr/lib64/valgrind/vgpreload_helgrind-amd64-linux.so) ==11503== by 0x4E3BDF2: start_thread (in /usr/lib64/libpthread-2.17.so) ==11503== by 0x61AA47C: clone (in /usr/lib64/libc-2.17.so)
[29 Jul 2015 11:48]
MySQL Verification Team
// 5.7.9
[umshastr@hod03]/export/umesh/server/source: md5sum 16026794.mysql-5.7-export-8266721.tar.gz
f99c1265b5785850683e002b4a40d798 16026794.mysql-5.7-export-8266721.tar.gz
[umshastr@hod03]/export/umesh/server/source/mysql-5.7-export-8266721: cmake . -DDOWNLOAD_BOOST=1 -DWITH_BOOST=/tmp -DCMAKE_BUILD_TYPE=Debug
[umshastr@hod03]/export/umesh/server/source/mysql-5.7-export-8266721: make -j 16
[umshastr@hod03]/export/umesh/server/source/mysql-5.7-export-8266721/mysql-test: ./mtr --debug --helgrind donothing
Logging: ./mtr --debug --helgrind donothing
MySQL Version 5.7.9
Turning on valgrind with helgrind for mysqld(s)
Checking supported features...
- SSL connections supported
- binaries are debug compiled
Collecting tests...
Removing old var directory...
Creating var directory '/export/umesh/server/source/mysql-5.7-export-8266721/mysql-test/var'...
Installing system database...
==============================================================================
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
worker[1] mysql-test-run: WARNING: Check-testcase failed, this could also be caused by the previous test run by this worker thread
main.donothing [ fail ]
Test ended at 2015-07-29 13:40:36
CURRENT_TEST: main.donothing
Timeout for 'check-testcase' expired after 90 secondsmysqltest failed but provided no output
- the logfile can be found in '/export/umesh/server/source/mysql-5.7-export-8266721/mysql-test/var/log/main.donothing/donothing.log'
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 132 seconds executing testcases
Completed: Failed 1/1 tests, 0.00% were successful.
Failing test(s): main.donothing
The log files in var/log may give you some hint of what went wrong.
If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
mysql-test-run: *** ERROR: there were failing test cases
==2223== Possible data race during read of size 8 at 0x2AAEA30 by thread #1
==2223== Locks held: none
==2223== at 0x17FC3A1: os_thread_create_func(void* (*)(void*), void*, unsigned long*) (os0thread.cc:183)
==2223== by 0x17DF249: recv_recovery_rollback_active() (log0recv.cc:3816)
==2223== by 0x18F0122: innobase_start_or_create_for_mysql() (srv0start.cc:2330)
==2223== by 0x173A9A3: innobase_init(void*) (ha_innodb.cc:3652)
==2223== by 0xE2AC10: ha_initialize_handlerton(st_plugin_int*) (handler.cc:840)
==2223== by 0x142B596: plugin_initialize(st_plugin_int*) (sql_plugin.cc:1171)
==2223== by 0x142BDAE: plugin_init(int*, char**, int) (sql_plugin.cc:1428)
==2223== by 0xDB7355: init_server_components() (mysqld.cc:4073)
==2223== by 0xDB837D: mysqld_main(int, char**) (mysqld.cc:4652)
==2223== by 0xDB0FDF: main (main.cc:25)
==2223==
==2223== This conflicts with a previous write of size 8 by thread #10
==2223== Locks held: 1, at address 0x2AAE9B8
==2223== at 0x17FC464: os_thread_exit(void*) (os0thread.cc:210)
==2223== by 0x192B90D: trx_rollback_or_clean_all_recovered (trx0roll.cc:861)
==2223== by 0x4C2CECD: ??? (in /usr/lib64/valgrind/vgpreload_helgrind-amd64-linux.so)
==2223== by 0x4E3BDF2: start_thread (in /usr/lib64/libpthread-2.17.so)
==2223== by 0x63B547C: clone (in /usr/lib64/libc-2.17.so)
==2223==
[31 Jul 2015 9:06]
Erlend Dahl
Posted by developer:
[29 Jul 2015 16:09] Sunny Bains
182
183 ut_a(os_thread_count <= OS_THREAD_MAX_N);
184
185 /* Return the thread_id if the caller requests it. */
186 if (thread_id != NULL) {
187 *thread_id = new_thread_id;
188 }
The variable *is* read without any mutex on line 183 but there is no race.
The variable was incremented in this very function and there it was done
under the cover of the mutex. That should have issued the correct load/store
fences. The above condition must hold independent of any mutex, only thing
required is atomicity. That should be OK on Intel x86. For C++11 we can
specify that explicitly with *relaxed., which is probably the right thing to
do anyway.
[31 Jul 2015 16:12]
Richard Prohaska
The race is between the assert in os_thread_create and os_thread_exit. Suppose that OS_THREAD_MAX_N is a hard limit. os_thread_create gets called and increments the count past the limit. while the count is being read in the assert in os_thread_create, os_thread exit simultaneously decrements the count. Since the read of the count is not serialized, the assert may or may not fire depending on the data race. IMO, this is a real data race. The fix is to move the assert up to where the count is incremented.
[1 Aug 2015 0:23]
Sunny Bains
Going beyond the max thread count is something I did not consider, and you are correct that it will not catch the temporary overflow. Though, as long as the read is atomic and the correct barriers are being issued, it should still enforce the invariant that we don't have more threads active in the system than there are waiting slots. As long as on thread create function exit we don't break that invariant we are OK. Some InnoDB specific things, only the main thread creates worker threads at startup. Worker threads created by the main thread don't further create new threads. Therefore the increment and decrement will always be handled by this one main thread. the exception is the FTS tokenize threads. Those are created by the user threads that are doing DDL and there can only be one active AFAIU due to MDL and this thread create/exit can never run when the worker threads are being created during startup. MAX := 1 and os_thread_count := 1, thread T1 is active Main thread is creating T2 mutex.enter(); ++os_thread_count; -- this goes over MAX mutex_exit(); Context switch to Thread1, first thread exists, in thread_exit() we have: mutex.enter(); --os_thread_count; -- this goes back to MAX mutex.exit(); Context switch back to the main thread: ut_a(os_thread_count <= MAX); -- if the read is atomic this should still hold, on x86 AFAIK it is. In other words, if I replace the mutex.enter(); incr/decr; mutex.exit(); by atomic increment with the correct barriers. the invariant that thread create is trying to enforce should still hold. In this case we rely on mutex enter/exit to issue the correct barriers. What am I missing? Given that I had to spend more time explaining this than the one line fix suggested, I think it is better to do the fix :-). Everything becomes obvious.
[5 Jan 2016 13:58]
Richard Prohaska
The thread sanitizer reports a data race on the os_thread_count variable. The assert 'ut_a(os_thread_count <= OS_THREAD_MAX_N)' should hold the 'thread_mutex'.
WARNING: ThreadSanitizer: data race (pid=1571)
Write of size 8 at 0x0000039655a8 by thread T13 (mutexes: write M1129):
#0 os_thread_exit(void*) /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/os/os0thread.cc:210:17 (mysqld+0x0000018a7cc1)
#1 trx_rollback_or_clean_all_recovered /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/trx/trx0roll.cc:880:2 (mysqld+0x0000019d37bd)
Previous read of size 8 at 0x0000039655a8 by main thread:
#0 os_thread_create_func(void* (*)(void*), void*, unsigned long*) /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/os/os0thread.cc:183:2 (mysqld+0x0000018a7b9f)
#1 recv_recovery_rollback_active() /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/log/log0recv.cc:4224:3 (mysqld+0x0000018855e1)
#2 innobase_start_or_create_for_mysql() /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/srv/srv0start.cc:2350:3 (mysqld+0x0000019954db)
#3 innobase_init(void*) /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/handler/ha_innodb.cc:3714:8 (mysqld+0x0000017eb179)
#4 ha_initialize_handlerton(st_plugin_int*) /home/rfp/projects/mysql.tsan/mysql-server/sql/handler.cc:837:31 (mysqld+0x000000edb836)
#5 plugin_initialize(st_plugin_int*) /home/rfp/projects/mysql.tsan/mysql-server/sql/sql_plugin.cc:1178:9 (mysqld+0x0000014c320e)
#6 plugin_init(int*, char**, int) /home/rfp/projects/mysql.tsan/mysql-server/sql/sql_plugin.cc:1435:11 (mysqld+0x0000014c230f)
#7 init_server_components() /home/rfp/projects/mysql.tsan/mysql-server/sql/mysqld.cc:3959:7 (mysqld+0x000000e4e8cd)
#8 mysqld_main(int, char**) /home/rfp/projects/mysql.tsan/mysql-server/sql/mysqld.cc:4586:7 (mysqld+0x000000e4c90e)
#9 main /home/rfp/projects/mysql.tsan/mysql-server/sql/main.cc:25:10 (mysqld+0x000000e4776e)
Location is global 'os_thread_count' of size 8 at 0x0000039655a8 (mysqld+0x0000039655a8)
Mutex M1129 (0x000003965520) created at:
#0 pthread_mutex_init /home/rfp/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:1063 (mysqld+0x000000dcf175)
#1 OSMutex::init() /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/include/sync0types.h:418:14 (mysqld+0x0000018571ac)
#2 OSTrackMutex<GenericPolicy>::init(latch_id_t, char const*, unsigned int) /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/include/ib0mutex.h:67:3 (mysqld+0x0000018570e7)
#3 PolicyMutex<OSTrackMutex<GenericPolicy> >::init(latch_id_t, char const*, unsigned int) /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/include/ib0mutex.h:1054:3 (mysqld+0x000001856fb2)
#4 void mutex_init<PolicyMutex<OSTrackMutex<GenericPolicy> > >(PolicyMutex<OSTrackMutex<GenericPolicy> >*, latch_id_t, char const*, unsigned int) /home/rfp/projects/mysql.tsan/mysql-server/storage/in\
nobase/include/ut0mutex.h:209:2 (mysqld+0x0000018556d8)
#5 os_thread_init() /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/os/os0thread.cc:299:2 (mysqld+0x0000018a7e29)
#6 srv_general_init() /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/srv/srv0srv.cc:1067:2 (mysqld+0x00000198b45b)
#7 srv_boot() /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/srv/srv0srv.cc:1105:2 (mysqld+0x00000198b496)
#8 innobase_start_or_create_for_mysql() /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/srv/srv0start.cc:1674:2 (mysqld+0x000001993109)
#9 innobase_init(void*) /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/handler/ha_innodb.cc:3714:8 (mysqld+0x0000017eb179)
#10 ha_initialize_handlerton(st_plugin_int*) /home/rfp/projects/mysql.tsan/mysql-server/sql/handler.cc:837:31 (mysqld+0x000000edb836)
#11 plugin_initialize(st_plugin_int*) /home/rfp/projects/mysql.tsan/mysql-server/sql/sql_plugin.cc:1178:9 (mysqld+0x0000014c320e)
#12 plugin_init(int*, char**, int) /home/rfp/projects/mysql.tsan/mysql-server/sql/sql_plugin.cc:1435:11 (mysqld+0x0000014c230f)
#13 init_server_components() /home/rfp/projects/mysql.tsan/mysql-server/sql/mysqld.cc:3959:7 (mysqld+0x000000e4e8cd)
#14 mysqld_main(int, char**) /home/rfp/projects/mysql.tsan/mysql-server/sql/mysqld.cc:4586:7 (mysqld+0x000000e4c90e)
#15 main /home/rfp/projects/mysql.tsan/mysql-server/sql/main.cc:25:10 (mysqld+0x000000e4776e)
Thread T13 (tid=1588, running) created by main thread at:
#0 pthread_create /home/rfp/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:848 (mysqld+0x000000de5ea3)
#1 os_thread_create_func(void* (*)(void*), void*, unsigned long*) /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/os/os0thread.cc:173:12 (mysqld+0x0000018a7b42)
#2 recv_recovery_rollback_active() /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/log/log0recv.cc:4224:3 (mysqld+0x0000018855e1)
#3 innobase_start_or_create_for_mysql() /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/srv/srv0start.cc:2350:3 (mysqld+0x0000019954db)
#4 innobase_init(void*) /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/handler/ha_innodb.cc:3714:8 (mysqld+0x0000017eb179)
#5 ha_initialize_handlerton(st_plugin_int*) /home/rfp/projects/mysql.tsan/mysql-server/sql/handler.cc:837:31 (mysqld+0x000000edb836)
#6 plugin_initialize(st_plugin_int*) /home/rfp/projects/mysql.tsan/mysql-server/sql/sql_plugin.cc:1178:9 (mysqld+0x0000014c320e)
#7 plugin_init(int*, char**, int) /home/rfp/projects/mysql.tsan/mysql-server/sql/sql_plugin.cc:1435:11 (mysqld+0x0000014c230f)
#8 init_server_components() /home/rfp/projects/mysql.tsan/mysql-server/sql/mysqld.cc:3959:7 (mysqld+0x000000e4e8cd)
#9 mysqld_main(int, char**) /home/rfp/projects/mysql.tsan/mysql-server/sql/mysqld.cc:4586:7 (mysqld+0x000000e4c90e)
#10 main /home/rfp/projects/mysql.tsan/mysql-server/sql/main.cc:25:10 (mysqld+0x000000e4776e)
SUMMARY: ThreadSanitizer: data race /home/rfp/projects/mysql.tsan/mysql-server/storage/innobase/os/os0thread.cc:210:17 in os_thread_exit(void*)
[5 Jan 2016 14:41]
Richard Prohaska
Perhaps instead of protecting the os_thread_count with a mutex, one could implement os_thread_count with a C++ atomic variable.
