Add trace code to track all posted tasks in message_loop and WorkerThreads (non-official builds only).

It's very helpful to understand what chrome is doing at runtime. Sometimes a thread in chrome does something expensive that causes a frame hitch. With this change, any expensive task will show up clearly in traces, with the file/function of where the task was posted.

TEST=go to about:tracing, run a trace and notice that all tasks are traced.

Review URL: http://codereview.chromium.org/7778033

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@103740 0039d316-1c4b-4281-b951-d872f2087c98

12 files changed, 195 insertions, 142 deletions

diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc
index 879f3a9..39a7484 100644
--- a/base/debug/trace_event.cc
+++ b/base/debug/trace_event.cc
@@ -20,6 +20,14 @@
 
 #define USE_UNRELIABLE_NOW
 
+class DeleteTraceLogForTesting {
+ public:
+  static void Delete() {
+    Singleton<base::debug::TraceLog,
+              StaticMemorySingletonTraits<base::debug::TraceLog> >::OnExit(0);
+  }
+};
+
 namespace base {
 namespace debug {
 
@@ -410,7 +418,7 @@ void TraceLog::Flush() {
        i < previous_logged_events.size();
        i += kTraceEventBatchSize) {
     scoped_refptr<RefCountedString> json_events_str_ptr =
-      new RefCountedString();
+        new RefCountedString();
     TraceEvent::AppendEventsAsJSON(previous_logged_events,
                                    i,
                                    kTraceEventBatchSize,
@@ -547,6 +555,10 @@ void TraceLog::AddCurrentMetadataEvents() {
   }
 }
 
+void TraceLog::DeleteForTesting() {
+  DeleteTraceLogForTesting::Delete();
+}
+
 void TraceLog::Resurrect() {
   StaticMemorySingletonTraits<TraceLog>::Resurrect();
 }
diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index e7b3f90..d5aa256 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -114,19 +114,19 @@
 // Older style trace macros with explicit id and extra data
 // Only these macros result in publishing data to ETW as currently implemented.
 #define TRACE_EVENT_BEGIN_ETW(name, id, extra) \
-  base::debug::TraceLog::AddTraceEventEtw( \
-      base::debug::TRACE_EVENT_PHASE_BEGIN, \
-      name, reinterpret_cast<const void*>(id), extra)
+    base::debug::TraceLog::AddTraceEventEtw( \
+        base::debug::TRACE_EVENT_PHASE_BEGIN, \
+        name, reinterpret_cast<const void*>(id), extra)
 
 #define TRACE_EVENT_END_ETW(name, id, extra) \
-  base::debug::TraceLog::AddTraceEventEtw( \
-      base::debug::TRACE_EVENT_PHASE_END, \
-      name, reinterpret_cast<const void*>(id), extra)
+    base::debug::TraceLog::AddTraceEventEtw( \
+        base::debug::TRACE_EVENT_PHASE_END, \
+        name, reinterpret_cast<const void*>(id), extra)
 
 #define TRACE_EVENT_INSTANT_ETW(name, id, extra) \
-  base::debug::TraceLog::AddTraceEventEtw( \
-      base::debug::TRACE_EVENT_PHASE_INSTANT, \
-      name, reinterpret_cast<const void*>(id), extra)
+    base::debug::TraceLog::AddTraceEventEtw( \
+        base::debug::TRACE_EVENT_PHASE_INSTANT, \
+        name, reinterpret_cast<const void*>(id), extra)
 
 // Records a pair of begin and end events called "name" for the current
 // scope, with 0, 1 or 2 associated arguments. If the category is not
@@ -134,12 +134,28 @@
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT0(category, name) \
-  TRACE_EVENT1(category, name, NULL, 0)
+    TRACE_EVENT1(category, name, NULL, 0)
 #define TRACE_EVENT1(category, name, arg1_name, arg1_val) \
-  TRACE_EVENT2(category, name, arg1_name, arg1_val, NULL, 0)
+    TRACE_EVENT2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT2(category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_ADD_SCOPED( \
-      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
+    INTERNAL_TRACE_EVENT_ADD_SCOPED( \
+        category, name, arg1_name, arg1_val, arg2_name, arg2_val)
+
+// Same as TRACE_EVENT except that they are not included in official builds.
+#ifdef OFFICIAL_BUILD
+#define UNSHIPPED_TRACE_EVENT0(category, name) (void)0
+#define UNSHIPPED_TRACE_EVENT1(category, name, arg1_name, arg1_val) (void)0
+#define UNSHIPPED_TRACE_EVENT2(category, name, arg1_name, arg1_val, \
+                               arg2_name, arg2_val) (void)0
+#else
+#define UNSHIPPED_TRACE_EVENT0(category, name) \
+    TRACE_EVENT0(category, name)
+#define UNSHIPPED_TRACE_EVENT1(category, name, arg1_name, arg1_val) \
+    TRACE_EVENT1(category, name, arg1_name, arg1_val)
+#define UNSHIPPED_TRACE_EVENT2(category, name, arg1_name, arg1_val, \
+                               arg2_name, arg2_val) \
+    TRACE_EVENT2(category, name, arg1_name, arg1_val, arg2_name, arg2_val)
+#endif
 
 // Records a single event called "name" immediately, with 0, 1 or 2
 // associated arguments. If the category is not enabled, then this
@@ -147,25 +163,25 @@
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT_INSTANT0(category, name) \
-  TRACE_EVENT_INSTANT1(category, name, NULL, 0)
+    TRACE_EVENT_INSTANT1(category, name, NULL, 0)
 #define TRACE_EVENT_INSTANT1(category, name, arg1_name, arg1_val) \
-  TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0)
+    TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, \
-    arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_INSTANT, \
-      category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
-      base::debug::TraceLog::EVENT_FLAG_NONE)
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_INSTANT, \
+        category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
+        base::debug::TraceLog::EVENT_FLAG_NONE)
 #define TRACE_EVENT_COPY_INSTANT0(category, name) \
