Fix races in trace events filtering.

Fix races in trace events filtering.

The trace event filters for each category were stored as a list and the
objects were destroyed when tracing ends. But, when destroying these
filters the trace events on other thread which have checked the
ENABLED_FOR_FILTERING flag will try to access the filters list at the
same time. This CL:
1. Makes the filters enabled for categories a bitmap and restricts the
   number of filters that can be added in Chrome to 32 across all
   tracing sessions in a single browsing session. This removes the need
   for creation for filters for each category group.
2. Keeps all the filters alive till next tracing session starts since it
   is not possible to determine when the trace events have finished
   accessing the filter and it gives enough time for all the threads to
   complete acessing the filter.
3. Stores a global vector of all filters with max size 32 to access all
   the enabled filters for a trace category (corresponding to the bitmap
   flag) quickly.

This CL also fixes another issue where the trace events from V8 and Skia
were not recorded by EndEvent calls in filters. This is because the
EndFilter was called by trace_event.h. This call is now moved to
UpdateDuration, and end of all the events will now be recorded in
filters.

BUG=625170
Committed: https://crrev.com/7e6ad8071badb6ce2bb83cc8278f9662f191c953
Cr-Commit-Position: refs/heads/master@{#419917}

[ssid, 2016-09-08 00:35:27]

Description was changed from

==========
Fix races in trace events filtering.

The trace event filters for each category were stores in a list and the
objects were destroyed when tracing ends. But, when destroying these
filters the trace events on other thread which have checked the
ENABLED_FOR_FILTERING flag will try to access the filters list at the
same time. This CL does:
1. Makes the filters enabled for a category a bitmap and restricts the
   number of filters that can be added in Chrome to 32 across all
   tracing sessions in a single browsing session.
2. Leaks all the filters since it is not possible to determine when the
   trace events have finished accessing the filter. The
   HeapProfilerFilter is made singleton and only one instance of this
   will be created.
3. Stores a global array of all leaked filters with max size 32 to
   access all the enabled filters for a trace event (corresponding to
   the bitmap flag) quickly.

This CL also fixes another issue where the trace events from V8 and Skia
were not recorded by EndEvent calls in filters. This is because the
EndFilter was called by trace_event.h. This call is now moved to
UpdateDuration, and end of all the events will now be recorded in
filters.

BUG=625170
==========

to

==========
Fix races in trace events filtering.

The trace event filters for each category were stored as a list and the
objects were destroyed when tracing ends. But, when destroying these
filters the trace events on other thread which have checked the
ENABLED_FOR_FILTERING flag will try to access the filters list at the
same time. This CL:
1. Makes the filters enabled for a category a bitmap and restricts the
   number of filters that can be added in Chrome to 32 across all
   tracing sessions in a single browsing session.
2. Leaks all the filters since it is not possible to determine when the
   trace events have finished accessing the filter. The
   HeapProfilerFilter is made singleton and only one instance of this
   will be created.
3. Stores a global array of all leaked filters with max size 32 to
   access all the enabled filters for a trace event (corresponding to
   the bitmap flag) quickly.

This CL also fixes another issue where the trace events from V8 and Skia
were not recorded by EndEvent calls in filters. This is because the
EndFilter was called by trace_event.h. This call is now moved to
UpdateDuration, and end of all the events will now be recorded in
filters.

BUG=625170
==========

[ssid, 2016-09-08 00:36:42]

The CQ bit was checked by ssid@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-09-08 00:37:18]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-09-08 00:39:42]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-08 00:39:43]

Dry run: Try jobs failed on following builders:
  mac_chromium_rel_ng on master.tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/mac_chromium_rel_...)

[ssid, 2016-09-08 03:45:36]

Patchset #1 (id:1) has been deleted

[ssid, 2016-09-08 03:53:25]

Patchset #1 (id:20001) has been deleted

[ssid, 2016-09-08 03:53:38]

Patchset #1 (id:40001) has been deleted

[ssid, 2016-09-08 03:53:56]

The CQ bit was checked by ssid@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-09-08 03:54:12]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-09-08 05:38:07]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-08 05:38:08]

Dry run: This issue passed the CQ dry run.

[ssid, 2016-09-08 17:36:50]

ssid@chromium.org changed reviewers:
+ oysteine@chromium.org

[ssid, 2016-09-08 17:36:50]

ptal thanks.

[ssid, 2016-09-13 01:37:56]

