This is an archive of the discontinued LLVM Phabricator instance.

Fix remaining threading issues in Log.h
ClosedPublic

Authored by labath on Mar 7 2017, 10:06 AM.

Details

Summary

This fixes two threading issues in the logging code. The access to the
mask and options flags had data races when we were trying to
enable/disable logging while another thread was writing to the log.
Since we can log from almost any context, and we want it to be fast, so
I avoided locking primitives and used atomic variables instead. I have
also removed the (unused) setters for the mask and flags to make sure
that the only way to set them is through the enable/disable channel
functions.

I also add tests, which when run under tsan, verify that the use cases
like "doing an LLDB_LOGV while another thread disables logging" are
data-race-free.

Diff Detail

Repository
rL LLVM

Event Timeline

labath created this revision.Mar 7 2017, 10:06 AM
clayborg accepted this revision.Mar 7 2017, 1:33 PM

With my limited std::atomic experience, this seems fine.

This revision is now accepted and ready to land.Mar 7 2017, 1:33 PM
eugene added a subscriber: eugene.Mar 7 2017, 1:39 PM
eugene added inline comments.
include/lldb/Utility/Log.h
152 ↗(On Diff #90875)

Seems like const on return value is not really needed.

163 ↗(On Diff #90875)

Do we actually need atomics here?

It seems like the stream itself is protected by the mutex, and It doesn't seem to affect performance.
Can we use the same (or a different) mutex to protect flags and options?

zturner added inline comments.Mar 7 2017, 1:45 PM
source/Utility/Log.cpp
90–91 ↗(On Diff #90875)

How about

uint32_t old_mask = log.m_mask.fetch_or(flags);
if (old_mask  & flags) {
  ...
}

Also, there is still a race if two people call this function at the same time.

103–104 ↗(On Diff #90875)
uint32_t old_mask = log->m_mask.fetch_and(~flags);
if (!(old_mask & ~flags)) {
  ...
}
116 ↗(On Diff #90875)

Any reason you always use the explicit load(memory_order_acquire) syntax instead of using the default sequentially consistent ordering?

labath added a comment.Mar 8 2017, 2:29 AM
include/lldb/Utility/Log.h
152 ↗(On Diff #90875)

Well... otherwise people could write something like: log.GetOptions().Reset(foo) and expect that it will change underlying log object. This worked before this patch, so this seems like a good idea -- make sure accidental usage like that results in a compiler error rather than silently fail.

163 ↗(On Diff #90875)

The difference is that these variables are accessed even when logging is disabled -- GetLogIfAll fetches the mask to decide whether it should log things. The stream mutex is only taken if logging is enabled and you are actually logging something (also only the read side is taken, so it is contention-free unless someone actually is modifying the stream at the same time).

I don't think doing this with a mutex would drastically hurt our performance, but I'm trying to avoid the case where enabling logging introduces enough thread synchronization than the race condition you were debugging disappears.

source/Utility/Log.cpp
90–91 ↗(On Diff #90875)

That is not the race I was trying to solve here, but it seems making sure that is safe wouldn't be too hard, and it should make this easier to reason about. I'll reuse the stream mutex for this case.

116 ↗(On Diff #90875)

The sequentially consistent ordering is more heavy, particularly on weakly ordered systems, and it's not necessary here - all I need is to make sure the value is read correctly. In fact, I was considering dropping this all the way to memory_order_relaxed.

labath updated this revision to Diff 90994.Mar 8 2017, 3:47 AM

I've repurposed the stream mutex to protect the entirety of enable/disable
operations. To make this flow better, I've also gotten rid of the LogAndChannel
struct and make Channel a member of Log directly (which required moving some
declarations from the cpp file to the header).

I've also updated all atomic operations to use relaxed memory order. For the
operations in the critical section in does not matter. for the fast path in the
logging code it is enough to makee sure that the reads are atomic and once we
get around to actually writing to the log, the read lock on the mutex will make
sure the modifications to m_stream_sp are visible to the logging thread.

zturner accepted this revision.Mar 8 2017, 4:04 PM
zturner added inline comments.
source/Utility/Log.cpp
82 ↗(On Diff #90994)

Might as well use memory_order_relaxed here.

unittests/Utility/LogTest.cpp
16 ↗(On Diff #90994)

Is this included needed?

labath added a comment.Mar 9 2017, 2:04 AM
source/Utility/Log.cpp
82 ↗(On Diff #90994)

Done. I missed that one.

unittests/Utility/LogTest.cpp
16 ↗(On Diff #90994)

Not anymore. I had tried implementing the test with futures, but I couldn't get tsan to work with them properly.

This revision was automatically updated to reflect the committed changes.