-  TRACE_EVENT_COPY_INSTANT1(category, name, NULL, 0)
+    TRACE_EVENT_COPY_INSTANT1(category, name, NULL, 0)
 #define TRACE_EVENT_COPY_INSTANT1(category, name, arg1_name, arg1_val) \
-  TRACE_EVENT_COPY_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0)
+    TRACE_EVENT_COPY_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_COPY_INSTANT2(category, name, arg1_name, arg1_val, \
-    arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_INSTANT, \
-      category, name, \
-      arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
-      arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
-      base::debug::TraceLog::EVENT_FLAG_COPY)
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_INSTANT, \
+        category, name, \
+        arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
+        arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
+        base::debug::TraceLog::EVENT_FLAG_COPY)
 
 // Records a single BEGIN event called "name" immediately, with 0, 1 or 2
 // associated arguments. If the category is not enabled, then this
@@ -173,50 +189,50 @@
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT_BEGIN0(category, name) \
-  TRACE_EVENT_BEGIN1(category, name, NULL, 0)
+    TRACE_EVENT_BEGIN1(category, name, NULL, 0)
 #define TRACE_EVENT_BEGIN1(category, name, arg1_name, arg1_val) \
-  TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0)
+    TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, \
-    arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_BEGIN, \
-      category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
-      base::debug::TraceLog::EVENT_FLAG_NONE)
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_BEGIN, \
+        category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
+        base::debug::TraceLog::EVENT_FLAG_NONE)
 #define TRACE_EVENT_COPY_BEGIN0(category, name) \
-  TRACE_EVENT_COPY_BEGIN1(category, name, NULL, 0)
+    TRACE_EVENT_COPY_BEGIN1(category, name, NULL, 0)
 #define TRACE_EVENT_COPY_BEGIN1(category, name, arg1_name, arg1_val) \
