Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Annotate LOG_EVERY_N macros as a benign race for TSAN #263

Merged
merged 1 commit into from
Feb 13, 2021

Conversation

kennyyu
Copy link
Contributor

@kennyyu kennyyu commented Nov 4, 2017

Summary:
Issue #80 points out several places in glog where TSAN discovers
false positives. One of these places is in the LOG_EVERY_N macros.
These macros are implemented by maintaining a static unprotected
integer counter, and TSAN will report data races on these counters.

Here is a minimum example to reproduce the data race:

#include <glog/logging.h>
#include <thread>

void logging() {
  for (int i = 0; i < 300; ++i) {
    LOG_EVERY_N(INFO, 2) << "foo";
  }
}

int main() {
  auto t1 = std::thread(logging);
  auto t2 = std::thread(logging);
  t1.join();
  t2.join();
  return 0;
}

And here is the TSAN report:

WARNING: ThreadSanitizer: data race (pid=776850)
  Write of size 4 at 0x558de483f684 by thread T2:
    #0 logging()
    #1 void std::_Bind_simple<void (*())()>::_M_invoke<>(std::_Index_tuple<>)
    #2 std::_Bind_simple<void (*())()>::operator()()
    #3 std::thread::_Impl<std::_Bind_simple<void (*())()> >::_M_run()
    #4 execute_native_thread_routine

  Previous write of size 4 at 0x558de483f684 by thread T1:
    #0 logging()
    #1 void std::_Bind_simple<void (*())()>::_M_invoke<>(std::_Index_tuple<>)
    #2 std::_Bind_simple<void (*())()>::operator()()
    #3 std::thread::_Impl<std::_Bind_simple<void (*())()> >::_M_run()
    #4 execute_native_thread_routine

  Location is global '<null>' at 0x000000000000 (main+0x00000011c684)

  Thread T2 (tid=776857, running) created by main thread at:
    #0 pthread_create
    #1 __gthread_create
    #2 std::thread::_M_start_thread(std::shared_ptr<std::thread::_Impl_base>, void (*)())
    #3 main

  Thread T1 (tid=776856, running) created by main thread at:
    #0 pthread_create
    #1 __gthread_create
    #2 std::thread::_M_start_thread(std::shared_ptr<std::thread::_Impl_base>, void (*)())
    #3 main

SUMMARY: ThreadSanitizer: data race in logging()

To avoid noisy TSAN reports and also avoid adding a performance hit, this
change will mark these counters as benign races so that TSAN will not report
them. This change will only have an effect if we are compiling with TSAN;
there are no changes if we are not building with TSAN.

With this change, the above example no longer reports a data race when built
and run with TSAN.

Summary:
Issue google#80 points out several places in glog where TSAN discovers
false positives. One of these places is in the `LOG_EVERY_N` macros.
These macros are implemented by maintaining a static unprotected
integer counter, and TSAN will report data races on these counters.

Here is a minimum example to reproduce the data race:

```

void logging() {
  for (int i = 0; i < 300; ++i) {
    LOG_EVERY_N(INFO, 2) << "foo";
  }
}

int main() {
  auto t1 = std::thread(logging);
  auto t2 = std::thread(logging);
  t1.join();
  t2.join();
  return 0;
}
```

And here is the TSAN report:

```
WARNING: ThreadSanitizer: data race (pid=776850)
  Write of size 4 at 0x558de483f684 by thread T2:
    #0 logging()
    google#1 void std::_Bind_simple<void (*())()>::_M_invoke<>(std::_Index_tuple<>)
    google#2 std::_Bind_simple<void (*())()>::operator()()
    google#3 std::thread::_Impl<std::_Bind_simple<void (*())()> >::_M_run()
    google#4 execute_native_thread_routine

  Previous write of size 4 at 0x558de483f684 by thread T1:
    #0 logging()
    google#1 void std::_Bind_simple<void (*())()>::_M_invoke<>(std::_Index_tuple<>)
    google#2 std::_Bind_simple<void (*())()>::operator()()
    google#3 std::thread::_Impl<std::_Bind_simple<void (*())()> >::_M_run()
    google#4 execute_native_thread_routine

  Location is global '<null>' at 0x000000000000 (main+0x00000011c684)

  Thread T2 (tid=776857, running) created by main thread at:
    #0 pthread_create
    google#1 __gthread_create
    google#2 std::thread::_M_start_thread(std::shared_ptr<std::thread::_Impl_base>, void (*)())
    google#3 main

  Thread T1 (tid=776856, running) created by main thread at:
    #0 pthread_create
    google#1 __gthread_create
    google#2 std::thread::_M_start_thread(std::shared_ptr<std::thread::_Impl_base>, void (*)())
    google#3 main

SUMMARY: ThreadSanitizer: data race in logging()
```