friendly ping

[oystein (OOO til 10th of July), 2016-09-13 21:19:09]

It feels like we should be able to solve this in a simpler way though, since the
whole list of filters is essentially add-only per tracing generation.

If I understand the problem correctly, it essentially lies in
UpdateCategoryGroupEnabledFlag(), in this bit:

   if (!(g_category_group_filter[category_index] == nullptr))
    g_category_group_filter[category_index].Get().clear();

(and also doing the .push_back() in the same function, for new filters)

Does that sound right?

I'm wondering if we could instead:
* Only mutate g_category_group_filter in UpdateCategoryGroupEnabledFlag() if
mode_ == RECORDING_MODE (mode__ == DISABLED should be the only actual case where
we decrease the number of filters).
* Change the filter lists from std::vector to static arrays (essentially NULL
terminated), for the case where two threads initialize a filter list in
UpdateCategoryGroupEnabledFlag() at the same time.
* Go through and delete any filters in FinishFlush() as there shouldn't be any
other threads interfering at that point.

The one codepath where I could see this breaking is if the set of enabled
categories changes while tracing is active and we go from N filters to M filters
where N>M>0 (and no other tracing options changes), but I actually think that's
a feature that isn't used by anything anyway.

wdyt? If that sounds doable it should keep the complexity down and avoid
leakage.

[ssid, 2016-09-13 22:37:27]

On 2016/09/13 21:19:09, oystein wrote:
> It feels like we should be able to solve this in a simpler way though, since
the
> whole list of filters is essentially add-only per tracing generation.
> 
> If I understand the problem correctly, it essentially lies in
> UpdateCategoryGroupEnabledFlag(), in this bit:
> 
>    if (!(g_category_group_filter[category_index] == nullptr))
>     g_category_group_filter[category_index].Get().clear();
> 
> (and also doing the .push_back() in the same function, for new filters)
> 
> Does that sound right?

Yes, that is the main issue.

> I'm wondering if we could instead:
> * Only mutate g_category_group_filter in UpdateCategoryGroupEnabledFlag() if
> mode_ == RECORDING_MODE (mode__ == DISABLED should be the only actual case
where
> we decrease the number of filters).
> * Change the filter lists from std::vector to static arrays (essentially NULL
> terminated), for the case where two threads initialize a filter list in
> UpdateCategoryGroupEnabledFlag() at the same time.

Not sure I understand how to have a static array of objects that can change in
number, and the args can change. The EventNameFilter depends on a list of trace
event names given by trace config. But, why can't we just hold the lock while
initializing, it is anyway done when tracelog is enabled right?

> * Go through and delete any filters in FinishFlush() as there shouldn't be any
> other threads interfering at that point.

This is a good idea. Essentially first disable filtering / recording, then the
flush goes through all the threads and collects events. This ensures that none
of these threads are actually in middle of adding a trace event, and after the
flush happens it is ensured that none of these trace events see filtering on.
But, there could be a case where a new thread hits a trace event before
disabling filtering and it is middle of adding trace event. At this point the
main thread does TraceLog::FlushInternal took a list of all threads. After this
the new thread adds itself to the thread_message_loops_ and tries to get the
filters, by this time the filters are deleted by the main thread.
I couldn't think of anyway to avoid leaking here. Maybe I could do something
like a disabled flag in the filter and delete the data later? I feel leaking is
a cleaner way to do it here.


> The one codepath where I could see this breaking is if the set of enabled
> categories changes while tracing is active and we go from N filters to M
filters
> where N>M>0 (and no other tracing options changes), but I actually think
that's
> a feature that isn't used by anything anyway.

Yes, i dont think this needs to be supported now.

> wdyt? If that sounds doable it should keep the complexity down and avoid
> leakage.

[oystein (OOO til 10th of July), 2016-09-15 16:39:01]

