ThreadSanitizer: data race at PlatformWorkerThread::trace_event_unique_atomic35

[hashseed]

I attempted to build Node.js with TSAN, and it seems to have found something. This happens at the build step where we run node to create code cache for internal libs. At this point I'm not sure whether this is an actual issue, or whether Node.js' code is just too clever for TSAN to understand, and we need to put suppressions in place. Thought I'd share.

ninja: Entering directory `out/Release/'
[2058/2065] ACTION //node:generate_code_cache(//build/toolchain/linux:clang_x64)
FAILED: gen/node/node_code_cache.cc 
python ../../tools/generate_code_cache.py node_no_cache ../../node/tools/generate_code_cache.js gen/node/node_code_cache.cc
==================
WARNING: ThreadSanitizer: data race (pid=11586)
  Read of size 8 at 0x55c851a8e190 by thread T3:
    #0 node::(anonymous namespace)::PlatformWorkerThread(void*) node/src/node_platform.cc:34:3 (node_no_cache+0x17cc134)

  Previous write of size 8 at 0x55c851a8e190 by thread T2:
    #0 node::(anonymous namespace)::PlatformWorkerThread(void*) node/src/node_platform.cc:34:3 (node_no_cache+0x17cc16f)

  Location is global 'node::(anonymous namespace)::PlatformWorkerThread(void*)::trace_event_unique_atomic35' of size 8 at 0x55c851a8e190 (node_no_cache+0x000003890190)

  Thread T3 (tid=11590, running) created by main thread at:
    #0 pthread_create /b/swarming/w/ir/kitchen-workdir/src/third_party/llvm/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:974:3 (node_no_cache+0x1630e15)
    #1 uv_thread_create node/deps/uv/src/unix/thread.c:215:9 (node_no_cache+0x2815f56)
    #2 node::WorkerThreadsTaskRunner::WorkerThreadsTaskRunner(int) node/src/node_platform.cc:186:9 (node_no_cache+0x17cbe00)
    #3 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/ext/new_allocator.h:136:23 (node_no_cache+0x17ce7ad)
    #4 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/alloc_traits.h:475 (node_no_cache+0x17ce7ad)
    #5 _Sp_counted_ptr_inplace<int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:549 (node_no_cache+0x17ce7ad)
    #6 __shared_count<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:662 (node_no_cache+0x17ce7ad)
    #7 __shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:1327 (node_no_cache+0x17ce7ad)
    #8 shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:360 (node_no_cache+0x17ce7ad)
    #9 allocate_shared<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:706 (node_no_cache+0x17ce7ad)
    #10 make_shared<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:722 (node_no_cache+0x17ce7ad)
    #11 node::NodePlatform::NodePlatform(int, node::tracing::TracingController*) node/src/node_platform.cc:295 (node_no_cache+0x17ce7ad)
    #12 node::V8Platform::Initialize(int) node/src/node_v8_platform-inl.h:90:21 (node_no_cache+0x16a022d)
    #13 node::InitializeV8Platform(int) node/src/api/environment.cc:177:28 (node_no_cache+0x16a00d2)
    #14 node::Start(int, char**) node/src/node.cc:919:3 (node_no_cache+0x1704c85)
    #15 main node/src/node_main.cc:126:10 (node_no_cache+0x169c7d8)

  Thread T2 (tid=11589, running) created by main thread at:
    #0 pthread_create /b/swarming/w/ir/kitchen-workdir/src/third_party/llvm/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:974:3 (node_no_cache+0x1630e15)
    #1 uv_thread_create node/deps/uv/src/unix/thread.c:215:9 (node_no_cache+0x2815f56)
    #2 node::WorkerThreadsTaskRunner::WorkerThreadsTaskRunner(int) node/src/node_platform.cc:186:9 (node_no_cache+0x17cbe00)
    #3 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/ext/new_allocator.h:136:23 (node_no_cache+0x17ce7ad)
    #4 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/alloc_traits.h:475 (node_no_cache+0x17ce7ad)
    #5 _Sp_counted_ptr_inplace<int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:549 (node_no_cache+0x17ce7ad)
    #6 __shared_count<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:662 (node_no_cache+0x17ce7ad)
    #7 __shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:1327 (node_no_cache+0x17ce7ad)
    #8 shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:360 (node_no_cache+0x17ce7ad)
    #9 allocate_shared<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:706 (node_no_cache+0x17ce7ad)
    #10 make_shared<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:722 (node_no_cache+0x17ce7ad)
    #11 node::NodePlatform::NodePlatform(int, node::tracing::TracingController*) node/src/node_platform.cc:295 (node_no_cache+0x17ce7ad)
    #12 node::V8Platform::Initialize(int) node/src/node_v8_platform-inl.h:90:21 (node_no_cache+0x16a022d)
    #13 node::InitializeV8Platform(int) node/src/api/environment.cc:177:28 (node_no_cache+0x16a00d2)
    #14 node::Start(int, char**) node/src/node.cc:919:3 (node_no_cache+0x1704c85)
    #15 main node/src/node_main.cc:126:10 (node_no_cache+0x169c7d8)

SUMMARY: ThreadSanitizer: data race node/src/node_platform.cc:34:3 in node::(anonymous namespace)::PlatformWorkerThread(void*)
==================
==================
WARNING: ThreadSanitizer: data race (pid=11586)
  Write of size 8 at 0x7ba000000100 by thread T1:
    #0 close /b/swarming/w/ir/kitchen-workdir/src/third_party/llvm/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:1677:3 (node_no_cache+0x1635c49)
    #1 uv__close_nocheckstdio node/deps/uv/src/unix/core.c:527:8 (node_no_cache+0x280319e)
    #2 uv__close node/deps/uv/src/unix/core.c:544 (node_no_cache+0x280319e)
    #3 uv__async_stop node/deps/uv/src/unix/async.c:224:3 (node_no_cache+0x28021d3)
    #4 uv__loop_close node/deps/uv/src/unix/loop.c:149:3 (node_no_cache+0x280d5aa)
    #5 uv_loop_close node/deps/uv/src/uv-common.c:669:3 (node_no_cache+0x28015b8)
    #6 node::CheckedUvLoopClose(uv_loop_s*) node/src/debug_utils.cc:284:7 (node_no_cache+0x16c733a)
    #7 node::WorkerThreadsTaskRunner::DelayedTaskScheduler::Run() node/src/node_platform.cc:91:5 (node_no_cache+0x17d0885)
    #8 operator() node/src/node_platform.cc:59:49 (node_no_cache+0x17d06d9)
    #9 node::WorkerThreadsTaskRunner::DelayedTaskScheduler::Start()::'lambda'(void*)::__invoke(void*) node/src/node_platform.cc:58 (node_no_cache+0x17d06d9)

  Previous read of size 8 at 0x7ba000000100 by main thread:
    #0 write /b/swarming/w/ir/kitchen-workdir/src/third_party/llvm/compiler-rt/lib/tsan/../sanitizer_common/sanitizer_common_interceptors.inc:1095:3 (node_no_cache+0x163c4b3)
    #1 uv__async_send node/deps/uv/src/unix/async.c:143:9 (node_no_cache+0x2801f3d)
    #2 uv_async_send node/deps/uv/src/unix/async.c:65 (node_no_cache+0x2801f3d)
    #3 Stop node/src/node_platform.cc:77:5 (node_no_cache+0x17cc845)
    #4 node::WorkerThreadsTaskRunner::Shutdown() node/src/node_platform.cc:215 (node_no_cache+0x17cc845)
    #5 node::NodePlatform::Shutdown() node/src/node_platform.cc:321:31 (node_no_cache+0x17cef5e)
    #6 Dispose node/src/node_v8_platform-inl.h:96:16 (node_no_cache+0x1704d37)
    #7 node::Start(int, char**) node/src/node.cc:934 (node_no_cache+0x1704d37)
    #8 main node/src/node_main.cc:126:10 (node_no_cache+0x169c7d8)

  Location is file descriptor 16 created by main thread at:
    [failed to restore the stack]

  Thread T1 (tid=11588, running) created by main thread at:
    #0 pthread_create /b/swarming/w/ir/kitchen-workdir/src/third_party/llvm/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:974:3 (node_no_cache+0x1630e15)
    #1 uv_thread_create node/deps/uv/src/unix/thread.c:215:9 (node_no_cache+0x2815f56)
    #2 Start node/src/node_platform.cc:63:5 (node_no_cache+0x17cbcc1)
    #3 node::WorkerThreadsTaskRunner::WorkerThreadsTaskRunner(int) node/src/node_platform.cc:178 (node_no_cache+0x17cbcc1)
    #4 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/ext/new_allocator.h:136:23 (node_no_cache+0x17ce7ad)
    #5 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/alloc_traits.h:475 (node_no_cache+0x17ce7ad)
    #6 _Sp_counted_ptr_inplace<int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:549 (node_no_cache+0x17ce7ad)
    #7 __shared_count<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:662 (node_no_cache+0x17ce7ad)
    #8 __shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:1327 (node_no_cache+0x17ce7ad)
    #9 shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:360 (node_no_cache+0x17ce7ad)
    #10 allocate_shared<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:706 (node_no_cache+0x17ce7ad)
    #11 make_shared<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:722 (node_no_cache+0x17ce7ad)
    #12 node::NodePlatform::NodePlatform(int, node::tracing::TracingController*) node/src/node_platform.cc:295 (node_no_cache+0x17ce7ad)
    #13 node::V8Platform::Initialize(int) node/src/node_v8_platform-inl.h:90:21 (node_no_cache+0x16a022d)
    #14 node::InitializeV8Platform(int) node/src/api/environment.cc:177:28 (node_no_cache+0x16a00d2)
    #15 node::Start(int, char**) node/src/node.cc:919:3 (node_no_cache+0x1704c85)
    #16 main node/src/node_main.cc:126:10 (node_no_cache+0x169c7d8)

SUMMARY: ThreadSanitizer: data race node/deps/uv/src/unix/core.c:527:8 in uv__close_nocheckstdio
==================
==================
WARNING: ThreadSanitizer: data race (pid=11586)
  Write of size 4 at 0x7b6800000900 by thread T1:
    #0 uv__async_stop node/deps/uv/src/unix/async.c:225:29 (node_no_cache+0x28021db)
    #1 uv__loop_close node/deps/uv/src/unix/loop.c:149:3 (node_no_cache+0x280d5aa)
    #2 uv_loop_close node/deps/uv/src/uv-common.c:669:3 (node_no_cache+0x28015b8)
    #3 node::CheckedUvLoopClose(uv_loop_s*) node/src/debug_utils.cc:284:7 (node_no_cache+0x16c733a)
    #4 node::WorkerThreadsTaskRunner::DelayedTaskScheduler::Run() node/src/node_platform.cc:91:5 (node_no_cache+0x17d0885)
    #5 operator() node/src/node_platform.cc:59:49 (node_no_cache+0x17d06d9)
    #6 node::WorkerThreadsTaskRunner::DelayedTaskScheduler::Start()::'lambda'(void*)::__invoke(void*) node/src/node_platform.cc:58 (node_no_cache+0x17d06d9)

  Previous read of size 4 at 0x7b6800000900 by main thread:
    #0 uv__async_send node/deps/uv/src/unix/async.c:138:33 (node_no_cache+0x2801f14)
    #1 uv_async_send node/deps/uv/src/unix/async.c:65 (node_no_cache+0x2801f14)
    #2 Stop node/src/node_platform.cc:77:5 (node_no_cache+0x17cc845)
    #3 node::WorkerThreadsTaskRunner::Shutdown() node/src/node_platform.cc:215 (node_no_cache+0x17cc845)
    #4 node::NodePlatform::Shutdown() node/src/node_platform.cc:321:31 (node_no_cache+0x17cef5e)
    #5 Dispose node/src/node_v8_platform-inl.h:96:16 (node_no_cache+0x1704d37)
    #6 node::Start(int, char**) node/src/node.cc:934 (node_no_cache+0x1704d37)
    #7 main node/src/node_main.cc:126:10 (node_no_cache+0x169c7d8)

  Location is heap block of size 1296 at 0x7b6800000600 allocated by main thread:
    #0 operator new(unsigned long) /b/swarming/w/ir/kitchen-workdir/src/third_party/llvm/compiler-rt/lib/tsan/rtl/tsan_new_delete.cc:64:3 (node_no_cache+0x169b9bd)
    #1 node::WorkerThreadsTaskRunner::WorkerThreadsTaskRunner(int) node/src/node_platform.cc:177:7 (node_no_cache+0x17cbade)
    #2 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/ext/new_allocator.h:136:23 (node_no_cache+0x17ce7ad)
    #3 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/alloc_traits.h:475 (node_no_cache+0x17ce7ad)
    #4 _Sp_counted_ptr_inplace<int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:549 (node_no_cache+0x17ce7ad)
    #5 __shared_count<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:662 (node_no_cache+0x17ce7ad)
    #6 __shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:1327 (node_no_cache+0x17ce7ad)
    #7 shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:360 (node_no_cache+0x17ce7ad)
    #8 allocate_shared<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:706 (node_no_cache+0x17ce7ad)
    #9 make_shared<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:722 (node_no_cache+0x17ce7ad)
    #10 node::NodePlatform::NodePlatform(int, node::tracing::TracingController*) node/src/node_platform.cc:295 (node_no_cache+0x17ce7ad)
    #11 node::V8Platform::Initialize(int) node/src/node_v8_platform-inl.h:90:21 (node_no_cache+0x16a022d)
    #12 node::InitializeV8Platform(int) node/src/api/environment.cc:177:28 (node_no_cache+0x16a00d2)
    #13 node::Start(int, char**) node/src/node.cc:919:3 (node_no_cache+0x1704c85)
    #14 main node/src/node_main.cc:126:10 (node_no_cache+0x169c7d8)

  Thread T1 (tid=11588, running) created by main thread at:
    #0 pthread_create /b/swarming/w/ir/kitchen-workdir/src/third_party/llvm/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:974:3 (node_no_cache+0x1630e15)
    #1 uv_thread_create node/deps/uv/src/unix/thread.c:215:9 (node_no_cache+0x2815f56)
    #2 Start node/src/node_platform.cc:63:5 (node_no_cache+0x17cbcc1)
    #3 node::WorkerThreadsTaskRunner::WorkerThreadsTaskRunner(int) node/src/node_platform.cc:178 (node_no_cache+0x17cbcc1)
    #4 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/ext/new_allocator.h:136:23 (node_no_cache+0x17ce7ad)
    #5 construct<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/alloc_traits.h:475 (node_no_cache+0x17ce7ad)
    #6 _Sp_counted_ptr_inplace<int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:549 (node_no_cache+0x17ce7ad)
    #7 __shared_count<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:662 (node_no_cache+0x17ce7ad)
    #8 __shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr_base.h:1327 (node_no_cache+0x17ce7ad)
    #9 shared_ptr<std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:360 (node_no_cache+0x17ce7ad)
    #10 allocate_shared<node::WorkerThreadsTaskRunner, std::allocator<node::WorkerThreadsTaskRunner>, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:706 (node_no_cache+0x17ce7ad)
    #11 make_shared<node::WorkerThreadsTaskRunner, int &> ../../include/c++/8.0.1/bits/shared_ptr.h:722 (node_no_cache+0x17ce7ad)
    #12 node::NodePlatform::NodePlatform(int, node::tracing::TracingController*) node/src/node_platform.cc:295 (node_no_cache+0x17ce7ad)
    #13 node::V8Platform::Initialize(int) node/src/node_v8_platform-inl.h:90:21 (node_no_cache+0x16a022d)
    #14 node::InitializeV8Platform(int) node/src/api/environment.cc:177:28 (node_no_cache+0x16a00d2)
    #15 node::Start(int, char**) node/src/node.cc:919:3 (node_no_cache+0x1704c85)
    #16 main node/src/node_main.cc:126:10 (node_no_cache+0x169c7d8)

SUMMARY: ThreadSanitizer: data race node/deps/uv/src/unix/async.c:225:29 in uv__async_stop
==================
ThreadSanitizer: reported 3 warnings
Traceback (most recent call last):
  File "../../tools/generate_code_cache.py", line 15, in <module>
    main(sys.argv[1], sys.argv[2], sys.argv[3])
  File "../../tools/generate_code_cache.py", line 12, in main
    [node_exe, "--expose-internals", script, output])
  File "/usr/lib/python2.7/subprocess.py", line 219, in check_output
    raise CalledProcessError(retcode, cmd, output=output)
subprocess.CalledProcessError: Command '['/usr/local/google/home/yangguo/node-ci/node-ci/out/Release/node_no_cache', '--expose-internals', '../../node/tools/generate_code_cache.js', 'gen/node/node_code_cache.cc']' returned non-zero exit status 66

Steps to reproduce:
Unfortunately the TSAN build is only available to GN.

get depot_tools

mkdir node-ci
cd node-ci
fetch node-ci
cd node-ci
gclient sync
tools/gn-gen --tsan out/Release
ninja -C out/Release node

[addaleax]

valgrind has been complaining about these too – I couldn’t find anything while looking into it, and it seemed like valgrind just didn’t get that atomics were being used here and that that was okay.

But maybe somebody from @nodejs/trace-events (@ofrobots ?) could verify that?

[hashseed]

Note that there are several issues TSan is complaining about. Two of which are in libuv.

[addaleax]

I couldn’t find anything while looking into it, and it seemed like valgrind just didn’t get that atomics were being used here and that that was okay.

I looked into it a bit more and it turns out that we’re not actually using atomics, we just gave everything a name with atomic in it. :|

node/src/tracing/trace_event.h

Lines 130 to 133 in e74019f

	// Defines atomic operations used internally by the tracing system.
	#define TRACE_EVENT_API_ATOMIC_WORD intptr_t
	#define TRACE_EVENT_API_ATOMIC_LOAD(var) (var)
	#define TRACE_EVENT_API_ATOMIC_STORE(var, value) (var) = (value)

[addaleax]

And the libuv issues seem to also be something I’ve seen before (with helgrind), namely that thread sanity checkers don’t see the causal relation between uv_async_send and the uv_async_t callback, because that’s hidden through reading from/writing to file descriptors rather than classic synchronization utilities.

[hashseed]

I'll retry after blacklisting the libuv issues :)

[jasnell]

Ping @hashseed @addaleax ... is this still an issue?

[Mesteery]

ping @addaleax