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
CrOS-Libchrome-Original-Commit: 19d8a90fbc1fd7c26a873dc84fcbc875c509cf11
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 @@
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::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 @@
// 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
// 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 @@
}
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 @@
// 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 @@
: 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 @@
// 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 @@
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 @@
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 @@
// tracked_objects::TallyADeathIfActive() and
// tracked_objects::TallyABirthIfActive correctly.
+ const tracked_objects::Location posted_from;
+
// The task to run.
base::Closure task;
};