-  TRACE_EVENT_COPY_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0)
+    TRACE_EVENT_COPY_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_COPY_BEGIN2(category, name, arg1_name, arg1_val, \
-    arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_BEGIN, \
-      category, name, \
-      arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
-      arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
-      base::debug::TraceLog::EVENT_FLAG_COPY)
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_BEGIN, \
+        category, name, \
+        arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
+        arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
+        base::debug::TraceLog::EVENT_FLAG_COPY)
 
 // Records a single END event for "name" immediately. If the category
 // is not enabled, then this does nothing.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT_END0(category, name) \
-  TRACE_EVENT_END1(category, name, NULL, 0)
+    TRACE_EVENT_END1(category, name, NULL, 0)
 #define TRACE_EVENT_END1(category, name, arg1_name, arg1_val) \
-  TRACE_EVENT_END2(category, name, arg1_name, arg1_val, NULL, 0)
+    TRACE_EVENT_END2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_END2(category, name, arg1_name, arg1_val, \
-    arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_END, \
-      category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
-      base::debug::TraceLog::EVENT_FLAG_NONE)
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_END, \
+        category, name, arg1_name, arg1_val, arg2_name, arg2_val, \
+        base::debug::TraceLog::EVENT_FLAG_NONE)
 #define TRACE_EVENT_COPY_END0(category, name) \
-  TRACE_EVENT_COPY_END1(category, name, NULL, 0)
+    TRACE_EVENT_COPY_END1(category, name, NULL, 0)
 #define TRACE_EVENT_COPY_END1(category, name, arg1_name, arg1_val) \
-  TRACE_EVENT_COPY_END2(category, name, arg1_name, arg1_val, NULL, 0)
+    TRACE_EVENT_COPY_END2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_COPY_END2(category, name, arg1_name, arg1_val, \
-    arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_END, \
-      category, name, \
-      arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
-      arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
-      base::debug::TraceLog::EVENT_FLAG_COPY)
+        arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_END, \
+        category, name, \
+        arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \
+        arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \
+        base::debug::TraceLog::EVENT_FLAG_COPY)
 
 // Time threshold event:
 // Only record the event if the duration is greater than the specified
@@ -227,15 +243,15 @@
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT_IF_LONGER_THAN0(threshold_us, category, name) \
-  TRACE_EVENT_IF_LONGER_THAN1(threshold_us, category, name, NULL, 0)
+    TRACE_EVENT_IF_LONGER_THAN1(threshold_us, category, name, NULL, 0)
 #define TRACE_EVENT_IF_LONGER_THAN1( \