On 2016/09/13 22:37:27, ssid wrote:
> On 2016/09/13 21:19:09, oystein wrote:
> > It feels like we should be able to solve this in a simpler way though, since
> the
> > whole list of filters is essentially add-only per tracing generation.
> > 
> > If I understand the problem correctly, it essentially lies in
> > UpdateCategoryGroupEnabledFlag(), in this bit:
> > 
> >    if (!(g_category_group_filter[category_index] == nullptr))
> >     g_category_group_filter[category_index].Get().clear();
> > 
> > (and also doing the .push_back() in the same function, for new filters)
> > 
> > Does that sound right?
> 
> Yes, that is the main issue.
> 
> > I'm wondering if we could instead:
> > * Only mutate g_category_group_filter in UpdateCategoryGroupEnabledFlag() if
> > mode_ == RECORDING_MODE (mode__ == DISABLED should be the only actual case
> where
> > we decrease the number of filters).
> > * Change the filter lists from std::vector to static arrays (essentially
NULL
> > terminated), for the case where two threads initialize a filter list in
> > UpdateCategoryGroupEnabledFlag() at the same time.
> 
> Not sure I understand how to have a static array of objects that can change in
> number, and the args can change. The EventNameFilter depends on a list of
trace
> event names given by trace config. But, why can't we just hold the lock while
> initializing, it is anyway done when tracelog is enabled right?
> 

The args wouldn't change during a tracing session; they can't. The number of
filters wouldn't change either, the reason for a static array would be in the
case where two threads are trying to create the list at the same time. In this
case they wouldn't be conflicting with each other, assuming they atomically set
the pointers in the list (they may leak objects, but that's it).

But yes you're right, the filters could be created while the lock is held during
SetEnabled() in a separate list, and then UpdateCategoryGroupEnabled() could
build an index into that list. That could be a useful refactor, as it avoids one
copy of each filter for each category.

> > * Go through and delete any filters in FinishFlush() as there shouldn't be
any
> > other threads interfering at that point.
> 
> This is a good idea. Essentially first disable filtering / recording, then the
> flush goes through all the threads and collects events. This ensures that none
> of these threads are actually in middle of adding a trace event, and after the
> flush happens it is ensured that none of these trace events see filtering on.
> But, there could be a case where a new thread hits a trace event before
> disabling filtering and it is middle of adding trace event. At this point the
> main thread does TraceLog::FlushInternal took a list of all threads. After
this
> the new thread adds itself to the thread_message_loops_ and tries to get the
> filters, by this time the filters are deleted by the main thread.
> I couldn't think of anyway to avoid leaking here. Maybe I could do something
> like a disabled flag in the filter and delete the data later? I feel leaking
is
> a cleaner way to do it here.
> 

Hmm good point. In the case of a new thread being "seen" for the first time, a
lock would always be held at some point though (either when creating a new
ThreadLocalEventBuffer or when adding the event in the non-messageloop case), it
feels like we should be able to bail at that point if tracing has been disabled.
That may be turning into a yak-shave though... wdyt?

> 
> > The one codepath where I could see this breaking is if the set of enabled
> > categories changes while tracing is active and we go from N filters to M
> filters
> > where N>M>0 (and no other tracing options changes), but I actually think
> that's
> > a feature that isn't used by anything anyway.
> 
> Yes, i dont think this needs to be supported now.
> 
> > wdyt? If that sounds doable it should keep the complexity down and avoid
> > leakage.

[ssid, 2016-09-16 04:18:51]

Description was changed from

==========
Fix races in trace events filtering.

The trace event filters for each category were stored as a list and the
objects were destroyed when tracing ends. But, when destroying these
filters the trace events on other thread which have checked the
ENABLED_FOR_FILTERING flag will try to access the filters list at the
same time. This CL:
1. Makes the filters enabled for a category a bitmap and restricts the
   number of filters that can be added in Chrome to 32 across all
   tracing sessions in a single browsing session.
2. Leaks all the filters since it is not possible to determine when the
   trace events have finished accessing the filter. The
   HeapProfilerFilter is made singleton and only one instance of this
   will be created.
3. Stores a global array of all leaked filters with max size 32 to
   access all the enabled filters for a trace event (corresponding to
   the bitmap flag) quickly.

This CL also fixes another issue where the trace events from V8 and Skia
were not recorded by EndEvent calls in filters. This is because the
EndFilter was called by trace_event.h. This call is now moved to
UpdateDuration, and end of all the events will now be recorded in
filters.

BUG=625170
==========

to

==========
Fix races in trace events filtering.

The trace event filters for each category were stored as a list and the
objects were destroyed when tracing ends. But, when destroying these
filters the trace events on other thread which have checked the
ENABLED_FOR_FILTERING flag will try to access the filters list at the
same time. This CL:
1. Makes the filters enabled for categories a bitmap and restricts the
   number of filters that can be added in Chrome to 32 across all
   tracing sessions in a single browsing session. This removes the need
   for creation for filters for each category group.
2. Keeps all the filters alive till next tracing session starts since it
   is not possible to determine when the trace events have finished
   accessing the filter and it gives enough time for all the threads to
   complete acessing the filter.
3. Stores a global vector of all filters with max size 32 to access all
   the enabled filters for a trace category (corresponding to the bitmap
   flag) quickly.

This CL also fixes another issue where the trace events from V8 and Skia
were not recorded by EndEvent calls in filters. This is because the
EndFilter was called by trace_event.h. This call is now moved to
UpdateDuration, and end of all the events will now be recorded in
filters.

BUG=625170
==========

[ssid, 2016-09-16 04:53:28]

Patchset #2 (id:80001) has been deleted

[ssid, 2016-09-16 05:00:07]

Patchset #2 (id:100001) has been deleted

[ssid, 2016-09-16 18:33:08]

cleared the filters at SetEnabled.
UpdateCategoryGroupEnabledFlag is always called under lock, so two threads
creating filters is not an issue.
ptal, thanks

[oystein (OOO til 10th of July), 2016-09-16 19:09:00]

This is great, thank you!

lgtm with nits.

https://codereview.chromium.org/2316403002/diff/120001/base/trace_event/trace...
File base/trace_event/trace_log.cc (right):

https://codereview.chromium.org/2316403002/diff/120001/base/trace_event/trace...
base/trace_event/trace_log.cc:591: unsigned index = 0;
nit: We don't use 'unsigned' as a bare type outside of Blink, just make it an
'int'.

https://codereview.chromium.org/2316403002/diff/120001/base/trace_event/trace...
base/trace_event/trace_log.cc:625: NOTREACHED();
Just stream the error message into NOTREACHED() instead.

https://codereview.chromium.org/2316403002/diff/120001/base/trace_event/trace...
base/trace_event/trace_log.cc:760: DLOG(ERROR) << "Adding new filters while
tracing was already enabled "
I think DLOG() is discouraged these days because it just spams the logs and are
never checked anywhere. I would just make it a DCHECK.

[ssid, 2016-09-20 21:23:17]

The CQ bit was checked by ssid@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-09-20 21:23:50]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-09-21 00:18:42]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-21 00:18:43]