To avoid noisy TSAN reports and also avoid adding a performance hit, this
change will mark these counters as benign races so that TSAN will not report
them. This change will only have an effect if we are compiling with TSAN;
there are no changes if we are not building with TSAN.

With this change, the above example no longer reports a data race when built
and run with TSAN.
@dfreese
Copy link
Contributor

dfreese commented Sep 2, 2021

I'm seeing error when using this in combination with Abseil, which also defines these:
https://github.com/abseil/abseil-cpp/blob/master/absl/base/dynamic_annotations.h#L213-L215

I haven't had a chance to look into what exactly is the appropriate way to not have them conflict, but the error I'm seeing results from the same file using LOG and absl::Status in the same file under tsan.

bazel-out/k8-fastbuild/bin/external/com_github_google_glog/_virtual_includes/glog/glog/logging.h:1006:17: error: conflicting declaration of C function 'void AnnotateBenignRaceSized(const char*, int, const volatile void*, long int, const char*)'
1006 | extern "C" void AnnotateBenignRaceSized(
| ^~~~~~~~~~~~~~~~~~~~~~~
In file included from external/com_google_absl/absl/base/internal/spinlock.h:37,
from external/com_google_absl/absl/strings/internal/cordz_info.h:24,
from external/com_google_absl/absl/strings/cord.h:86,
from external/com_google_absl/absl/status/internal/status_internal.h:20,
from external/com_google_absl/absl/status/status.h:58,
from ./lib/io/errno.h:6,
from ./lib/io/memory_map.h:9,
from lib/io/memory_map.cc:1:
external/com_google_absl/absl/base/dynamic_annotations.h:213:6: note: previous declaration 'void AnnotateBenignRaceSized(const char*, int, const volatile void*, size_t, const char*)'
213 | void AnnotateBenignRaceSized(const char* file, int line,
| ^~~~~~~~~~~~~~~~~~~~~~~

@sergiud
Copy link
Collaborator

sergiud commented Sep 2, 2021

It looks like extern "C" is the sole difference between both declarations.

@dfreese
Copy link
Contributor

dfreese commented Sep 3, 2021

It looks like extern "C" is the sole difference between both declarations.

Looks like Abseil also has that, just hidden in a preprocessor define. I'm used to seeing the abseil version. I didn't realize it could be applied to a specific function.

@sergiud
Copy link
Collaborator

sergiud commented Sep 3, 2021

I see. The other difference that stands out is the type of the size parameter. Glog uses long

void AnnotateBenignRaceSized(const char *file, int line, const volatile void *mem, long size, const char *description);

whereas absl size_t

void AnnotateBenignRaceSized(const char* file, int line, const volatile void* address, size_t size, const char* description);

@dfreese
Copy link
Contributor

dfreese commented Sep 3, 2021

Ahh, thanks for point that out. Changing it to size_t fixed things for me. I opened #706.

@1e100
Copy link

1e100 commented Dec 22, 2021

I'm seeing effectively the same issue with VLOG(N)

@dfreese
Copy link
Contributor

dfreese commented Dec 22, 2021

I'm seeing effectively the same issue with VLOG(N)

Before or after #706?

@1e100
Copy link

1e100 commented Dec 22, 2021

In 0.5, so before. Good to see someone's addressed it already.

@sergiud
Copy link
Collaborator

sergiud commented Dec 22, 2021

No action necessary, correct @dfreese @1e100?

@1e100
Copy link

1e100 commented Dec 22, 2021

Seems like it. Once 0.6 is released this will be resolved. For now I just implemented an exclusion in my tests.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants