tracing: fix races in CategoryRegistry

base/trace_event/trace_log.cc

 // Copyright 2015 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/trace_event/trace_log.h"
 
 #include <algorithm>
 #include <cmath>
 #include <memory>
 #include <utility>
@@ skipping 475 matching lines @@
   return true;
 }
 
 const unsigned char* TraceLog::GetCategoryGroupEnabled(
     const char* category_group) {
   TraceLog* tracelog = GetInstance();
   if (!tracelog) {
     DCHECK(!CategoryRegistry::kCategoryAlreadyShutdown->is_enabled());
     return CategoryRegistry::kCategoryAlreadyShutdown->state_ptr();
   }
-  TraceCategory* category = nullptr;
-  bool is_new_category =
-      CategoryRegistry::GetOrCreateCategoryByName(category_group, &category);

[Primiano Tucci (use gerrit), 2016/11/16 16:46:54]

Essentially this was the core of the problem.
The original code, before my previous CL, was quite similar to the latest
patchset.
Then, in my previous CL, I modified as follows:

if (category_NOT_seen_before) {
1.   Lock
2.   Create Category
3.   Unlock
4.   Update category flags looking  at trace config
}

This opened a race window such that if two threads hit this code at the same
time:
- They will only create one category entry, as the creation is locked (good)
- The second thread might use the category before the first thread as hit 4
(bad)

So, in practice, what can happen is that:
two threads hit TRACE_EVENT0("something-enabled-by-default").

1. Thread 1: adds "something-enabled-by-default" to the registry
2. Thread 2: sees that "something-enabled-by-default" is already in the registry
and uses that. However since T1 didn't initialize the flags yet, T2 will assume
that the category is not enabled and skip and not add its event to the log.
3. T1: does the initialization: queries TraceConfig, figures out that
"something-enabled-by-default" is enabled, and updates the flag of the category.

Now, this is not really a drama. It means that if two thread hit a new
TRACE_EVENT with the same category at the same time, one of the two might be not
recorded.

However, there are unitttests that depend on this behavior. Also this behavior
was guaranteed by the previous design, before my previous CL, so it's seems
reasonable to re-establish.

As an unrelated note, this is yet another reason to kill the concept of
"dynamic" categories in the future and only have statically defined categories. 

-  if (is_new_category)
-    tracelog->UpdateCategoryState(category);
+  TraceCategory* category = CategoryRegistry::GetCategoryByName(category_group);
+  if (!category) {
+    // Slow path: in the case of a new category we have to repeat the check
+    // holding the lock, as multiple threads might have reached this point
+    // at the same time.
+    auto category_initializer = [](TraceCategory* category) {
+      TraceLog::GetInstance()->UpdateCategoryState(category);
+    };
+    AutoLock lock(tracelog->lock_);
+    CategoryRegistry::GetOrCreateCategoryLocked(
+        category_group, category_initializer, &category);
+  }
   DCHECK(category->state_ptr());
   return category->state_ptr();
 }
 
 const char* TraceLog::GetCategoryGroupName(
     const unsigned char* category_group_enabled) {
   return CategoryRegistry::GetCategoryByStatePtr(category_group_enabled)
       ->name();
 }
 
@@ skipping 1279 matching lines @@
 }
 
 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
   if (*category_group_enabled_) {
     TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, name_,
                                                 event_handle_);
   }
 }
 
 }  // namespace trace_event_internal