Dry run: This issue passed the CQ dry run.

[ssid, 2016-09-21 00:20:26]

thanks, fixed.

https://codereview.chromium.org/2316403002/diff/120001/base/trace_event/trace...
File base/trace_event/trace_log.cc (right):

https://codereview.chromium.org/2316403002/diff/120001/base/trace_event/trace...
base/trace_event/trace_log.cc:591: unsigned index = 0;
On 2016/09/16 19:09:00, oystein wrote:
> nit: We don't use 'unsigned' as a bare type outside of Blink, just make it an
> 'int'.

Done.

https://codereview.chromium.org/2316403002/diff/120001/base/trace_event/trace...
base/trace_event/trace_log.cc:625: NOTREACHED();
On 2016/09/16 19:09:00, oystein wrote:
> Just stream the error message into NOTREACHED() instead.

Done.

https://codereview.chromium.org/2316403002/diff/120001/base/trace_event/trace...
base/trace_event/trace_log.cc:760: DLOG(ERROR) << "Adding new filters while
tracing was already enabled "
On 2016/09/16 19:09:00, oystein wrote:
> I think DLOG() is discouraged these days because it just spams the logs and
are
> never checked anywhere. I would just make it a DCHECK.

Done.

[ssid, 2016-09-21 00:20:57]

The CQ bit was checked by ssid@chromium.org

[ssid, 2016-09-21 00:20:57]

The patchset sent to the CQ was uploaded after l-g-t-m from
oysteine@chromium.org
Link to the patchset: https://codereview.chromium.org/2316403002/#ps140001
(title: "Fixes.")

[commit-bot: I haz the power, 2016-09-21 00:21:23]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-09-21 00:28:31]

Description was changed from

==========
Fix races in trace events filtering.

The trace event filters for each category were stored as a list and the
objects were destroyed when tracing ends. But, when destroying these
filters the trace events on other thread which have checked the
ENABLED_FOR_FILTERING flag will try to access the filters list at the
same time. This CL:
1. Makes the filters enabled for categories a bitmap and restricts the
   number of filters that can be added in Chrome to 32 across all
   tracing sessions in a single browsing session. This removes the need
   for creation for filters for each category group.