-    threshold_us, category, name, arg1_name, arg1_val) \
-  TRACE_EVENT_IF_LONGER_THAN2(threshold_us, category, name, \
-                         arg1_name, arg1_val, NULL, 0)
+        threshold_us, category, name, arg1_name, arg1_val) \
+    TRACE_EVENT_IF_LONGER_THAN2(threshold_us, category, name, \
+                           arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_IF_LONGER_THAN2( \
     threshold_us, category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN(threshold_us, \
-      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
+    INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN(threshold_us, \
+        category, name, arg1_name, arg1_val, arg2_name, arg2_val)
 
 
 // Implementation detail: trace event macros create temporary variables
@@ -244,69 +260,69 @@
 #define INTERNAL_TRACE_EVENT_UID3(a,b) \
     trace_event_unique_##a##b
 #define INTERNAL_TRACE_EVENT_UID2(a,b) \
-  INTERNAL_TRACE_EVENT_UID3(a,b)
+    INTERNAL_TRACE_EVENT_UID3(a,b)
 #define INTERNAL_TRACE_EVENT_UID(name_prefix) \
-  INTERNAL_TRACE_EVENT_UID2(name_prefix, __LINE__)
+    INTERNAL_TRACE_EVENT_UID2(name_prefix, __LINE__)
 
 // Implementation detail: internal macro to create static category.
 // - ANNOTATE_BENIGN_RACE, see Thread Safety above.
 #define INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category) \
-  static const base::debug::TraceCategory* \
-      INTERNAL_TRACE_EVENT_UID(catstatic) = NULL; \
-  ANNOTATE_BENIGN_RACE(&INTERNAL_TRACE_EVENT_UID(catstatic), \
-                       "trace_event category"); \
-  if (!INTERNAL_TRACE_EVENT_UID(catstatic)) \
-    INTERNAL_TRACE_EVENT_UID(catstatic) = \
-        base::debug::TraceLog::GetCategory(category);
+    static const base::debug::TraceCategory* \
+        INTERNAL_TRACE_EVENT_UID(catstatic) = NULL; \
+    ANNOTATE_BENIGN_RACE(&INTERNAL_TRACE_EVENT_UID(catstatic), \
+                         "trace_event category"); \
+    if (!INTERNAL_TRACE_EVENT_UID(catstatic)) \
+      INTERNAL_TRACE_EVENT_UID(catstatic) = \
+          base::debug::TraceLog::GetCategory(category);
 
 // Implementation detail: internal macro to create static category and add begin
 // event if the category is enabled.
 #define INTERNAL_TRACE_EVENT_ADD( \
-    phase, category, name, arg1_name, arg1_val, arg2_name, arg2_val, flags) \
-  INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
-  if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
-    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
-        phase, INTERNAL_TRACE_EVENT_UID(catstatic), \
-        name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, flags); \
-  }
+      phase, category, name, arg1_name, arg1_val, arg2_name, arg2_val, flags) \
+    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
+    if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
+      base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+          phase, INTERNAL_TRACE_EVENT_UID(catstatic), \
+          name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, flags); \
+    }
 
 // Implementation detail: internal macro to create static category and add begin
 // event if the category is enabled. Also adds the end event when the scope
 // ends.
 #define INTERNAL_TRACE_EVENT_ADD_SCOPED( \
-    category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
-  base::debug::internal::TraceEndOnScopeClose \
-      INTERNAL_TRACE_EVENT_UID(profileScope); \
-  if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
-    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
-        base::debug::TRACE_EVENT_PHASE_BEGIN, \
-        INTERNAL_TRACE_EVENT_UID(catstatic), \
-        name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
-        base::debug::TraceLog::EVENT_FLAG_NONE); \
-    INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
-        INTERNAL_TRACE_EVENT_UID(catstatic), name); \
-  }
-
-// Implementation detail: internal macro to create static category and add begin
-// event if the category is enabled. Also adds the end event when the scope
-// ends. If the elapsed time is < threshold time, the begin/end pair is erased.
-#define INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN(threshold, \
-    category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
-  INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
-  base::debug::internal::TraceEndOnScopeCloseThreshold \
-      INTERNAL_TRACE_EVENT_UID(profileScope); \
-  if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
-    int INTERNAL_TRACE_EVENT_UID(begin_event_id) = \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
+    base::debug::internal::TraceEndOnScopeClose \
+        INTERNAL_TRACE_EVENT_UID(profileScope); \
+    if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
       base::debug::TraceLog::GetInstance()->AddTraceEvent( \
           base::debug::TRACE_EVENT_PHASE_BEGIN, \
           INTERNAL_TRACE_EVENT_UID(catstatic), \
           name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
           base::debug::TraceLog::EVENT_FLAG_NONE); \
