This is an automated email from the ASF dual-hosted git repository. adar pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/kudu.git
commit 8ef7e18f3528000f656cb9a467a6787e6ed080c9 Author: Adar Dembo <[email protected]> AuthorDate: Wed Sep 18 11:46:04 2019 -0700 trace-test: fix kernel stack watchdog data race The KernelStackWatchdog thread runs independently of the test thread, and by calling IsBeingDebugged, it winds up creating a trace event of its own. This is problematic given that trace-test sets up event callbacks to write to test fixture members, which go out of scope in between tests. The only solution I could find was to avoid starting the KernelStackWatchdog in trace-test by passing Thread::NO_STACK_WATCHDOG into thread creation. I also had to do this when creating the trace sampling thread, but given that's not on by default, I don't think it's so bad that we lose watchdog monitoring for it. To test, I ran trace-test under gdb and set a breakpoint in KernelStackWatchdog::RunThread. With the fix, gdb no longer hit that breakpoint. WARNING: ThreadSanitizer: data race (pid=4111) Read of size 8 at 0x0000015ba5c8 by thread T2: #0 kudu::TraceEventCallbackTest::Callback(long, char, unsigned char const*, char const*, unsigned long, int, char const* const*, unsigned char const*, unsigned long const*, unsigned char) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/trace-test.cc:463:5 (trace-test+0x4f107f) #1 kudu::debug::TraceLog::AddTraceEventWithThreadIdAndTimestamp(char, unsigned char const*, char const*, unsigned long, int, long const&, int, char const**, unsigned char const*, unsigned long const*, scoped_refptr<kudu::debug::ConvertableToTraceFormat> const*, unsigned char) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/debug/trace_event_impl.cc:1911:7 (libkudu_util.so+0x1208b3) #2 kudu::debug::TraceEventHandle trace_event_internal::AddTraceEventWithThreadIdAndTimestamp<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(char, unsigned char const*, char const*, unsigned long, int, long const&, unsigned char, char const*, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/debug/trace_event.h:1314:10 (libkudu_util.so+0x146f58) #3 kudu::debug::TraceEventHandle trace_event_internal::AddTraceEvent<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(char, unsigned char const*, char const*, unsigned long, unsigned char, char const*, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/debug/trace_event.h:1330:10 (libkudu_util.so+0x146bef) #4 kudu::(anonymous namespace)::PosixEnv::NewSequentialFile(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unique_ptr<kudu::SequentialFile, std::__1::default_delete<kudu::SequentialFile> >*) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/env_posix.cc:1077:5 (libkudu_util.so+0x140905) #5 kudu::ReadFileToString(kudu::Env*, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, kudu::faststring*) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/env.cc:73:19 (libkudu_util.so+0x140054) #6 kudu::IsBeingDebugged() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/os-util.cc:154:14 (libkudu_util.so+0x1c9687) #7 kudu::KernelStackWatchdog::RunThread() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/kernel_stack_watchdog.cc:141:9 (libkudu_util.so+0x17de59) #8 boost::_mfi::mf0<void, kudu::KernelStackWatchdog>::operator()(kudu::KernelStackWatchdog*) const /home/jenkins-slave/workspace/kudu-master/2/thirdparty/installed/tsan/include/boost/bind/mem_fn_template.hpp:49:29 (libkudu_util.so+0x17fd89) #9 void boost::_bi::list1<boost::_bi::value<kudu::KernelStackWatchdog*> >::operator()<boost::_mfi::mf0<void, kudu::KernelStackWatchdog>, boost::_bi::list0>(boost::_bi::type<void>, boost::_mfi::mf0<void, kudu::KernelStackWatchdog>&, boost::_bi::list0&, int) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/installed/tsan/include/boost/bind/bind.hpp:259:9 (libkudu_util.so+0x17fcda) #10 boost::_bi::bind_t<void, boost::_mfi::mf0<void, kudu::KernelStackWatchdog>, boost::_bi::list1<boost::_bi::value<kudu::KernelStackWatchdog*> > >::operator()() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/installed/tsan/include/boost/bind/bind.hpp:1222:16 (libkudu_util.so+0x17fc63) #11 boost::detail::function::void_function_obj_invoker0<boost::_bi::bind_t<void, boost::_mfi::mf0<void, kudu::KernelStackWatchdog>, boost::_bi::list1<boost::_bi::value<kudu::KernelStackWatchdog*> > >, void>::invoke(boost::detail::function::function_buffer&) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/installed/tsan/include/boost/function/function_template.hpp:159:11 (libkudu_util.so+0x17fa59) #12 boost::function0<void>::operator()() const /home/jenkins-slave/workspace/kudu-master/2/thirdparty/installed/tsan/include/boost/function/function_template.hpp:770:14 (libkudu_util.so+0x1f1dd1) #13 kudu::Thread::SuperviseThread(void*) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/thread.cc:657:3 (libkudu_util.so+0x1ef3f4) Previous write of size 8 at 0x0000015ba5c8 by main thread: #0 kudu::TraceEventCallbackTest::SetUp() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/trace-test.cc:340:16 (trace-test+0x4f3a17) #1 void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2402:10 (libgmock.so+0x552ef) #2 void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2438 (libgmock.so+0x552ef) #3 testing::Test::Run() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2470:3 (libgmock.so+0x343c1) #4 testing::TestInfo::Run() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2656:11 (libgmock.so+0x3574c) #5 testing::TestCase::Run() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2774:28 (libgmock.so+0x36226) #6 testing::internal::UnitTestImpl::RunAllTests() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:4649:43 (libgmock.so+0x425fa) #7 bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2402:10 (libgmock.so+0x5625f) #8 bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2438 (libgmock.so+0x5625f) #9 testing::UnitTest::Run() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:4257:10 (libgmock.so+0x41ee2) #10 RUN_ALL_TESTS() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/installed/tsan/include/gtest/gtest.h:2233:46 (libkudu_test_main.so+0x351b) #11 main /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/test_main.cc:106:13 (libkudu_test_main.so+0x2cc6) Location is global 'kudu::TraceEventCallbackTest::s_instance' of size 8 at 0x0000015ba5c8 (trace-test+0x0000015ba5c8) Thread T2 'kernel-watcher-' (tid=4116, running) created by main thread at: #0 pthread_create /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/llvm-6.0.0.src/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:992 (trace-test+0x453c86) #1 kudu::Thread::StartThread(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, boost::function<void ()> const&, unsigned long, scoped_refptr<kudu::Thread>*) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/thread.cc:601:15 (libkudu_util.so+0x1eebdb) #2 kudu::Status kudu::Thread::CreateWithFlags<boost::_bi::bind_t<void, boost::_mfi::mf0<void, kudu::KernelStackWatchdog>, boost::_bi::list1<boost::_bi::value<kudu::KernelStackWatchdog*> > > >(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, boost::_bi::bind_t<void, boost::_mfi::mf0<void, kudu::KernelStackWatchdog>, boost::_bi::list1<boost::_bi: [...] #3 kudu::KernelStackWatchdog::KernelStackWatchdog() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/kernel_stack_watchdog.cc:71:3 (libkudu_util.so+0x17dc36) #4 Singleton<kudu::KernelStackWatchdog>::CreateInstance() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/gutil/singleton.h:124:18 (libkudu_util.so+0x17f664) #5 Singleton<kudu::KernelStackWatchdog>::Init() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/gutil/singleton.h:117:17 (libkudu_util.so+0x17f604) #6 GoogleOnceInternalInit(int*, void (*)(), void (*)(void*), void*) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/gutil/once.cc:43:7 (libgutil.so+0x2d7b3) #7 GoogleOnceInit(GoogleOnceType*, void (*)()) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/gutil/once.h:53:5 (libkudu_util.so+0x113e4d) #8 Singleton<kudu::KernelStackWatchdog>::get() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/gutil/singleton.h:79:5 (libkudu_util.so+0x17f5b1) #9 kudu::KernelStackWatchdog::GetInstance() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/kernel_stack_watchdog.h:87:12 (libkudu_util.so+0x17f423) #10 kudu::KernelStackWatchdog::CreateAndRegisterTLS() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/kernel_stack_watchdog.cc:219:3 (libkudu_util.so+0x17ed17) #11 kudu::KernelStackWatchdog::GetTLS() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/kernel_stack_watchdog.h:170:7 (libkudu_util.so+0x1f2901) #12 kudu::ScopedWatchKernelStack::ScopedWatchKernelStack(char const*, int) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/kernel_stack_watchdog.h:248:13 (libkudu_util.so+0x1f1b70) #13 kudu::Thread::StartThread(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, boost::function<void ()> const&, unsigned long, scoped_refptr<kudu::Thread>*) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/thread.cc:600:5 (libkudu_util.so+0x1eebaf) #14 kudu::Status kudu::Thread::Create<void (*)(int, int), int, int>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, void (* const&)(int, int), int const&, int const&, scoped_refptr<kudu::Thread>*) /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/thread.h:170:12 (trace-test+0x4f03ef) #15 kudu::TraceTest_TestChromeTracing_Test::TestBody() /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/trace-test.cc:172:5 (trace-test+0x4e750b) #16 void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2402:10 (libgmock.so+0x552ef) #17 void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2438 (libgmock.so+0x552ef) #18 testing::Test::Run() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2474:5 (libgmock.so+0x344b8) #19 testing::TestInfo::Run() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2656:11 (libgmock.so+0x3574c) #20 testing::TestCase::Run() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2774:28 (libgmock.so+0x36226) #21 testing::internal::UnitTestImpl::RunAllTests() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:4649:43 (libgmock.so+0x425fa) #22 bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2402:10 (libgmock.so+0x5625f) #23 bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:2438 (libgmock.so+0x5625f) #24 testing::UnitTest::Run() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/src/googletest-release-1.8.0/googletest/src/gtest.cc:4257:10 (libgmock.so+0x41ee2) #25 RUN_ALL_TESTS() /home/jenkins-slave/workspace/kudu-master/2/thirdparty/installed/tsan/include/gtest/gtest.h:2233:46 (libkudu_test_main.so+0x351b) #26 main /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/test_main.cc:106:13 (libkudu_test_main.so+0x2cc6) Change-Id: I5dc974be22ff101dcb8091be1fe692ab61376bc2 SUMMARY: ThreadSanitizer: data race /home/jenkins-slave/workspace/kudu-master/2/src/kudu/util/trace-test.cc:463:5 in kudu::TraceEventCallbackTest::Callback(long, char, unsigned char const*, char const*, unsigned long, int, char const* const*, unsigned char const*, unsigned long const*, unsigned char) Reviewed-on: http://gerrit.cloudera.org:8080/14256 Reviewed-by: Alexey Serbin <[email protected]> Tested-by: Adar Dembo <[email protected]> --- src/kudu/util/debug/trace_event_impl.cc | 11 ++++++----- src/kudu/util/trace-test.cc | 25 +++++++++++++++++-------- 2 files changed, 23 insertions(+), 13 deletions(-) diff --git a/src/kudu/util/debug/trace_event_impl.cc b/src/kudu/util/debug/trace_event_impl.cc index 9b1d919..0f1da6e 100644 --- a/src/kudu/util/debug/trace_event_impl.cc +++ b/src/kudu/util/debug/trace_event_impl.cc @@ -12,6 +12,7 @@ #include <cinttypes> #include <cstdlib> #include <cstring> +#include <functional> #include <list> #include <sstream> #include <type_traits> @@ -36,7 +37,6 @@ #include "kudu/gutil/strings/util.h" #include "kudu/gutil/sysinfo.h" #include "kudu/gutil/walltime.h" - #include "kudu/util/atomic.h" #include "kudu/util/debug/trace_event.h" #include "kudu/util/debug/trace_event_synthetic_delay.h" @@ -906,6 +906,7 @@ void TraceResultBuffer::Collect( // //////////////////////////////////////////////////////////////////////////////// class TraceBucketData; + typedef Callback<void(TraceBucketData*)> TraceSampleCallback; class TraceBucketData { @@ -1357,10 +1358,10 @@ void TraceLog::SetEnabled(const CategoryFilter& category_filter, "bucket2", Bind(&TraceSamplingThread::DefaultSamplingCallback)); - Status s = Thread::Create("tracing", "sampler", - &TraceSamplingThread::ThreadMain, - sampling_thread_.get(), - &sampling_thread_handle_); + Status s = Thread::CreateWithFlags( + "tracing", "sampler", + std::bind(&TraceSamplingThread::ThreadMain,sampling_thread_.get()), + Thread::NO_STACK_WATCHDOG, &sampling_thread_handle_); if (!s.ok()) { LOG(DFATAL) << "failed to create trace sampling thread: " << s.ToString(); } diff --git a/src/kudu/util/trace-test.cc b/src/kudu/util/trace-test.cc index 9473a54..a1388ee 100644 --- a/src/kudu/util/trace-test.cc +++ b/src/kudu/util/trace-test.cc @@ -15,9 +15,12 @@ // specific language governing permissions and limitations // under the License. +#include "kudu/util/trace.h" + #include <cctype> #include <cstdint> #include <cstring> +#include <functional> #include <map> #include <ostream> #include <string> @@ -47,7 +50,6 @@ #include "kudu/util/test_util.h" #include "kudu/util/thread.h" #include "kudu/util/trace_metrics.h" -#include "kudu/util/trace.h" using kudu::debug::TraceLog; using kudu::debug::TraceResultBuffer; @@ -169,8 +171,10 @@ TEST_F(TraceTest, TestChromeTracing) { Stopwatch s; s.start(); for (int i = 0; i < kNumThreads; i++) { - CHECK_OK(Thread::Create("test", "gen-traces", &GenerateTraceEvents, i, kEventsPerThread, - &threads[i])); + CHECK_OK(Thread::CreateWithFlags( + "test", "gen-traces", + std::bind(GenerateTraceEvents, i, kEventsPerThread), + Thread::NO_STACK_WATCHDOG, &threads[i])); } for (int i = 0; i < kNumThreads; i++) { @@ -203,8 +207,9 @@ TEST_F(TraceTest, TestTraceFromExitedThread) { // Generate 10 trace events in a separate thread. int kNumEvents = 10; scoped_refptr<Thread> t; - CHECK_OK(Thread::Create("test", "gen-traces", &GenerateTraceEvents, 1, kNumEvents, - &t)); + CHECK_OK(Thread::CreateWithFlags( + "test", "gen-traces", std::bind(GenerateTraceEvents, 1, kNumEvents), + Thread::NO_STACK_WATCHDOG, &t)); t->Join(); tl->SetDisabled(); string trace_json = TraceResultBuffer::FlushTraceLogToString(); @@ -231,7 +236,9 @@ TEST_F(TraceTest, TestWideSpan) { TraceLog::RECORD_CONTINUOUSLY); scoped_refptr<Thread> t; - CHECK_OK(Thread::Create("test", "gen-traces", &GenerateWideSpan, &t)); + CHECK_OK(Thread::CreateWithFlags( + "test", "gen-traces", &GenerateWideSpan, + Thread::NO_STACK_WATCHDOG, &t)); t->Join(); tl->SetDisabled(); @@ -277,8 +284,10 @@ TEST_F(TraceTest, TestStartAndStopCollection) { CountDownLatch latch(1); AtomicInt<int64_t> num_events_generated(0); scoped_refptr<Thread> t; - CHECK_OK(Thread::Create("test", "gen-traces", &GenerateTracesUntilLatch, - &num_events_generated, &latch, &t)); + CHECK_OK(Thread::CreateWithFlags( + "test", "gen-traces", + std::bind(GenerateTracesUntilLatch, &num_events_generated, &latch), + Thread::NO_STACK_WATCHDOG, &t)); const int num_flushes = AllowSlowTests() ? 50 : 3; for (int i = 0; i < num_flushes; i++) {
