Bug #80530 innodb monitor_set_tlb variable used before initialized, data race
Submitted: 26 Feb 2016 13:13 Modified: 4 Apr 2016 10:21
Reporter: Richard Prohaska Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7.11 OS:Any
Assigned to: CPU Architecture:Any

[26 Feb 2016 13:13] Richard Prohaska
Description:
The 'monitor_set_tbl' global variable in the InnoDB storage engine is initialized after it is used by background threads that InnoDB creates.  This causes a data race to be reported by the thread sanitizer.  The data race occurs because the 'srv_master_thread' uses a sleep to attempt to coordinate with the main thread that is doing the InnoDB initialization.  Sleep does not guarantee correctness since the threads can be executed according to an arbitrary schedule by the operating system.

The details are:
1. mysql calls the innodb initialization function 'ha_initialize_handlerton'.
2. innodb calls 'innobase_start_or_create_for_mysql' which creates some background threads including the 'srv_master_thread'.
3. 'srv_master_thread' runs into a while loop and sleeps for awhile.
4. suppose that 'srv_master_thread' wakes up before the main thread reaches the code that initializes 'monitor_set_tlb'.  it attempts to increment a monitor variable.  this increment reads 'monitor_set_tbl' before it is initialized.
5. finally, the main thread initializes 'monitor_set_tlb'.

A race detector like the thread sanitizer reports a data race because there is no happens before relationship between the read of monitor_set_tbl in the srv_master_thread and the write of monitor_set_tbl in the main innodb initialization thread.

The thread sanitizer report is:
WARNING: ThreadSanitizer: data race (pid=9811)
  Read of size 8 at 0x0000039a66f8 by thread T16:
    #0 srv_master_thread /home/rfp/projects/mysql.57.tsan/mysql-server/storage/innobase/srv/srv0srv.cc:2356:3 (mysqld+0x0000019ce5e7)

  Previous write of size 8 at 0x0000039a66f8 by main thread:
    [failed to restore the stack]

  As if synchronized via sleep:
    #0 nanosleep /home/rfp/projects/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:381 (mysqld+0x000000e161ea)
    #1 os_thread_sleep(unsigned long) /home/rfp/projects/mysql.57.tsan/mysql-server/storage/innobase/os/os0thread.cc:258:2 (mysqld+0x0000018e7f5c)
    #2 srv_master_sleep() /home/rfp/projects/mysql.57.tsan/mysql-server/storage/innobase/srv/srv0srv.cc:2307:2 (mysqld+0x0000019cea81)
    #3 srv_master_thread /home/rfp/projects/mysql.57.tsan/mysql-server/storage/innobase/srv/srv0srv.cc:2354:3 (mysqld+0x0000019ce5d4)

  Location is global 'monitor_set_tbl' of size 32 at 0x0000039a66e0 (mysqld+0x0000039a66f8)

  Thread T16 (tid=9830, running) created by main thread at:
    #0 pthread_create /home/rfp/projects/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:964 (mysqld+0x000000dee8cb)
    #1 os_thread_create_func(void* (*)(void*), void*, unsigned long*) /home/rfp/projects/mysql.57.tsan/mysql-server/storage/innobase/os/os0thread.cc:173:12 (mysqld+0x0000018e7d42)
    #2 innobase_start_or_create_for_mysql() /home/rfp/projects/mysql.57.tsan/mysql-server/storage/innobase/srv/srv0start.cc:2482:3 (mysqld+0x0000019d560c)
    #3 innobase_init(void*) /home/rfp/projects/mysql.57.tsan/mysql-server/storage/innobase/handler/ha_innodb.cc:3971:8 (mysqld+0x000001828f5f)
    #4 ha_initialize_handlerton(st_plugin_int*) /home/rfp/projects/mysql.57.tsan/mysql-server/sql/handler.cc:837:31 (mysqld+0x000000f0c2f6)
    #5 plugin_initialize(st_plugin_int*) /home/rfp/projects/mysql.57.tsan/mysql-server/sql/sql_plugin.cc:1184:9 (mysqld+0x0000014e573e)
    #6 plugin_init(int*, char**, int) /home/rfp/projects/mysql.57.tsan/mysql-server/sql/sql_plugin.cc:1528:11 (mysqld+0x0000014e4477)
    #7 init_server_components() /home/rfp/projects/mysql.57.tsan/mysql-server/sql/mysqld.cc:3979:7 (mysqld+0x000000e7f1b3)
    #8 mysqld_main(int, char**) /home/rfp/projects/mysql.57.tsan/mysql-server/sql/mysqld.cc:4606:7 (mysqld+0x000000e7d1ee)
    #9 main /home/rfp/projects/mysql.57.tsan/mysql-server/sql/main.cc:25:10 (mysqld+0x000000e7803e)

SUMMARY: ThreadSanitizer: data race /home/rfp/projects/mysql.57.tsan/mysql-server/storage/innobase/srv/srv0srv.cc:2356:3 in srv_master_thread

How to repeat:
Build mysql 5.7 with the thread sanitizer.  Unfortunately, the thread sanitizer is not yet supported.
OR
Run mysqld with helgrind and see if helgrind reports this data race.
OR
Examine the source code.

Suggested fix:
Initialize 'monitor_set_tbl' BEFORE any of the innodb background threads are created in the 'innobase_start_or_create_for_mysql' function.
[4 Apr 2016 10:21] Umesh Shastry
Hello Richard,

Thank you for the report.

Thanks,
Umesh