-    INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
-        INTERNAL_TRACE_EVENT_UID(catstatic), name, \
-        INTERNAL_TRACE_EVENT_UID(begin_event_id), threshold); \
-  }
+      INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
+          INTERNAL_TRACE_EVENT_UID(catstatic), name); \
+    }
+
+// Implementation detail: internal macro to create static category and add begin
+// event if the category is enabled. Also adds the end event when the scope
+// ends. If the elapsed time is < threshold time, the begin/end pair is erased.
+#define INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN(threshold, \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
+    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
+    base::debug::internal::TraceEndOnScopeCloseThreshold \
+        INTERNAL_TRACE_EVENT_UID(profileScope); \
+    if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
+      int INTERNAL_TRACE_EVENT_UID(begin_event_id) = \
+        base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+            base::debug::TRACE_EVENT_PHASE_BEGIN, \
+            INTERNAL_TRACE_EVENT_UID(catstatic), \
+            name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \
+            base::debug::TraceLog::EVENT_FLAG_NONE); \
+      INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
+          INTERNAL_TRACE_EVENT_UID(catstatic), name, \
+          INTERNAL_TRACE_EVENT_UID(begin_event_id), threshold); \
+    }
 
 namespace base {
 
@@ -577,6 +593,9 @@ class BASE_EXPORT TraceLog {
 
   // Exposed for unittesting:
 
+  // Allows deleting our singleton instance.
+  static void DeleteForTesting();
+
   // Allows resurrecting our singleton instance post-AtExit processing.
   static void Resurrect();
 
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index a5c889f..c0c9380 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -58,20 +58,23 @@ class TraceEventTestFixture : public testing::Test {
  private:
   // We want our singleton torn down after each test.
   ShadowingAtExitManager at_exit_manager_;
+  Lock lock_;
 };
 
 void TraceEventTestFixture::ManualTestSetUp() {
+  TraceLog::DeleteForTesting();
   TraceLog::Resurrect();
   TraceLog* tracelog = TraceLog::GetInstance();
   ASSERT_TRUE(tracelog);
   ASSERT_FALSE(tracelog->IsEnabled());
   tracelog->SetOutputCallback(
-    base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
-               base::Unretained(this)));
+      base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
+                 base::Unretained(this)));
 }
 
 void TraceEventTestFixture::OnTraceDataCollected(
     scoped_refptr<TraceLog::RefCountedString> json_events_str) {
+  AutoLock lock(lock_);
   trace_string_ += json_events_str->data;
 
   scoped_ptr<Value> root;
@@ -283,11 +286,11 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed,
   DictionaryValue* item = NULL;
 
 #define EXPECT_FIND_(string) \
-  EXPECT_TRUE((item = FindTraceEntry(trace_parsed, string)));
+    EXPECT_TRUE((item = FindTraceEntry(trace_parsed, string)));
 #define EXPECT_NOT_FIND_(string) \
-  EXPECT_FALSE((item = FindTraceEntry(trace_parsed, string)));
+    EXPECT_FALSE((item = FindTraceEntry(trace_parsed, string)));
 #define EXPECT_SUB_FIND_(string) \
-  if (item) EXPECT_TRUE((IsStringInDict(string, item)));
+    if (item) EXPECT_TRUE((IsStringInDict(string, item)));
 
   EXPECT_FIND_("ETW Trace Event");
   EXPECT_FIND_("all");
@@ -679,12 +682,12 @@ TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
   thread.Start();
 
   thread.message_loop()->PostTask(
-    FROM_HERE, NewRunnableFunction(&TraceWithAllMacroVariants,
-                                   &task_complete_event));
+      FROM_HERE, NewRunnableFunction(&TraceWithAllMacroVariants,
+                                     &task_complete_event));
   task_complete_event.Wait();
+  thread.Stop();
 
   TraceLog::GetInstance()->SetEnabled(false);
-  thread.Stop();
   ValidateAllTraceMacrosCreatedData(trace_parsed_, trace_string_);
 }
 
@@ -702,22 +705,22 @@ TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
     task_complete_events[i] = new WaitableEvent(false, false);
     threads[i]->Start();
     threads[i]->message_loop()->PostTask(
-      FROM_HERE, NewRunnableFunction(&TraceManyInstantEvents,
-                                     i, num_events, task_complete_events[i]));
+        FROM_HERE, NewRunnableFunction(&TraceManyInstantEvents,
+                                       i, num_events, task_complete_events[i]));
   }
 
   for (int i = 0; i < num_threads; i++) {
     task_complete_events[i]->Wait();
   }
 
