Ensure Origin Thread Affinity for BlameContext

Ensure Origin Thread Affinity for BlameContext

Currently, it is possible that instances of BlameContext (and its subclasses)
to be created and managed in one thread, but its callbacks OnTraceLogEnabled()
and OnTraceLogDisabled() are called in a different one, which potentially
causes threading issues.

This patch sets new policies to ensure thread safety:

1. The two callbacks, when called from a different thread, must post tasks to
the thread where the instance was created, instead of doing their business
directly;

2. BlameContext and any of its subclasses must remove itself from TraceLog's
observer list at the beginning of destruction, so that the destructor does not
race with the callbacks.

BUG=546021

[Xiaocheng, 2016-04-26 08:33:38]

xiaochengh@chromium.org changed reviewers:
+ benjhayden@chromium.org, nduca@chromium.org, skyostil@chromium.org

[Xiaocheng, 2016-04-26 10:49:47]

PTAL.

This patch is made following the discussion in [1]. After this patch gets landed
we can remove the locks in [1].

https://codereview.chromium.org/1901023003

[Sami, 2016-04-26 11:00:32]

Thanks for the quick fix! One suggestion below.

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
File base/trace_event/blame_context.cc (right):

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
base/trace_event/blame_context.cc:78: // Called by TraceLog from a non-main
thread. Since access to TraceLog's list
I'd suggest talking about an "origin" thread (i.e., the thread an object was
created on) instead of a specific main thread. It might be perfectly reasonable
to have a blame context on the file thread for example.

This would also involve changing the below to

if (task_runner_->BelongsToCurrentThread() {
  TakeSnapshot();
} else {
  PostTask(...);
}

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
base/trace_event/blame_context.cc:80: // a different thread safely without
worrying about threading issues.
nit: task_runner_ is thread safe, as is getting a weak pointer from
weak_factory_ (while not dereferencing it).

[Xiaocheng, 2016-04-26 12:39:51]

Description was changed from

==========
Ensure Main Thread Affinity for BlameContext

Currently, instances of BlameContext (and its subclasses) live in main
threads but BlameContext::TakeSnapshot() can be called from a different
thread by the TraceLog via BlameContext::OnTraceLogEnabled(),
potentially causing threading issues.

This patch makes BlameContext::OnTraceLogEnabled() post a task to main
thread to run TakeSnapshot() instead of running it directly to ensure
thread safety.

BUG=546021
==========

to

==========
Ensure Origin Thread Affinity for BlameContext

Currently, it is possible that instances of BlameContext (and its subclasses)
to be created and managed in one thread, but BlameContext::TakeSnapshot() gets
called from a different thread by TraceLog via
BlameContext::OnTraceLogEnabled(),
potentially causing threading issues.

This patch makes BlameContext::OnTraceLogEnabled() post a task to the thread
where the instance was created when called from a different thread to ensure
thread safety.

BUG=546021
==========

[Xiaocheng, 2016-04-26 12:48:21]

Thanks for the review.

The patch is revised accordingly. PTAL.

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
File base/trace_event/blame_context.cc (right):

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
base/trace_event/blame_context.cc:78: // Called by TraceLog from a non-main
thread. Since access to TraceLog's list
On 2016/04/26 at 11:00:32, Sami wrote:
> I'd suggest talking about an "origin" thread (i.e., the thread an object was
created on) instead of a specific main thread. It might be perfectly reasonable
to have a blame context on the file thread for example.
> 
> This would also involve changing the below to
> 
> if (task_runner_->BelongsToCurrentThread() {
>   TakeSnapshot();
> } else {
>   PostTask(...);
> }

Yeah, that's a better idea.

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
base/trace_event/blame_context.cc:80: // a different thread safely without
worrying about threading issues.
On 2016/04/26 at 11:00:32, Sami wrote:
> nit: task_runner_ is thread safe, as is getting a weak pointer from
weak_factory_ (while not dereferencing it).

Sorry for the ambiguity.

I just want to say that it is safe for the trace log to access members
(task_runner_ and weak_factory_) of a BlameContext via a raw pointer.

Since (almost) every access to TraceLog::enabled_state_observer_list_ is
lock-guarded, the above thread safety claim should be true. The only exception
is in the deletion of TraceLog. Can I simply assume that TraceLog is always
deleted later than any BlameContext (since TraceLog is a singleton)?

[Sami, 2016-04-26 12:57:13]

Thanks, lgtm.

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
File base/trace_event/blame_context.cc (right):

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
base/trace_event/blame_context.cc:80: // a different thread safely without
worrying about threading issues.
On 2016/04/26 12:48:21, Xiaocheng wrote:
> On 2016/04/26 at 11:00:32, Sami wrote:
> > nit: task_runner_ is thread safe, as is getting a weak pointer from
> weak_factory_ (while not dereferencing it).
> 
> Sorry for the ambiguity.
> 
> I just want to say that it is safe for the trace log to access members
> (task_runner_ and weak_factory_) of a BlameContext via a raw pointer.
> 
> Since (almost) every access to TraceLog::enabled_state_observer_list_ is
> lock-guarded, the above thread safety claim should be true. The only exception
> is in the deletion of TraceLog. Can I simply assume that TraceLog is always
> deleted later than any BlameContext (since TraceLog is a singleton)?

I see. When a BlameContext is deleted, it removes itself from the TraceLog's
observer list and any in-flight task to TakeSnapshot becomes a no-op. Conversely
after a TraceLog is deleted, we won't have a call to OnTraceLogEnabled in the
first place. So that is just a long way of saying that this should be safe :)

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
File base/trace_event/blame_context.h (right):

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
base/trace_event/blame_context.h:107: virtual void
AsValueInto(trace_event::TracedValue* state);
Could you add a note here saying that this is always called on the thread on
which this object was created on?