2. Keeps all the filters alive till next tracing session starts since it
   is not possible to determine when the trace events have finished
   accessing the filter and it gives enough time for all the threads to
   complete acessing the filter.
3. Stores a global vector of all filters with max size 32 to access all
   the enabled filters for a trace category (corresponding to the bitmap
   flag) quickly.

This CL also fixes another issue where the trace events from V8 and Skia
were not recorded by EndEvent calls in filters. This is because the
EndFilter was called by trace_event.h. This call is now moved to
UpdateDuration, and end of all the events will now be recorded in
filters.

BUG=625170
==========

to

==========
Fix races in trace events filtering.

The trace event filters for each category were stored as a list and the
objects were destroyed when tracing ends. But, when destroying these
filters the trace events on other thread which have checked the
ENABLED_FOR_FILTERING flag will try to access the filters list at the
same time. This CL:
1. Makes the filters enabled for categories a bitmap and restricts the
   number of filters that can be added in Chrome to 32 across all
   tracing sessions in a single browsing session. This removes the need
   for creation for filters for each category group.
2. Keeps all the filters alive till next tracing session starts since it
   is not possible to determine when the trace events have finished
   accessing the filter and it gives enough time for all the threads to
   complete acessing the filter.
3. Stores a global vector of all filters with max size 32 to access all
   the enabled filters for a trace category (corresponding to the bitmap
   flag) quickly.

This CL also fixes another issue where the trace events from V8 and Skia
were not recorded by EndEvent calls in filters. This is because the
EndFilter was called by trace_event.h. This call is now moved to
UpdateDuration, and end of all the events will now be recorded in
filters.

BUG=625170
==========

[commit-bot: I haz the power, 2016-09-21 00:28:33]

Committed patchset #3 (id:140001)

[commit-bot: I haz the power, 2016-09-21 00:31:03]

Description was changed from

==========
Fix races in trace events filtering.

The trace event filters for each category were stored as a list and the
objects were destroyed when tracing ends. But, when destroying these
filters the trace events on other thread which have checked the
ENABLED_FOR_FILTERING flag will try to access the filters list at the
same time. This CL:
1. Makes the filters enabled for categories a bitmap and restricts the
   number of filters that can be added in Chrome to 32 across all
   tracing sessions in a single browsing session. This removes the need
   for creation for filters for each category group.
2. Keeps all the filters alive till next tracing session starts since it
   is not possible to determine when the trace events have finished
   accessing the filter and it gives enough time for all the threads to
   complete acessing the filter.
3. Stores a global vector of all filters with max size 32 to access all
   the enabled filters for a trace category (corresponding to the bitmap
   flag) quickly.

This CL also fixes another issue where the trace events from V8 and Skia
were not recorded by EndEvent calls in filters. This is because the
EndFilter was called by trace_event.h. This call is now moved to
UpdateDuration, and end of all the events will now be recorded in
filters.

BUG=625170
==========

to

==========
Fix races in trace events filtering.

The trace event filters for each category were stored as a list and the
objects were destroyed when tracing ends. But, when destroying these
filters the trace events on other thread which have checked the
ENABLED_FOR_FILTERING flag will try to access the filters list at the
same time. This CL:
1. Makes the filters enabled for categories a bitmap and restricts the
   number of filters that can be added in Chrome to 32 across all
   tracing sessions in a single browsing session. This removes the need
   for creation for filters for each category group.
2. Keeps all the filters alive till next tracing session starts since it
   is not possible to determine when the trace events have finished
   accessing the filter and it gives enough time for all the threads to
   complete acessing the filter.
3. Stores a global vector of all filters with max size 32 to access all
   the enabled filters for a trace category (corresponding to the bitmap
   flag) quickly.

This CL also fixes another issue where the trace events from V8 and Skia
were not recorded by EndEvent calls in filters. This is because the
EndFilter was called by trace_event.h. This call is now moved to
UpdateDuration, and end of all the events will now be recorded in
filters.

BUG=625170

Committed: https://crrev.com/7e6ad8071badb6ce2bb83cc8278f9662f191c953
Cr-Commit-Position: refs/heads/master@{#419917}
==========

[commit-bot: I haz the power, 2016-09-21 00:31:04]

Patchset 3 (id:??) landed as
https://crrev.com/7e6ad8071badb6ce2bb83cc8278f9662f191c953
Cr-Commit-Position: refs/heads/master@{#419917}