-  TraceLog::GetInstance()->SetEnabled(false);
-
   for (int i = 0; i < num_threads; i++) {
     threads[i]->Stop();
     delete threads[i];
     delete task_complete_events[i];
   }
 
+  TraceLog::GetInstance()->SetEnabled(false);
+
   ValidateInstantEventPresentOnEveryThread(trace_parsed_, trace_string_,
                                            num_threads, num_events);
 }
@@ -745,21 +748,22 @@ TEST_F(TraceEventTestFixture, ThreadNames) {
     threads[i]->Start();
     thread_ids[i] = threads[i]->thread_id();
     threads[i]->message_loop()->PostTask(
-      FROM_HERE, NewRunnableFunction(&TraceManyInstantEvents,
-                                     i, num_events, task_complete_events[i]));
+        FROM_HERE, NewRunnableFunction(&TraceManyInstantEvents,
+                                       i, num_events, task_complete_events[i]));
   }
   for (int i = 0; i < num_threads; i++) {
     task_complete_events[i]->Wait();
   }
 
   // Shut things down.
-  TraceLog::GetInstance()->SetEnabled(false);
   for (int i = 0; i < num_threads; i++) {
     threads[i]->Stop();
     delete threads[i];
     delete task_complete_events[i];
   }
 
+  TraceLog::GetInstance()->SetEnabled(false);
+
   std::string tmp;
   int tmp_int;
   DictionaryValue* item;
diff --git a/base/location.h b/base/location.h
index fab8f4f..74a38eb 100644
--- a/base/location.h
+++ b/base/location.h
@@ -60,10 +60,10 @@ class BASE_EXPORT Location {
   void WriteFunctionName(std::string* output) const;
 
  private:
-  const char* const function_name_;
-  const char* const file_name_;
-  const int line_number_;
-  const void* const program_counter_;
+  const char* function_name_;
+  const char* file_name_;
+  int line_number_;
+  const void* program_counter_;
 };
 
 BASE_EXPORT const void* GetProgramCounter();