[Primiano Tucci (use gerrit), 2016-04-26 15:32:15]

primiano@chromium.org changed reviewers:
+ primiano@chromium.org

[Primiano Tucci (use gerrit), 2016-04-26 15:32:15]

https://codereview.chromium.org/1916843003/diff/60001/base/trace_event/blame_...
File base/trace_event/blame_context.cc (right):

https://codereview.chromium.org/1916843003/diff/60001/base/trace_event/blame_...
base/trace_event/blame_context.cc:88: task_runner_->PostTask(FROM_HERE,
Bind(&BlameContext::TakeSnapshot,
What happens in the case that BlameContext is destroyed on another thread while
you are executing this? You are going to access a weak_factory_ that is being
torn down.
I think you just moved the race to this method now.

In general, this method can be called while the BlameContext is destroyed. The
EnabledStateObserver does not manage the lifetime of the observer (BlameContext
in this case).

[Sami, 2016-04-26 15:45:26]

https://codereview.chromium.org/1916843003/diff/60001/base/trace_event/blame_...
File base/trace_event/blame_context.cc (right):

https://codereview.chromium.org/1916843003/diff/60001/base/trace_event/blame_...
base/trace_event/blame_context.cc:88: task_runner_->PostTask(FROM_HERE,
Bind(&BlameContext::TakeSnapshot,
On 2016/04/26 15:32:15, Primiano Tucci wrote:
> What happens in the case that BlameContext is destroyed on another thread
while
> you are executing this? You are going to access a weak_factory_ that is being
> torn down.
> I think you just moved the race to this method now.
> 
> In general, this method can be called while the BlameContext is destroyed. The
> EnabledStateObserver does not manage the lifetime of the observer
(BlameContext
> in this case).
> 

BlameContext removes itself as an observer in the destructor (which I presume is
a thread safe operation), so it doesn't seem like there's a way for this method
to execute after BlameContext has gone away or while it is being destructed.

[Primiano Tucci (use gerrit), 2016-04-26 16:27:02]

On 2016/04/26 15:45:26, Sami wrote:
>
https://codereview.chromium.org/1916843003/diff/60001/base/trace_event/blame_...
> File base/trace_event/blame_context.cc (right):
> 
>
https://codereview.chromium.org/1916843003/diff/60001/base/trace_event/blame_...
> base/trace_event/blame_context.cc:88: task_runner_->PostTask(FROM_HERE,
> Bind(&BlameContext::TakeSnapshot,
> On 2016/04/26 15:32:15, Primiano Tucci wrote:
> > What happens in the case that BlameContext is destroyed on another thread
> while
> > you are executing this? You are going to access a weak_factory_ that is
being
> > torn down.
> > I think you just moved the race to this method now.
> > 
> > In general, this method can be called while the BlameContext is destroyed.
The
> > EnabledStateObserver does not manage the lifetime of the observer
> (BlameContext
> > in this case).
> > 
> 
> BlameContext removes itself as an observer in the destructor (which I presume
is
> a thread safe operation), so it doesn't seem like there's a way for this
method
> to execute after BlameContext has gone away or while it is being destructed.

oh right, the lock inside the tracing observer methods guarantees you that you
can't possibly be destroying and in the callback at the same time . 

unrelatedly with this cl, you can still see a partially destroyed object there
(in OnTraceLogEnabled)  in the following cases :
1. if somebody adds some cleanup code in the dtor before the un registration.
(maybe just add a comment) 
2. if a class derives from blamecontext, the dtor of the base class (this one)
is called after the dtor of the derived class has run (if I remember c++
correctly,  which I wouldn't take for granted) . from that point on, any virtual
call on this class will have undefined behavior.

[Sami, 2016-04-26 17:05:51]

> unrelatedly with this cl, you can still see a partially destroyed object there
> (in OnTraceLogEnabled)  in the following cases :
> 1. if somebody adds some cleanup code in the dtor before the un registration.
> (maybe just add a comment) 

Good idea.

> 2. if a class derives from blamecontext, the dtor of the base class (this one)
> is called after the dtor of the derived class has run (if I remember c++
> correctly,  which I wouldn't take for granted) . from that point on, any
virtual
> call on this class will have undefined behavior.

I need to brush up on my C++ details here too, but according to [1] we'd only be
calling the base class methods in that case. However strictly speaking the call
won't be via the destructor, so this may be undefined after all.

[1]
http://stackoverflow.com/questions/12092933/calling-virtual-function-from-des...

[Primiano Tucci (use gerrit), 2016-04-26 18:28:03]

On 2016/04/26 17:05:51, Sami wrote: 
> > 2. if a class derives from blamecontext, the dtor of the base class (this
one)
> > is called after the dtor of the derived class has run (if I remember c++
> > correctly,  which I wouldn't take for granted) . from that point on, any
> virtual
> > call on this class will have undefined behavior.
> 
> I need to brush up on my C++ details here too, but according to [1] we'd only
be
> calling the base class methods in that case. However strictly speaking the
call
> won't be via the destructor, so this may be undefined after all.
> 
> [1]
>
http://stackoverflow.com/questions/12092933/calling-virtual-function-from-des...


This is the repro case I am thinking about, based only on proper sleep()-s:
https://codereview.chromium.org/1921973003

P.S: is based on somewhat old code, whatever I had on the laptop. Offline is
hard :)

[Xiaocheng, 2016-04-27 03:02:25]

On 2016/04/26 at 18:28:03, primiano wrote:
> On 2016/04/26 17:05:51, Sami wrote: 
> > > 2. if a class derives from blamecontext, the dtor of the base class (this
one)
> > > is called after the dtor of the derived class has run (if I remember c++
> > > correctly,  which I wouldn't take for granted) . from that point on, any
> > virtual
> > > call on this class will have undefined behavior.
> > 
> > I need to brush up on my C++ details here too, but according to [1] we'd
only be
> > calling the base class methods in that case. However strictly speaking the
call
> > won't be via the destructor, so this may be undefined after all.
> > 
> > [1]
> >
http://stackoverflow.com/questions/12092933/calling-virtual-function-from-des...
> 
> 
> This is the repro case I am thinking about, based only on proper sleep()-s:
> https://codereview.chromium.org/1921973003
> 
> P.S: is based on somewhat old code, whatever I had on the laptop. Offline is
hard :)

Thanks for the insightful test case.

The problem is that the un-registration from the trace log is currently the last
step of the dtor, which makes access from TraceLog possible during the
destruction. It should be fixed by moving the un-registration to the beginning
of the dtor (and requiring all subclasses to do so).

[Xiaocheng, 2016-04-27 08:13:17]

On 2016/04/27 at 03:02:25, Xiaocheng wrote:
> On 2016/04/26 at 18:28:03, primiano wrote:
> > On 2016/04/26 17:05:51, Sami wrote: 
> > > > 2. if a class derives from blamecontext, the dtor of the base class
(this one)
> > > > is called after the dtor of the derived class has run (if I remember c++
> > > > correctly,  which I wouldn't take for granted) . from that point on, any
> > > virtual
> > > > call on this class will have undefined behavior.
> > > 
> > > I need to brush up on my C++ details here too, but according to [1] we'd
only be
> > > calling the base class methods in that case. However strictly speaking the
call
> > > won't be via the destructor, so this may be undefined after all.
> > > 
> > > [1]
> > >
http://stackoverflow.com/questions/12092933/calling-virtual-function-from-des...
> > 
> > 
> > This is the repro case I am thinking about, based only on proper sleep()-s:
> > https://codereview.chromium.org/1921973003
> > 
> > P.S: is based on somewhat old code, whatever I had on the laptop. Offline is
hard :)
> 
> Thanks for the insightful test case.
> 
> The problem is that the un-registration from the trace log is currently the
last step of the dtor, which makes access from TraceLog possible during the
destruction. It should be fixed by moving the un-registration to the beginning
of the dtor (and requiring all subclasses to do so).

It is getting more and more problematic...

In trace_log.cc, the call sites of OnTraceLogEnabled()/Disabled() are
intentionally put outside the lock. The purpose, I guess, is to prevent deadlock
with AddTraceEvent(). However this is introducing a risk of data race: an
observer may get destructed in one thread while its callback running in another
thread. A repro case is given as follows (based on primiano's case):

class TestBlameContextWithHeavyCallback : public BlameContext {
 public:
  TestBlameContextWithHeavyCallback()
      : BlameContext(kTestBlameContextCategory,
                     kTestBlameContextName,
                     kTestBlameContextType,
                     kTestBlameContextScope,
                     0,
                     nullptr) {}

  ~TestBlameContextWithHeavyCallback() override {}

  void OnTraceLogEnabled() override {
    usleep(200000); // Anything longer than the usleep() in RaceWithDTOR.

    // Now the instance is already deleted, so it would crash inside.
    BlameContext::OnTraceLogEnabled();
  }
};

TEST_F(BlameContextTest, RaceWithDTOR) {
  Thread thread("test thread");
  thread.Start();

  std::unique_ptr<TestBlameContextWithHeavyCallback> derived;
  derived.reset(new TestBlameContextWithHeavyCallback());
  derived->Initialize();
  thread.task_runner()->PostTask(
      FROM_HERE,
      base::Bind(&BlameContextTest::StartTracing, base::Unretained(this)));
  usleep(100000);
  derived.reset();
}

[Xiaocheng, 2016-04-27 10:11:32]

Description was changed from

==========
Ensure Origin Thread Affinity for BlameContext

Currently, it is possible that instances of BlameContext (and its subclasses)
to be created and managed in one thread, but BlameContext::TakeSnapshot() gets
called from a different thread by TraceLog via
BlameContext::OnTraceLogEnabled(),
potentially causing threading issues.

This patch makes BlameContext::OnTraceLogEnabled() post a task to the thread
where the instance was created when called from a different thread to ensure
thread safety.

BUG=546021
==========

to

==========
Ensure Origin Thread Affinity for BlameContext

Currently, it is possible that instances of BlameContext (and its subclasses)
to be created and managed in one thread, but its callbacks OnTraceLogEnabled()
and OnTraceLogDisabled() are called in a different one, which potentially
causes threading issues.

This patch sets new policies to ensure thread safety:

1. The two callbacks, when called from a different thread, must post tasks to
the thread where the instance was created, instead of doing their business
directly;

2. BlameContext and any of its subclasses must remove itself from TraceLog's
observer list at the beginning of destruction, so that the destructor does not
race with the callbacks.

BUG=546021
==========

[Xiaocheng, 2016-04-27 12:21:11]

PTAL.

It seems impossible to fix the race between callbacks and dtor if
TraceLog::enabled_state_observer_list_ is not protected by any lock when
dispatching to the observers, so (yet) another patch is made:
https://codereview.chromium.org/1923193002

I've modified this patch based on the above one, and also included a new test
case for this data race.

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
File base/trace_event/blame_context.h (right):

https://codereview.chromium.org/1916843003/diff/40001/base/trace_event/blame_...
base/trace_event/blame_context.h:107: virtual void
AsValueInto(trace_event::TracedValue* state);
On 2016/04/26 at 12:57:12, Sami wrote:
> Could you add a note here saying that this is always called on the thread on
which this object was created on?

A note on thread safety is added before the class definition.

[Xiaocheng, 2016-05-11 07:29:03]

Closing this patch since thread safety of BlameContext will be handled
differently.