diff --git a/base/memory/singleton.h b/base/memory/singleton.h
index 10f0981..bc4684b 100644
--- a/base/memory/singleton.h
+++ b/base/memory/singleton.h
@@ -205,6 +205,9 @@ class Singleton {
   // method and call Singleton::get() from within that.
   friend Type* Type::GetInstance();
 
+  // Allow TraceLog tests to test tracing after OnExit.
+  friend class DeleteTraceLogForTesting;
+
   // This class is safe to be constructed and copy-constructed since it has no
   // member.
 
diff --git a/base/message_loop.cc b/base/message_loop.cc
index d96b57d..b4af87d 100644
--- a/base/message_loop.cc
+++ b/base/message_loop.cc
@@ -9,6 +9,7 @@
 #include "base/bind.h"
 #include "base/compiler_specific.h"
 #include "base/debug/alias.h"
+#include "base/debug/trace_event.h"
 #include "base/lazy_instance.h"
 #include "base/logging.h"
 #include "base/memory/scoped_ptr.h"
@@ -458,6 +459,9 @@ bool MessageLoop::ProcessNextDelayedNonNestableTask() {
 }
 
 void MessageLoop::RunTask(const PendingTask& pending_task) {
+  UNSHIPPED_TRACE_EVENT2("task", "MessageLoop::RunTask",
+                         "src_file", pending_task.posted_from.file_name(),
+                         "src_func", pending_task.posted_from.function_name());
   DCHECK(nestable_tasks_allowed_);
   // Execute the task and assume the worst: It is probably not reentrant.
   nestable_tasks_allowed_ = false;
@@ -467,7 +471,8 @@ void MessageLoop::RunTask(const PendingTask& pending_task) {
   // crashes. Be careful not to assume that the variable itself will have the
   // expected value when displayed by the optimizer in an optimized build.
   // Look at a memory dump of the stack.
-  const void* program_counter = pending_task.birth_program_counter;
+  const void* program_counter =
+      pending_task.posted_from.program_counter();
   base::debug::Alias(&program_counter);
 
   HistogramEvent(kTaskRunEvent);
@@ -765,9 +770,9 @@ MessageLoop::PendingTask::PendingTask(
     : task(task),
       time_posted(TimeTicks::Now()),
       delayed_run_time(delayed_run_time),
+      posted_from(posted_from),
       sequence_num(0),
-      nestable(nestable),
-      birth_program_counter(posted_from.program_counter()) {
+      nestable(nestable) {
 #if defined(TRACK_ALL_TASK_OBJECTS)
   post_births = tracked_objects::ThreadData::TallyABirthIfActive(posted_from);
 #endif  // defined(TRACK_ALL_TASK_OBJECTS)
diff --git a/base/message_loop.h b/base/message_loop.h
index 67980ea..fffcd2f 100644
--- a/base/message_loop.h
+++ b/base/message_loop.h
@@ -430,14 +430,14 @@ class BASE_EXPORT MessageLoop : public base::MessagePump::Delegate {
     // The time when the task should be run.
     base::TimeTicks delayed_run_time;
 
+    // The site this PendingTask was posted from.
+    tracked_objects::Location posted_from;
+
     // Secondary sort key for run time.
     int sequence_num;
 
     // OK to dispatch from a nested loop.
     bool nestable;
-
-    // The site this PendingTask was posted from.
-    const void* birth_program_counter;
   };
 
   class TaskQueue : public std::queue<PendingTask> {
diff --git a/base/threading/worker_pool_posix.cc b/base/threading/worker_pool_posix.cc
index c3a382c..3a4408c 100644
--- a/base/threading/worker_pool_posix.cc
+++ b/base/threading/worker_pool_posix.cc
@@ -5,6 +5,7 @@
 #include "base/threading/worker_pool_posix.h"
 
 #include "base/bind.h"
+#include "base/debug/trace_event.h"
 #include "base/lazy_instance.h"
 #include "base/logging.h"
 #include "base/memory/ref_counted.h"
@@ -83,6 +84,9 @@ void WorkerThread::ThreadMain() {
     PosixDynamicThreadPool::PendingTask pending_task = pool_->WaitForTask();
     if (pending_task.task.is_null())
       break;
+    UNSHIPPED_TRACE_EVENT2("task", "WorkerThread::ThreadMain::Run",
+        "src_file", pending_task.posted_from.file_name(),
+        "src_func", pending_task.posted_from.function_name());
     pending_task.task.Run();
   }
 
@@ -107,7 +111,8 @@ bool WorkerPool::PostTask(const tracked_objects::Location& from_here,
 PosixDynamicThreadPool::PendingTask::PendingTask(
     const tracked_objects::Location& posted_from,
     const base::Closure& task)
-    : task(task) {
+    : posted_from(posted_from),
+      task(task) {
 }
 
 PosixDynamicThreadPool::PendingTask::~PendingTask() {
diff --git a/base/threading/worker_pool_posix.h b/base/threading/worker_pool_posix.h
index 990f50a..59593e2 100644
--- a/base/threading/worker_pool_posix.h
+++ b/base/threading/worker_pool_posix.h
@@ -55,6 +55,8 @@ class BASE_EXPORT PosixDynamicThreadPool
     // tracked_objects::TallyADeathIfActive() and
     // tracked_objects::TallyABirthIfActive correctly.
 
+    const tracked_objects::Location posted_from;
+
     // The task to run.
     base::Closure task;
   };
diff --git a/base/threading/worker_pool_win.cc b/base/threading/worker_pool_win.cc
index 2aa423f..b7eaad1 100644
--- a/base/threading/worker_pool_win.cc
+++ b/base/threading/worker_pool_win.cc
@@ -5,6 +5,7 @@
 #include "base/threading/worker_pool.h"
 
 #include "base/bind.h"
+#include "base/debug/trace_event.h"
 #include "base/logging.h"
 #include "base/task.h"
 #include "base/tracked_objects.h"
@@ -17,7 +18,8 @@ struct PendingTask {
   PendingTask(
       const tracked_objects::Location& posted_from,
       const base::Closure& task)
-      : task(task) {
+      : posted_from(posted_from),
+        task(task) {
 #if defined(TRACK_ALL_TASK_OBJECTS)
     post_births = tracked_objects::ThreadData::TallyABirthIfActive(posted_from);
     time_posted = TimeTicks::Now();
@@ -32,12 +34,18 @@ struct PendingTask {
   TimeTicks time_posted;
 #endif  // defined(TRACK_ALL_TASK_OBJECTS)
 
+  // The site this PendingTask was posted from.
+  tracked_objects::Location posted_from;
+
   // The task to run.
   base::Closure task;
 };
 
 DWORD CALLBACK WorkItemCallback(void* param) {
   PendingTask* pending_task = static_cast<PendingTask*>(param);
+  UNSHIPPED_TRACE_EVENT2("task", "WorkItemCallback::Run",
+                         "src_file", pending_task->posted_from.file_name(),
+                         "src_func", pending_task->posted_from.function_name());
   pending_task->task.Run();
 #if defined(TRACK_ALL_TASK_OBJECTS)
   tracked_objects::ThreadData::TallyADeathIfActive(
diff --git a/chrome/browser/sync/profile_sync_service.cc b/chrome/browser/sync/profile_sync_service.cc
index 5be5a23..17cf14a 100644
--- a/chrome/browser/sync/profile_sync_service.cc
+++ b/chrome/browser/sync/profile_sync_service.cc
@@ -565,7 +565,7 @@ void ProfileSyncService::NotifyObservers() {
 void ProfileSyncService::ClearStaleErrors() {
   unrecoverable_error_detected_ = false;
   unrecoverable_error_message_.clear();
-  unrecoverable_error_location_.reset();
+  unrecoverable_error_location_ = tracked_objects::Location();
   last_actionable_error_ = SyncProtocolError();
 }
 
@@ -644,11 +644,7 @@ void ProfileSyncService::OnUnrecoverableError(
     const std::string& message) {
   unrecoverable_error_detected_ = true;
   unrecoverable_error_message_ = message;
-  unrecoverable_error_location_.reset(
-      new tracked_objects::Location(from_here.function_name(),
-                                    from_here.file_name(),
-                                    from_here.line_number(),
-                                    from_here.program_counter()));
+  unrecoverable_error_location_ = from_here;
 
   // Tell the wizard so it can inform the user only if it is already open.
   wizard_.Step(SyncSetupWizard::FATAL_ERROR);
diff --git a/chrome/browser/sync/profile_sync_service.h b/chrome/browser/sync/profile_sync_service.h
index 1cdd662..1f45e1f 100644
--- a/chrome/browser/sync/profile_sync_service.h
+++ b/chrome/browser/sync/profile_sync_service.h
@@ -293,8 +293,7 @@ class ProfileSyncService : public browser_sync::SyncFrontend,
     return unrecoverable_error_message_;
   }
   tracked_objects::Location unrecoverable_error_location() {
-    return unrecoverable_error_location_.get() ?
-        *unrecoverable_error_location_.get() : tracked_objects::Location();
+    return unrecoverable_error_location_;
   }
 
   bool UIShouldDepictAuthInProgress() const {
@@ -613,7 +612,7 @@ class ProfileSyncService : public browser_sync::SyncFrontend,
 
   // A message sent when an unrecoverable error occurred.
   std::string unrecoverable_error_message_;
-  scoped_ptr<tracked_objects::Location> unrecoverable_error_location_;
+  tracked_objects::Location unrecoverable_error_location_;
 
   // Manages the start and stop of the various data types.
   scoped_ptr<browser_sync::DataTypeManager> data_type_manager_;