diff options
-rw-r--r-- | base/debug/trace_event_impl.cc | 155 | ||||
-rw-r--r-- | base/debug/trace_event_impl.h | 77 | ||||
-rw-r--r-- | base/debug/trace_event_unittest.cc | 152 | ||||
-rw-r--r-- | base/test/trace_event_analyzer_unittest.cc | 9 | ||||
-rw-r--r-- | chrome/chrome_tests.gypi | 1 | ||||
-rw-r--r-- | chrome/test/base/tracing.cc | 80 | ||||
-rw-r--r-- | chrome/test/base/tracing.h | 24 | ||||
-rw-r--r-- | chrome/test/base/tracing_browsertest.cc | 88 | ||||
-rw-r--r-- | content/browser/trace_controller_impl.cc | 77 | ||||
-rw-r--r-- | content/browser/trace_controller_impl.h | 12 | ||||
-rw-r--r-- | content/browser/trace_message_filter.cc | 17 | ||||
-rw-r--r-- | content/browser/trace_message_filter.h | 5 | ||||
-rw-r--r-- | content/common/child_process_messages.h | 11 | ||||
-rw-r--r-- | content/common/child_trace_message_filter.cc | 57 | ||||
-rw-r--r-- | content/common/child_trace_message_filter.h | 5 | ||||
-rw-r--r-- | content/public/browser/trace_controller.h | 10 | ||||
-rw-r--r-- | content/public/browser/trace_subscriber.h | 5 | ||||
-rw-r--r-- | content/renderer/render_view_impl.cc | 3 |
18 files changed, 626 insertions, 162 deletions
diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc index 9cf3341..13b6a97 100644 --- a/base/debug/trace_event_impl.cc +++ b/base/debug/trace_event_impl.cc @@ -7,21 +7,23 @@ #include <algorithm> #include "base/bind.h" +#include "base/debug/leak_annotations.h" #include "base/debug/trace_event.h" #include "base/file_util.h" #include "base/format_macros.h" #include "base/lazy_instance.h" #include "base/memory/singleton.h" #include "base/process_util.h" +#include "base/stl_util.h" #include "base/stringprintf.h" #include "base/string_tokenizer.h" -#include "base/threading/platform_thread.h" -#include "base/threading/thread_local.h" -#include "base/utf_string_conversions.h" -#include "base/stl_util.h" +#include "base/string_util.h" #include "base/sys_info.h" #include "base/third_party/dynamic_annotations/dynamic_annotations.h" +#include "base/threading/platform_thread.h" +#include "base/threading/thread_local.h" #include "base/time.h" +#include "base/utf_string_conversions.h" #if defined(OS_WIN) #include "base/debug/trace_event_win.h" @@ -316,14 +318,37 @@ void TraceResultBuffer::Finish() { // //////////////////////////////////////////////////////////////////////////////// +TraceLog::NotificationHelper::NotificationHelper(TraceLog* trace_log) + : trace_log_(trace_log), + notification_(0) { +} + +TraceLog::NotificationHelper::~NotificationHelper() { +} + +void TraceLog::NotificationHelper::AddNotificationWhileLocked( + int notification) { + if (trace_log_->notification_callback_.is_null()) + return; + if (notification_ == 0) + callback_copy_ = trace_log_->notification_callback_; + notification_ |= notification; +} + +void TraceLog::NotificationHelper::SendNotificationIfAny() { + if (notification_) + callback_copy_.Run(notification_); +} + // static TraceLog* TraceLog::GetInstance() { return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get(); } TraceLog::TraceLog() - : enabled_(false) - , dispatching_to_observer_list_(false) { + : enabled_(false), + dispatching_to_observer_list_(false), + watch_category_(NULL) { // Trace is enabled or disabled on one thread while other threads are // accessing the enabled flag. We don't care whether edge-case events are // traced or not, so we allow races on the enabled flag to keep the trace @@ -406,7 +431,11 @@ const unsigned char* TraceLog::GetCategoryEnabledInternal(const char* name) { "must increase TRACE_EVENT_MAX_CATEGORIES"; if (g_category_index < TRACE_EVENT_MAX_CATEGORIES) { int new_index = g_category_index++; - g_categories[new_index] = name; + // Don't hold on to the name pointer, so that we can create categories with + // strings not known at compile time (this is required by SetWatchEvent). + const char* new_name = base::strdup(name); + ANNOTATE_LEAKING_OBJECT_PTR(new_name); + g_categories[new_index] = new_name; DCHECK(!g_category_enabled[new_index]); if (enabled_) { // Note that if both included and excluded_categories are empty, the else @@ -491,31 +520,30 @@ void TraceLog::GetEnabledTraceCategories( } void TraceLog::SetDisabled() { - { - AutoLock lock(lock_); - if (!enabled_) - return; + AutoLock lock(lock_); + if (!enabled_) + return; - if (dispatching_to_observer_list_) { - DLOG(ERROR) - << "Cannot manipulate TraceLog::Enabled state from an observer."; - return; - } + if (dispatching_to_observer_list_) { + DLOG(ERROR) + << "Cannot manipulate TraceLog::Enabled state from an observer."; + return; + } - dispatching_to_observer_list_ = true; - FOR_EACH_OBSERVER(EnabledStateChangedObserver, enabled_state_observer_list_, - OnTraceLogWillDisable()); - dispatching_to_observer_list_ = false; - - enabled_ = false; - included_categories_.clear(); - excluded_categories_.clear(); - for (int i = 0; i < g_category_index; i++) - g_category_enabled[i] = 0; - AddThreadNameMetadataEvents(); - AddClockSyncMetadataEvents(); - } // release lock - Flush(); + dispatching_to_observer_list_ = true; + FOR_EACH_OBSERVER(EnabledStateChangedObserver, enabled_state_observer_list_, + OnTraceLogWillDisable()); + dispatching_to_observer_list_ = false; + + enabled_ = false; + included_categories_.clear(); + excluded_categories_.clear(); + watch_category_ = NULL; + watch_event_name_ = ""; + for (int i = 0; i < g_category_index; i++) + g_category_enabled[i] = 0; + AddThreadNameMetadataEvents(); + AddClockSyncMetadataEvents(); } void TraceLog::SetEnabled(bool enabled) { @@ -538,28 +566,19 @@ float TraceLog::GetBufferPercentFull() const { return (float)((double)logged_events_.size()/(double)kTraceEventBufferSize); } -void TraceLog::SetOutputCallback(const TraceLog::OutputCallback& cb) { +void TraceLog::SetNotificationCallback( + const TraceLog::NotificationCallback& cb) { AutoLock lock(lock_); - output_callback_ = cb; + notification_callback_ = cb; } -void TraceLog::SetBufferFullCallback(const TraceLog::BufferFullCallback& cb) { - AutoLock lock(lock_); - buffer_full_callback_ = cb; -} - -void TraceLog::Flush() { +void TraceLog::Flush(const TraceLog::OutputCallback& cb) { std::vector<TraceEvent> previous_logged_events; - OutputCallback output_callback_copy; { AutoLock lock(lock_); previous_logged_events.swap(logged_events_); - output_callback_copy = output_callback_; } // release lock - if (output_callback_copy.is_null()) - return; - for (size_t i = 0; i < previous_logged_events.size(); i += kTraceEventBatchSize) { @@ -569,7 +588,7 @@ void TraceLog::Flush() { i, kTraceEventBatchSize, &(json_events_str_ptr->data())); - output_callback_copy.Run(json_events_str_ptr); + cb.Run(json_events_str_ptr); } } @@ -586,7 +605,7 @@ int TraceLog::AddTraceEvent(char phase, unsigned char flags) { DCHECK(name); TimeTicks now = TimeTicks::NowFromSystemTraceTime(); - BufferFullCallback buffer_full_callback_copy; + NotificationHelper notifier(this); int ret_begin_id = -1; { AutoLock lock(lock_); @@ -652,13 +671,14 @@ int TraceLog::AddTraceEvent(char phase, num_args, arg_names, arg_types, arg_values, flags)); - if (logged_events_.size() == kTraceEventBufferSize) { - buffer_full_callback_copy = buffer_full_callback_; - } + if (logged_events_.size() == kTraceEventBufferSize) + notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL); + + if (watch_category_ == category_enabled && watch_event_name_ == name) + notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); } // release lock - if (!buffer_full_callback_copy.is_null()) - buffer_full_callback_copy.Run(); + notifier.SendNotificationIfAny(); return ret_begin_id; } @@ -686,6 +706,41 @@ void TraceLog::AddTraceEventEtw(char phase, TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); } +void TraceLog::SetWatchEvent(const std::string& category_name, + const std::string& event_name) { + const unsigned char* category = GetCategoryEnabled(category_name.c_str()); + int notify_count = 0; + { + AutoLock lock(lock_); + watch_category_ = category; + watch_event_name_ = event_name; + + // First, search existing events for watch event because we want to catch it + // even if it has already occurred. + for (size_t i = 0u; i < logged_events_.size(); ++i) { + if (category == logged_events_[i].category_enabled() && + strcmp(event_name.c_str(), logged_events_[i].name()) == 0) { + ++notify_count; + } + } + } // release lock + + // Send notification for each event found. + for (int i = 0; i < notify_count; ++i) { + NotificationHelper notifier(this); + lock_.Acquire(); + notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); + lock_.Release(); + notifier.SendNotificationIfAny(); + } +} + +void TraceLog::CancelWatchEvent() { + AutoLock lock(lock_); + watch_category_ = NULL; + watch_event_name_ = ""; +} + void TraceLog::AddClockSyncMetadataEvents() { #if defined(OS_ANDROID) // Since Android does not support sched_setaffinity, we cannot establish clock diff --git a/base/debug/trace_event_impl.h b/base/debug/trace_event_impl.h index ca711db..62a81d8 100644 --- a/base/debug/trace_event_impl.h +++ b/base/debug/trace_event_impl.h @@ -16,6 +16,7 @@ #include "base/memory/ref_counted_memory.h" #include "base/observer_list.h" #include "base/string_util.h" +#include "base/synchronization/condition_variable.h" #include "base/synchronization/lock.h" #include "base/timer.h" @@ -89,6 +90,7 @@ class BASE_EXPORT TraceEvent { return parameter_copy_storage_.get(); } + const unsigned char* category_enabled() const { return category_enabled_; } const char* name() const { return name_; } private: @@ -154,6 +156,16 @@ class BASE_EXPORT TraceResultBuffer { class BASE_EXPORT TraceLog { public: + // Notification is a mask of one or more of the following events. + enum Notification { + // The trace buffer does not flush dynamically, so when it fills up, + // subsequent trace events will be dropped. This callback is generated when + // the trace buffer is full. The callback must be thread safe. + TRACE_BUFFER_FULL = 1 << 0, + // A subscribed trace-event occurred. + EVENT_WATCH_NOTIFICATION = 1 << 1 + }; + static TraceLog* GetInstance(); // Get set of known categories. This can change as new code paths are reached. @@ -213,23 +225,21 @@ class BASE_EXPORT TraceLog { float GetBufferPercentFull() const; - // When enough events are collected, they are handed (in bulk) to - // the output callback. If no callback is set, the output will be - // silently dropped. The callback must be thread safe. The string format is + // Set the thread-safe notification callback. The callback can occur at any + // time and from any thread. WARNING: It is possible for the previously set + // callback to be called during OR AFTER a call to SetNotificationCallback. + // Therefore, the target of the callback must either be a global function, + // ref-counted object or a LazyInstance with Leaky traits (or equivalent). + typedef base::Callback<void(int)> NotificationCallback; + void SetNotificationCallback(const NotificationCallback& cb); + + // Flush all collected events to the given output callback. The callback will + // be called one or more times with IPC-bite-size chunks. The string format is // undefined. Use TraceResultBuffer to convert one or more trace strings to // JSON. typedef base::Callback<void(const scoped_refptr<base::RefCountedString>&)> OutputCallback; - void SetOutputCallback(const OutputCallback& cb); - - // The trace buffer does not flush dynamically, so when it fills up, - // subsequent trace events will be dropped. This callback is generated when - // the trace buffer is full. The callback must be thread safe. - typedef base::Callback<void(void)> BufferFullCallback; - void SetBufferFullCallback(const BufferFullCallback& cb); - - // Flushes all logged data to the callback. - void Flush(); + void Flush(const OutputCallback& cb); // Called by TRACE_EVENT* macros, don't call this directly. static const unsigned char* GetCategoryEnabled(const char* name); @@ -263,6 +273,16 @@ class BASE_EXPORT TraceLog { const void* id, const std::string& extra); + // For every matching event, a notification will be fired. NOTE: the + // notification will fire for each matching event that has already occurred + // since tracing was started (including before tracing if the process was + // started with tracing turned on). + void SetWatchEvent(const std::string& category_name, + const std::string& event_name); + // Cancel the watch event. If tracing is enabled, this may race with the + // watch event notification firing. + void CancelWatchEvent(); + int process_id() const { return process_id_; } // Exposed for unittesting: @@ -287,6 +307,29 @@ class BASE_EXPORT TraceLog { // by the Singleton class. friend struct StaticMemorySingletonTraits<TraceLog>; + // Helper class for managing notification_thread_count_ and running + // notification callbacks. This is very similar to a reader-writer lock, but + // shares the lock with TraceLog and manages the notification flags. + class NotificationHelper { + public: + inline explicit NotificationHelper(TraceLog* trace_log); + inline ~NotificationHelper(); + + // Called only while TraceLog::lock_ is held. This ORs the given + // notification with any existing notifcations. + inline void AddNotificationWhileLocked(int notification); + + // Called only while TraceLog::lock_ is NOT held. If there are any pending + // notifications from previous calls to AddNotificationWhileLocked, this + // will call the NotificationCallback. + inline void SendNotificationIfAny(); + + private: + TraceLog* trace_log_; + NotificationCallback callback_copy_; + int notification_; + }; + TraceLog(); ~TraceLog(); const unsigned char* GetCategoryEnabledInternal(const char* name); @@ -295,10 +338,10 @@ class BASE_EXPORT TraceLog { // TODO(nduca): switch to per-thread trace buffers to reduce thread // synchronization. + // This lock protects TraceLog member accesses from arbitrary threads. Lock lock_; bool enabled_; - OutputCallback output_callback_; - BufferFullCallback buffer_full_callback_; + NotificationCallback notification_callback_; std::vector<TraceEvent> logged_events_; std::vector<std::string> included_categories_; std::vector<std::string> excluded_categories_; @@ -312,6 +355,10 @@ class BASE_EXPORT TraceLog { int process_id_; + // Allow tests to wake up when certain events occur. + const unsigned char* watch_category_; + std::string watch_event_name_; + DISALLOW_COPY_AND_ASSIGN(TraceLog); }; diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc index f806cf1..1f358fb 100644 --- a/base/debug/trace_event_unittest.cc +++ b/base/debug/trace_event_unittest.cc @@ -46,6 +46,10 @@ class TraceEventTestFixture : public testing::Test { void ManualTestSetUp(); void OnTraceDataCollected( const scoped_refptr<base::RefCountedString>& events_str); + void OnTraceNotification(int notification) { + if (notification & TraceLog::EVENT_WATCH_NOTIFICATION) + ++event_watch_notification_; + } DictionaryValue* FindMatchingTraceEntry(const JsonKeyValue* key_values); DictionaryValue* FindNamePhase(const char* name, const char* phase); DictionaryValue* FindNamePhaseKeyValue(const char* name, @@ -61,6 +65,18 @@ class TraceEventTestFixture : public testing::Test { json_output_.json_output.clear(); } + void BeginTrace() { + event_watch_notification_ = 0; + TraceLog::GetInstance()->SetEnabled("*"); + } + + void EndTraceAndFlush() { + TraceLog::GetInstance()->SetDisabled(); + TraceLog::GetInstance()->Flush( + base::Bind(&TraceEventTestFixture::OnTraceDataCollected, + base::Unretained(this))); + } + virtual void SetUp() OVERRIDE { old_thread_name_ = PlatformThread::GetName(); } @@ -74,6 +90,7 @@ class TraceEventTestFixture : public testing::Test { ListValue trace_parsed_; base::debug::TraceResultBuffer trace_buffer_; base::debug::TraceResultBuffer::SimpleOutput json_output_; + int event_watch_notification_; private: // We want our singleton torn down after each test. @@ -87,8 +104,8 @@ void TraceEventTestFixture::ManualTestSetUp() { TraceLog* tracelog = TraceLog::GetInstance(); ASSERT_TRUE(tracelog); ASSERT_FALSE(tracelog->IsEnabled()); - tracelog->SetOutputCallback( - base::Bind(&TraceEventTestFixture::OnTraceDataCollected, + tracelog->SetNotificationCallback( + base::Bind(&TraceEventTestFixture::OnTraceNotification, base::Unretained(this))); trace_buffer_.SetOutputCallback(json_output_.GetCallback()); } @@ -650,7 +667,7 @@ TEST_F(TraceEventTestFixture, DataCaptured) { TraceWithAllMacroVariants(NULL); - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); ValidateAllTraceMacrosCreatedData(trace_parsed_); } @@ -741,10 +758,10 @@ TEST_F(TraceEventTestFixture, Categories) { // enabled or disabled when the trace event was encountered. TRACE_EVENT_INSTANT0("c1", "name"); TRACE_EVENT_INSTANT0("c2", "name"); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); TRACE_EVENT_INSTANT0("c3", "name"); TRACE_EVENT_INSTANT0("c4", "name"); - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); std::vector<std::string> cats; TraceLog::GetInstance()->GetKnownCategories(&cats); EXPECT_TRUE(std::find(cats.begin(), cats.end(), "c1") != cats.end()); @@ -765,7 +782,7 @@ TEST_F(TraceEventTestFixture, Categories) { TraceLog::GetInstance()->SetEnabled(included_categories, empty_categories); TRACE_EVENT_INSTANT0("cat1", "name"); TRACE_EVENT_INSTANT0("cat2", "name"); - TraceLog::GetInstance()->SetDisabled(); + EndTraceAndFlush(); EXPECT_TRUE(trace_parsed_.empty()); // Include existent category -> only events of that category @@ -775,7 +792,7 @@ TEST_F(TraceEventTestFixture, Categories) { TraceLog::GetInstance()->SetEnabled(included_categories, empty_categories); TRACE_EVENT_INSTANT0("inc", "name"); TRACE_EVENT_INSTANT0("inc2", "name"); - TraceLog::GetInstance()->SetDisabled(); + EndTraceAndFlush(); EXPECT_TRUE(FindMatchingValue("cat", "inc")); EXPECT_FALSE(FindNonMatchingValue("cat", "inc")); @@ -791,7 +808,7 @@ TEST_F(TraceEventTestFixture, Categories) { TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "not_inc"); TRACE_EVENT_INSTANT0("cat1", "not_inc"); TRACE_EVENT_INSTANT0("cat2", "not_inc"); - TraceLog::GetInstance()->SetDisabled(); + EndTraceAndFlush(); EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_abc")); EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_")); EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_x_end")); @@ -806,7 +823,7 @@ TEST_F(TraceEventTestFixture, Categories) { TraceLog::GetInstance()->SetEnabled(empty_categories, excluded_categories); TRACE_EVENT_INSTANT0("cat1", "name"); TRACE_EVENT_INSTANT0("cat2", "name"); - TraceLog::GetInstance()->SetDisabled(); + EndTraceAndFlush(); EXPECT_TRUE(FindMatchingValue("cat", "cat1")); EXPECT_TRUE(FindMatchingValue("cat", "cat2")); @@ -817,7 +834,7 @@ TEST_F(TraceEventTestFixture, Categories) { TraceLog::GetInstance()->SetEnabled(empty_categories, excluded_categories); TRACE_EVENT_INSTANT0("inc", "name"); TRACE_EVENT_INSTANT0("inc2", "name"); - TraceLog::GetInstance()->SetDisabled(); + EndTraceAndFlush(); EXPECT_TRUE(FindMatchingValue("cat", "inc2")); EXPECT_FALSE(FindMatchingValue("cat", "inc")); @@ -833,7 +850,7 @@ TEST_F(TraceEventTestFixture, Categories) { TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "included"); TRACE_EVENT_INSTANT0("cat1", "included"); TRACE_EVENT_INSTANT0("cat2", "included"); - TraceLog::GetInstance()->SetDisabled(); + EndTraceAndFlush(); EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_bla_end")); EXPECT_TRUE(FindMatchingValue("cat", "cat1")); EXPECT_TRUE(FindMatchingValue("cat", "cat2")); @@ -843,7 +860,7 @@ TEST_F(TraceEventTestFixture, Categories) { // Simple Test for time threshold events. TEST_F(TraceEventTestFixture, DataCapturedThreshold) { ManualTestSetUp(); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); // Test that events at the same level are properly filtered by threshold. { @@ -910,7 +927,7 @@ TEST_F(TraceEventTestFixture, DataCapturedThreshold) { } } - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); #define EXPECT_FIND_BE_(str) \ EXPECT_TRUE(FindNamePhase(str, "B")); \ @@ -943,10 +960,69 @@ TEST_F(TraceEventTestFixture, DataCapturedThreshold) { EXPECT_NOT_FIND_BE_("4thresholdlong2"); } +// Test EVENT_WATCH_NOTIFICATION +TEST_F(TraceEventTestFixture, EventWatchNotification) { + ManualTestSetUp(); + + // Basic one occurrence. + BeginTrace(); + TraceLog::GetInstance()->SetWatchEvent("cat", "event"); + TRACE_EVENT_INSTANT0("cat", "event"); + EndTraceAndFlush(); + EXPECT_EQ(event_watch_notification_, 1); + + // Basic one occurrence before Set. + BeginTrace(); + TRACE_EVENT_INSTANT0("cat", "event"); + TraceLog::GetInstance()->SetWatchEvent("cat", "event"); + EndTraceAndFlush(); + EXPECT_EQ(event_watch_notification_, 1); + + // Auto-reset after end trace. + BeginTrace(); + TraceLog::GetInstance()->SetWatchEvent("cat", "event"); + EndTraceAndFlush(); + BeginTrace(); + TRACE_EVENT_INSTANT0("cat", "event"); + EndTraceAndFlush(); + EXPECT_EQ(event_watch_notification_, 0); + + // Multiple occurrence. + BeginTrace(); + int num_occurrences = 5; + TraceLog::GetInstance()->SetWatchEvent("cat", "event"); + for (int i = 0; i < num_occurrences; ++i) + TRACE_EVENT_INSTANT0("cat", "event"); + EndTraceAndFlush(); + EXPECT_EQ(event_watch_notification_, num_occurrences); + + // Wrong category. + BeginTrace(); + TraceLog::GetInstance()->SetWatchEvent("cat", "event"); + TRACE_EVENT_INSTANT0("wrong_cat", "event"); + EndTraceAndFlush(); + EXPECT_EQ(event_watch_notification_, 0); + + // Wrong name. + BeginTrace(); + TraceLog::GetInstance()->SetWatchEvent("cat", "event"); + TRACE_EVENT_INSTANT0("cat", "wrong_event"); + EndTraceAndFlush(); + EXPECT_EQ(event_watch_notification_, 0); + + // Canceled. + BeginTrace(); + TraceLog::GetInstance()->SetWatchEvent("cat", "event"); + TraceLog::GetInstance()->CancelWatchEvent(); + TRACE_EVENT_INSTANT0("cat", "event"); + EndTraceAndFlush(); + EXPECT_EQ(event_watch_notification_, 0); +} + // Test ASYNC_BEGIN/END events TEST_F(TraceEventTestFixture, AsyncBeginEndEvents) { ManualTestSetUp(); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); unsigned long long id = 0xfeedbeeffeedbeefull; TRACE_EVENT_ASYNC_BEGIN0( "cat", "name1", id); @@ -955,7 +1031,7 @@ TEST_F(TraceEventTestFixture, AsyncBeginEndEvents) { TRACE_EVENT_BEGIN0( "cat", "name2"); TRACE_EVENT_ASYNC_BEGIN0( "cat", "name3", 0); - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); EXPECT_TRUE(FindNamePhase("name1", "S")); EXPECT_TRUE(FindNamePhase("name1", "T")); @@ -980,15 +1056,15 @@ TEST_F(TraceEventTestFixture, AsyncBeginEndPointerMangling) { void* ptr = this; TraceLog::GetInstance()->SetProcessID(100); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); TRACE_EVENT_ASYNC_BEGIN0( "cat", "name1", ptr); TRACE_EVENT_ASYNC_BEGIN0( "cat", "name2", ptr); - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); TraceLog::GetInstance()->SetProcessID(200); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); TRACE_EVENT_ASYNC_END0( "cat", "name1", ptr); - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); DictionaryValue* async_begin = FindNamePhase("name1", "S"); DictionaryValue* async_begin2 = FindNamePhase("name2", "S"); @@ -1017,11 +1093,11 @@ TEST_F(TraceEventTestFixture, StaticStringVsString) { ManualTestSetUp(); TraceLog* tracer = TraceLog::GetInstance(); // Make sure old events are flushed: - tracer->SetEnabled(false); + EndTraceAndFlush(); EXPECT_EQ(0u, tracer->GetEventsSize()); { - tracer->SetEnabled(true); + BeginTrace(); // Test that string arguments are copied. TRACE_EVENT2("cat", "name1", "arg1", std::string("argval"), "arg2", std::string("argval")); @@ -1039,11 +1115,11 @@ TEST_F(TraceEventTestFixture, StaticStringVsString) { EXPECT_TRUE(event2.parameter_copy_storage() != NULL); EXPECT_GT(event1.parameter_copy_storage()->size(), 0u); EXPECT_GT(event2.parameter_copy_storage()->size(), 0u); - tracer->SetEnabled(false); + EndTraceAndFlush(); } { - tracer->SetEnabled(true); + BeginTrace(); // Test that static literal string arguments are not copied. TRACE_EVENT2("cat", "name1", "arg1", "argval", "arg2", "argval"); @@ -1061,14 +1137,14 @@ TEST_F(TraceEventTestFixture, StaticStringVsString) { EXPECT_STREQ("name2", event2.name()); EXPECT_TRUE(event1.parameter_copy_storage() == NULL); EXPECT_TRUE(event2.parameter_copy_storage() == NULL); - tracer->SetEnabled(false); + EndTraceAndFlush(); } } // Test that data sent from other threads is gathered TEST_F(TraceEventTestFixture, DataCapturedOnThread) { ManualTestSetUp(); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); Thread thread("1"); WaitableEvent task_complete_event(false, false); @@ -1079,14 +1155,14 @@ TEST_F(TraceEventTestFixture, DataCapturedOnThread) { task_complete_event.Wait(); thread.Stop(); - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); ValidateAllTraceMacrosCreatedData(trace_parsed_); } // Test that data sent from multiple threads is gathered TEST_F(TraceEventTestFixture, DataCapturedManyThreads) { ManualTestSetUp(); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); const int num_threads = 4; const int num_events = 4000; @@ -1111,7 +1187,7 @@ TEST_F(TraceEventTestFixture, DataCapturedManyThreads) { delete task_complete_events[i]; } - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); ValidateInstantEventPresentOnEveryThread(trace_parsed_, num_threads, num_events); @@ -1131,7 +1207,7 @@ TEST_F(TraceEventTestFixture, ThreadNames) { threads[i] = new Thread(StringPrintf("Thread %d", i).c_str()); // Enable tracing. - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); // Now run some trace code on these threads. WaitableEvent* task_complete_events[num_threads]; @@ -1154,7 +1230,7 @@ TEST_F(TraceEventTestFixture, ThreadNames) { delete task_complete_events[i]; } - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); std::string tmp; int tmp_int; @@ -1190,7 +1266,7 @@ TEST_F(TraceEventTestFixture, ThreadNames) { TEST_F(TraceEventTestFixture, ThreadNameChanges) { ManualTestSetUp(); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); PlatformThread::SetName(""); TRACE_EVENT_INSTANT0("drink", "water"); @@ -1208,7 +1284,7 @@ TEST_F(TraceEventTestFixture, ThreadNameChanges) { PlatformThread::SetName(" bar"); TRACE_EVENT_INSTANT0("drink", "whisky"); - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); std::vector<const DictionaryValue*> items = FindTraceEntries(trace_parsed_, "thread_name"); @@ -1247,14 +1323,14 @@ TEST_F(TraceEventTestFixture, AtExit) { TRACE_EVENT_INSTANT0("all", "not recorded; system not enabled"); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); TRACE_EVENT_INSTANT0("all", "is recorded 1; system has been enabled"); // Trace calls that will cache pointers to categories; they're valid here TraceCallsWithCachedCategoryPointersPointers( "is recorded 2; system has been enabled"); - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); } // scope to destroy singleton ASSERT_FALSE(TraceLog::GetInstance()); @@ -1295,14 +1371,14 @@ TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) { std::string name_string("event name"); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); TRACE_EVENT_INSTANT0("category", name_string.c_str()); // Modify the string in place (a wholesale reassignment may leave the old // string intact on the heap). name_string[0] = '@'; - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name")); EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str())); @@ -1322,7 +1398,7 @@ TEST_F(TraceEventTestFixture, DeepCopy) { std::string val1("val1"); std::string val2("val2"); - TraceLog::GetInstance()->SetEnabled(true); + BeginTrace(); TRACE_EVENT_COPY_INSTANT0("category", name1.c_str()); TRACE_EVENT_COPY_BEGIN1("category", name2.c_str(), arg1.c_str(), 5); @@ -1333,7 +1409,7 @@ TEST_F(TraceEventTestFixture, DeepCopy) { // As per NormallyNoDeepCopy, modify the strings in place. name1[0] = name2[0] = name3[0] = arg1[0] = arg2[0] = val1[0] = val2[0] = '@'; - TraceLog::GetInstance()->SetEnabled(false); + EndTraceAndFlush(); EXPECT_FALSE(FindTraceEntry(trace_parsed_, name1.c_str())); EXPECT_FALSE(FindTraceEntry(trace_parsed_, name2.c_str())); diff --git a/base/test/trace_event_analyzer_unittest.cc b/base/test/trace_event_analyzer_unittest.cc index 63760a4..5d850e2 100644 --- a/base/test/trace_event_analyzer_unittest.cc +++ b/base/test/trace_event_analyzer_unittest.cc @@ -26,11 +26,7 @@ class TraceEventAnalyzerTest : public testing::Test { void TraceEventAnalyzerTest::ManualSetUp() { base::debug::TraceLog::Resurrect(); - base::debug::TraceLog* tracelog = base::debug::TraceLog::GetInstance(); - ASSERT_TRUE(tracelog); - tracelog->SetOutputCallback( - base::Bind(&TraceEventAnalyzerTest::OnTraceDataCollected, - base::Unretained(this))); + ASSERT_TRUE(base::debug::TraceLog::GetInstance()); buffer_.SetOutputCallback(output_.GetCallback()); output_.json_output.clear(); } @@ -48,6 +44,9 @@ void TraceEventAnalyzerTest::BeginTracing() { void TraceEventAnalyzerTest::EndTracing() { base::debug::TraceLog::GetInstance()->SetEnabled(false); + base::debug::TraceLog::GetInstance()->Flush( + base::Bind(&TraceEventAnalyzerTest::OnTraceDataCollected, + base::Unretained(this))); buffer_.Finish(); } diff --git a/chrome/chrome_tests.gypi b/chrome/chrome_tests.gypi index 72b57ed..def9a96 100644 --- a/chrome/chrome_tests.gypi +++ b/chrome/chrome_tests.gypi @@ -3079,6 +3079,7 @@ 'test/base/chrome_render_view_test.cc', 'test/base/chrome_render_view_test.h', 'test/base/chrome_test_launcher.cc', + 'test/base/tracing_browsertest.cc', 'test/data/webui/assertions.js', 'test/data/webui/async_gen.cc', 'test/data/webui/async_gen.h', diff --git a/chrome/test/base/tracing.cc b/chrome/test/base/tracing.cc index 7e609ec..9ab978d 100644 --- a/chrome/test/base/tracing.cc +++ b/chrome/test/base/tracing.cc @@ -7,27 +7,64 @@ #include "base/debug/trace_event.h" #include "base/memory/singleton.h" #include "base/message_loop.h" +#include "content/public/browser/browser_thread.h" #include "content/public/browser/trace_controller.h" #include "content/public/browser/trace_subscriber.h" #include "content/public/test/test_utils.h" namespace { +using content::BrowserThread; + class InProcessTraceController : public content::TraceSubscriber { public: static InProcessTraceController* GetInstance() { return Singleton<InProcessTraceController>::get(); } - InProcessTraceController() {} + InProcessTraceController() + : is_waiting_on_watch_(false), + watch_notification_count_(0) {} virtual ~InProcessTraceController() {} bool BeginTracing(const std::string& categories) { + DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); return content::TraceController::GetInstance()->BeginTracing( this, categories); } + bool BeginTracingWithWatch(const std::string& categories, + const std::string& category_name, + const std::string& event_name, + int num_occurrences) { + DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); + DCHECK(num_occurrences > 0); + watch_notification_count_ = num_occurrences; + return BeginTracing(categories) && + content::TraceController::GetInstance()->SetWatchEvent( + this, category_name, event_name); + } + + bool WaitForWatchEvent(base::TimeDelta timeout) { + DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); + if (watch_notification_count_ == 0) + return true; + + if (timeout != base::TimeDelta()) { + timer_.Start(FROM_HERE, timeout, this, + &InProcessTraceController::Timeout); + } + + is_waiting_on_watch_ = true; + message_loop_runner_ = new content::MessageLoopRunner; + message_loop_runner_->Run(); + is_waiting_on_watch_ = false; + + return watch_notification_count_ == 0; + } + bool EndTracing(std::string* json_trace_output) { + DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); using namespace base::debug; TraceResultBuffer::SimpleOutput output; @@ -44,28 +81,53 @@ class InProcessTraceController : public content::TraceSubscriber { trace_buffer_.SetOutputCallback(TraceResultBuffer::OutputCallback()); *json_trace_output = output.json_output; + + // Watch notifications can occur during this method's message loop run, but + // not after, so clear them here. + watch_notification_count_ = 0; return true; } private: friend struct DefaultSingletonTraits<InProcessTraceController>; - // TraceSubscriber + // TraceSubscriber implementation virtual void OnEndTracingComplete() OVERRIDE { message_loop_runner_->Quit(); } - // TraceSubscriber + // TraceSubscriber implementation virtual void OnTraceDataCollected( const scoped_refptr<base::RefCountedString>& trace_fragment) OVERRIDE { trace_buffer_.AddFragment(trace_fragment->data()); } + // TraceSubscriber implementation + virtual void OnEventWatchNotification() OVERRIDE { + if (watch_notification_count_ == 0) + return; + if (--watch_notification_count_ == 0) { + timer_.Stop(); + if (is_waiting_on_watch_) + message_loop_runner_->Quit(); + } + } + + void Timeout() { + DCHECK(is_waiting_on_watch_); + message_loop_runner_->Quit(); + } + // For collecting trace data asynchronously. base::debug::TraceResultBuffer trace_buffer_; scoped_refptr<content::MessageLoopRunner> message_loop_runner_; + base::OneShotTimer<InProcessTraceController> timer_; + + bool is_waiting_on_watch_; + int watch_notification_count_; + DISALLOW_COPY_AND_ASSIGN(InProcessTraceController); }; @@ -77,6 +139,18 @@ bool BeginTracing(const std::string& categories) { return InProcessTraceController::GetInstance()->BeginTracing(categories); } +bool BeginTracingWithWatch(const std::string& categories, + const std::string& category_name, + const std::string& event_name, + int num_occurrences) { + return InProcessTraceController::GetInstance()->BeginTracingWithWatch( + categories, category_name, event_name, num_occurrences); +} + +bool WaitForWatchEvent(base::TimeDelta timeout) { + return InProcessTraceController::GetInstance()->WaitForWatchEvent(timeout); +} + bool EndTracing(std::string* json_trace_output) { return InProcessTraceController::GetInstance()->EndTracing(json_trace_output); } diff --git a/chrome/test/base/tracing.h b/chrome/test/base/tracing.h index 4ba107e..15dffc7 100644 --- a/chrome/test/base/tracing.h +++ b/chrome/test/base/tracing.h @@ -8,13 +8,15 @@ #include <string> #include "base/compiler_specific.h" +#include "base/time.h" namespace tracing { +// Called from UI thread. // Begin tracing specified categories on the browser. -// |categories| is a comma-delimited list of category wildcards. -// A category can have an optional '-' prefix to make it an excluded category. -// Either all categories must be included or all must be excluded. +// |categories| is a comma-delimited list of category wildcards. A category can +// have an optional '-' prefix to make it an excluded category. Either all +// categories must be included or all must be excluded. // // Example: BeginTracing("test_MyTest*"); // Example: BeginTracing("test_MyTest*,test_OtherStuff"); @@ -24,6 +26,22 @@ namespace tracing { // categories. bool BeginTracing(const std::string& categories) WARN_UNUSED_RESULT; +// Called from UI thread. +// Specify a watch event in order to use the WaitForWatchEvent function. +// After |num_occurrences| of the given event have been seen on a particular +// process, WaitForWatchEvent will return. +bool BeginTracingWithWatch(const std::string& categories, + const std::string& category_name, + const std::string& event_name, + int num_occurrences) WARN_UNUSED_RESULT; + +// Called from UI thread. +// Wait on the event set with BeginTracingWithWatch. If non-zero, return after +// |timeout| regardless of watch event notification. Returns true if watch event +// occurred, false if it timed out. +bool WaitForWatchEvent(base::TimeDelta timeout) WARN_UNUSED_RESULT; + +// Called from UI thread. // End trace and collect the trace output as a json string. bool EndTracing(std::string* json_trace_output) WARN_UNUSED_RESULT; diff --git a/chrome/test/base/tracing_browsertest.cc b/chrome/test/base/tracing_browsertest.cc new file mode 100644 index 0000000..5b1b284 --- /dev/null +++ b/chrome/test/base/tracing_browsertest.cc @@ -0,0 +1,88 @@ +// Copyright (c) 2012 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 "chrome/test/base/tracing.h" + +#include "base/debug/trace_event.h" +#include "base/message_loop.h" +#include "base/run_loop.h" +#include "chrome/test/base/in_process_browser_test.h" +#include "chrome/test/base/ui_test_utils.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace { + +using tracing::BeginTracingWithWatch; +using tracing::WaitForWatchEvent; +using tracing::EndTracing; + +const char* g_category = "test_tracing"; +const char* g_event = "TheEvent"; + +class TracingBrowserTest : public InProcessBrowserTest { +}; + +void AddEvents(int num) { + for (int i = 0; i < num; ++i) + TRACE_EVENT_INSTANT0(g_category, g_event); +} + +IN_PROC_BROWSER_TEST_F(TracingBrowserTest, BeginTracingWithWatch) { + base::TimeDelta no_timeout; + base::TimeDelta short_timeout = base::TimeDelta::FromMilliseconds(5); + std::string json_events; + + // One event before wait. + ASSERT_TRUE(BeginTracingWithWatch(g_category, g_category, g_event, 1)); + AddEvents(1); + EXPECT_TRUE(WaitForWatchEvent(no_timeout)); + ASSERT_TRUE(EndTracing(&json_events)); + + // One event after wait. + ASSERT_TRUE(BeginTracingWithWatch(g_category, g_category, g_event, 1)); + MessageLoop::current()->PostTask(FROM_HERE, base::Bind(&AddEvents, 1)); + EXPECT_TRUE(WaitForWatchEvent(no_timeout)); + ASSERT_TRUE(EndTracing(&json_events)); + + // Not enough events timeout. + ASSERT_TRUE(BeginTracingWithWatch(g_category, g_category, g_event, 2)); + AddEvents(1); + EXPECT_FALSE(WaitForWatchEvent(short_timeout)); + ASSERT_TRUE(EndTracing(&json_events)); + + // Multi event before wait. + ASSERT_TRUE(BeginTracingWithWatch(g_category, g_category, g_event, 5)); + AddEvents(5); + EXPECT_TRUE(WaitForWatchEvent(no_timeout)); + ASSERT_TRUE(EndTracing(&json_events)); + + // Multi event after wait. + ASSERT_TRUE(BeginTracingWithWatch(g_category, g_category, g_event, 5)); + MessageLoop::current()->PostTask(FROM_HERE, base::Bind(&AddEvents, 5)); + EXPECT_TRUE(WaitForWatchEvent(no_timeout)); + ASSERT_TRUE(EndTracing(&json_events)); + + // Child process events from same process. + GURL url1("chrome://tracing"); + ASSERT_TRUE(BeginTracingWithWatch(g_category, g_category, + "RenderViewImpl::OnNavigate", 2)); + ui_test_utils::NavigateToURL(browser(), url1); + ui_test_utils::NavigateToURL(browser(), url1); + EXPECT_TRUE(WaitForWatchEvent(no_timeout)); + ASSERT_TRUE(EndTracing(&json_events)); + + // Child process events from different processes. + GURL url2("about:blank"); + ASSERT_TRUE(BeginTracingWithWatch(g_category, g_category, + "RenderViewImpl::OnNavigate", 2)); + // Open two tabs to different URLs to encourage two separate renderer + // processes. Each will fire an event that will be counted towards the total. + ui_test_utils::NavigateToURL(browser(), url1); + ui_test_utils::NavigateToURLWithDisposition(browser(), url2, + NEW_FOREGROUND_TAB, ui_test_utils::BROWSER_TEST_WAIT_FOR_NAVIGATION); + EXPECT_TRUE(WaitForWatchEvent(no_timeout)); + ASSERT_TRUE(EndTracing(&json_events)); +} + +} // namespace diff --git a/content/browser/trace_controller_impl.cc b/content/browser/trace_controller_impl.cc index 91640fc..8b3a610 100644 --- a/content/browser/trace_controller_impl.cc +++ b/content/browser/trace_controller_impl.cc @@ -20,6 +20,9 @@ namespace content { namespace { +base::LazyInstance<TraceControllerImpl>::Leaky g_controller = + LAZY_INSTANCE_INITIALIZER; + class AutoStopTraceSubscriberStdio : public content::TraceSubscriberStdio { public: AutoStopTraceSubscriberStdio(const FilePath& file_path) @@ -52,18 +55,19 @@ TraceControllerImpl::TraceControllerImpl() : maximum_bpf_(0.0f), is_tracing_(false), is_get_categories_(false) { - TraceLog::GetInstance()->SetOutputCallback( - base::Bind(&TraceControllerImpl::OnTraceDataCollected, + TraceLog::GetInstance()->SetNotificationCallback( + base::Bind(&TraceControllerImpl::OnTraceNotification, base::Unretained(this))); } TraceControllerImpl::~TraceControllerImpl() { - if (TraceLog* trace_log = TraceLog::GetInstance()) - trace_log->SetOutputCallback(TraceLog::OutputCallback()); + // No need to SetNotificationCallback(nil) on the TraceLog since this is a + // Leaky instance. + NOTREACHED(); } TraceControllerImpl* TraceControllerImpl::GetInstance() { - return Singleton<TraceControllerImpl>::get(); + return g_controller.Pointer(); } void TraceControllerImpl::InitStartupTracing(const CommandLine& command_line) { @@ -204,6 +208,38 @@ bool TraceControllerImpl::GetTraceBufferPercentFullAsync( return true; } +bool TraceControllerImpl::SetWatchEvent(TraceSubscriber* subscriber, + const std::string& category_name, + const std::string& event_name) { + DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); + if (subscriber != subscriber_) + return false; + + watch_category_ = category_name; + watch_name_ = event_name; + + TraceLog::GetInstance()->SetWatchEvent(category_name, event_name); + for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it) + it->get()->SendSetWatchEvent(category_name, event_name); + + return true; +} + +bool TraceControllerImpl::CancelWatchEvent(TraceSubscriber* subscriber) { + DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); + if (subscriber != subscriber_) + return false; + + watch_category_.clear(); + watch_name_.clear(); + + TraceLog::GetInstance()->CancelWatchEvent(); + for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it) + it->get()->SendCancelWatchEvent(); + + return true; +} + void TraceControllerImpl::CancelSubscriber(TraceSubscriber* subscriber) { DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); @@ -226,6 +262,8 @@ void TraceControllerImpl::AddFilter(TraceMessageFilter* filter) { filters_.insert(filter); if (is_tracing_enabled()) { filter->SendBeginTracing(included_categories_, excluded_categories_); + if (!watch_category_.empty()) + filter->SendSetWatchEvent(watch_category_, watch_name_); } } @@ -272,11 +310,16 @@ void TraceControllerImpl::OnEndTracingAck( // All acks have been received. is_tracing_ = false; - // Disable local trace. During this call, our OnTraceDataCollected will be + // Disable local trace. + TraceLog::GetInstance()->SetDisabled(); + + // During this call, our OnTraceDataCollected will be // called with the last of the local trace data. Since we are on the UI // thread, the call to OnTraceDataCollected will be synchronous, so we can // immediately call OnEndTracingComplete below. - TraceLog::GetInstance()->SetEnabled(false); + TraceLog::GetInstance()->Flush( + base::Bind(&TraceControllerImpl::OnTraceDataCollected, + base::Unretained(this))); // Trigger callback if one is set. if (subscriber_) { @@ -318,19 +361,25 @@ void TraceControllerImpl::OnTraceDataCollected( subscriber_->OnTraceDataCollected(events_str_ptr); } -void TraceControllerImpl::OnTraceBufferFull() { - // OnTraceBufferFull may be called from any browser thread, either by the +void TraceControllerImpl::OnTraceNotification(int notification) { + // OnTraceNotification may be called from any browser thread, either by the // local event trace system or from child processes via TraceMessageFilter. if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) { BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, - base::Bind(&TraceControllerImpl::OnTraceBufferFull, - base::Unretained(this))); + base::Bind(&TraceControllerImpl::OnTraceNotification, + base::Unretained(this), notification)); return; } - // EndTracingAsync may return false if tracing is already in the process of - // being ended. That is ok. - EndTracingAsync(subscriber_); + if (notification & base::debug::TraceLog::TRACE_BUFFER_FULL) { + // EndTracingAsync may return false if tracing is already in the process + // of being ended. That is ok. + EndTracingAsync(subscriber_); + } + if (notification & base::debug::TraceLog::EVENT_WATCH_NOTIFICATION) { + if (subscriber_) + subscriber_->OnEventWatchNotification(); + } } void TraceControllerImpl::OnTraceBufferPercentFullReply(float percent_full) { diff --git a/content/browser/trace_controller_impl.h b/content/browser/trace_controller_impl.h index 18fd539..915f6a9 100644 --- a/content/browser/trace_controller_impl.h +++ b/content/browser/trace_controller_impl.h @@ -10,7 +10,7 @@ #include <vector> #include "base/debug/trace_event.h" -#include "base/memory/singleton.h" +#include "base/lazy_instance.h" #include "content/public/browser/trace_controller.h" class CommandLine; @@ -46,12 +46,16 @@ class TraceControllerImpl : public TraceController { virtual bool EndTracingAsync(TraceSubscriber* subscriber) OVERRIDE; virtual bool GetTraceBufferPercentFullAsync( TraceSubscriber* subscriber) OVERRIDE; + virtual bool SetWatchEvent(TraceSubscriber* subscriber, + const std::string& category_name, + const std::string& event_name) OVERRIDE; + virtual bool CancelWatchEvent(TraceSubscriber* subscriber) OVERRIDE; virtual void CancelSubscriber(TraceSubscriber* subscriber) OVERRIDE; private: typedef std::set<scoped_refptr<TraceMessageFilter> > FilterMap; - friend struct DefaultSingletonTraits<TraceControllerImpl>; + friend struct base::DefaultLazyInstanceTraits<TraceControllerImpl>; friend class ::TraceMessageFilter; TraceControllerImpl(); @@ -85,7 +89,7 @@ class TraceControllerImpl : public TraceController { void OnEndTracingAck(const std::vector<std::string>& known_categories); void OnTraceDataCollected( const scoped_refptr<base::RefCountedString>& events_str_ptr); - void OnTraceBufferFull(); + void OnTraceNotification(int notification); void OnTraceBufferPercentFullReply(float percent_full); FilterMap filters_; @@ -100,6 +104,8 @@ class TraceControllerImpl : public TraceController { std::set<std::string> known_categories_; std::vector<std::string> included_categories_; std::vector<std::string> excluded_categories_; + std::string watch_category_; + std::string watch_name_; DISALLOW_COPY_AND_ASSIGN(TraceControllerImpl); }; diff --git a/content/browser/trace_message_filter.cc b/content/browser/trace_message_filter.cc index 6d57ece..17dbee7 100644 --- a/content/browser/trace_message_filter.cc +++ b/content/browser/trace_message_filter.cc @@ -47,8 +47,8 @@ bool TraceMessageFilter::OnMessageReceived(const IPC::Message& message, IPC_MESSAGE_HANDLER(ChildProcessHostMsg_EndTracingAck, OnEndTracingAck) IPC_MESSAGE_HANDLER(ChildProcessHostMsg_TraceDataCollected, OnTraceDataCollected) - IPC_MESSAGE_HANDLER(ChildProcessHostMsg_TraceBufferFull, - OnTraceBufferFull) + IPC_MESSAGE_HANDLER(ChildProcessHostMsg_TraceNotification, + OnTraceNotification) IPC_MESSAGE_HANDLER(ChildProcessHostMsg_TraceBufferPercentFullReply, OnTraceBufferPercentFullReply) IPC_MESSAGE_UNHANDLED(handled = false) @@ -78,6 +78,15 @@ void TraceMessageFilter::SendGetTraceBufferPercentFull() { Send(new ChildProcessMsg_GetTraceBufferPercentFull); } +void TraceMessageFilter::SendSetWatchEvent(const std::string& category_name, + const std::string& event_name) { + Send(new ChildProcessMsg_SetWatchEvent(category_name, event_name)); +} + +void TraceMessageFilter::SendCancelWatchEvent() { + Send(new ChildProcessMsg_CancelWatchEvent); +} + TraceMessageFilter::~TraceMessageFilter() {} void TraceMessageFilter::OnChildSupportsTracing() { @@ -103,8 +112,8 @@ void TraceMessageFilter::OnTraceDataCollected(const std::string& data) { TraceControllerImpl::GetInstance()->OnTraceDataCollected(data_ptr); } -void TraceMessageFilter::OnTraceBufferFull() { - TraceControllerImpl::GetInstance()->OnTraceBufferFull(); +void TraceMessageFilter::OnTraceNotification(int notification) { + TraceControllerImpl::GetInstance()->OnTraceNotification(notification); } void TraceMessageFilter::OnTraceBufferPercentFullReply(float percent_full) { diff --git a/content/browser/trace_message_filter.h b/content/browser/trace_message_filter.h index ba54a7f..4eece06 100644 --- a/content/browser/trace_message_filter.h +++ b/content/browser/trace_message_filter.h @@ -29,6 +29,9 @@ class TraceMessageFilter : public content::BrowserMessageFilter { const std::vector<std::string>& excluded_categories); void SendEndTracing(); void SendGetTraceBufferPercentFull(); + void SendSetWatchEvent(const std::string& category_name, + const std::string& event_name); + void SendCancelWatchEvent(); protected: virtual ~TraceMessageFilter(); @@ -37,7 +40,7 @@ class TraceMessageFilter : public content::BrowserMessageFilter { // Message handlers. void OnChildSupportsTracing(); void OnEndTracingAck(const std::vector<std::string>& known_categories); - void OnTraceBufferFull(); + void OnTraceNotification(int notification); void OnTraceBufferPercentFullReply(float percent_full); void OnTraceDataCollected(const std::string& data); diff --git a/content/common/child_process_messages.h b/content/common/child_process_messages.h index 1403969..93c5578 100644 --- a/content/common/child_process_messages.h +++ b/content/common/child_process_messages.h @@ -83,6 +83,14 @@ IPC_MESSAGE_CONTROL0(ChildProcessMsg_EndTracing) // Sent to all child processes to get trace buffer fullness. IPC_MESSAGE_CONTROL0(ChildProcessMsg_GetTraceBufferPercentFull) +// Sent to all child processes to set watch event. +IPC_MESSAGE_CONTROL2(ChildProcessMsg_SetWatchEvent, + std::string /* category_name */, + std::string /* event_name */) + +// Sent to all child processes to clear watch event. +IPC_MESSAGE_CONTROL0(ChildProcessMsg_CancelWatchEvent) + // Tell the child process to enable or disable the profiler status. IPC_MESSAGE_CONTROL1(ChildProcessMsg_SetProfilerStatus, tracked_objects::ThreadData::Status /* profiler status */) @@ -117,7 +125,8 @@ IPC_MESSAGE_CONTROL1(ChildProcessHostMsg_EndTracingAck, std::vector<std::string> /* known_categories */) // Sent if the trace buffer becomes full. -IPC_MESSAGE_CONTROL0(ChildProcessHostMsg_TraceBufferFull) +IPC_MESSAGE_CONTROL1(ChildProcessHostMsg_TraceNotification, + int /* base::debug::TraceLog::Notification */) // Child processes send trace data back in JSON chunks. IPC_MESSAGE_CONTROL1(ChildProcessHostMsg_TraceDataCollected, diff --git a/content/common/child_trace_message_filter.cc b/content/common/child_trace_message_filter.cc index adc5426..6ca3031 100644 --- a/content/common/child_trace_message_filter.cc +++ b/content/common/child_trace_message_filter.cc @@ -10,23 +10,20 @@ #include "content/common/child_process.h" #include "content/common/child_process_messages.h" +using base::debug::TraceLog; ChildTraceMessageFilter::ChildTraceMessageFilter() : channel_(NULL) {} void ChildTraceMessageFilter::OnFilterAdded(IPC::Channel* channel) { channel_ = channel; - base::debug::TraceLog::GetInstance()->SetOutputCallback( - base::Bind(&ChildTraceMessageFilter::OnTraceDataCollected, this)); - base::debug::TraceLog::GetInstance()->SetBufferFullCallback( - base::Bind(&ChildTraceMessageFilter::OnTraceBufferFull, this)); + TraceLog::GetInstance()->SetNotificationCallback( + base::Bind(&ChildTraceMessageFilter::OnTraceNotification, this)); channel_->Send(new ChildProcessHostMsg_ChildSupportsTracing()); } void ChildTraceMessageFilter::OnFilterRemoved() { - base::debug::TraceLog::GetInstance()->SetOutputCallback( - base::debug::TraceLog::OutputCallback()); - base::debug::TraceLog::GetInstance()->SetBufferFullCallback( - base::debug::TraceLog::BufferFullCallback()); + TraceLog::GetInstance()->SetNotificationCallback( + TraceLog::NotificationCallback()); } bool ChildTraceMessageFilter::OnMessageReceived(const IPC::Message& message) { @@ -36,6 +33,8 @@ bool ChildTraceMessageFilter::OnMessageReceived(const IPC::Message& message) { IPC_MESSAGE_HANDLER(ChildProcessMsg_EndTracing, OnEndTracing) IPC_MESSAGE_HANDLER(ChildProcessMsg_GetTraceBufferPercentFull, OnGetTraceBufferPercentFull) + IPC_MESSAGE_HANDLER(ChildProcessMsg_SetWatchEvent, OnSetWatchEvent) + IPC_MESSAGE_HANDLER(ChildProcessMsg_CancelWatchEvent, OnCancelWatchEvent) IPC_MESSAGE_UNHANDLED(handled = false) IPC_END_MESSAGE_MAP() return handled; @@ -46,29 +45,41 @@ ChildTraceMessageFilter::~ChildTraceMessageFilter() {} void ChildTraceMessageFilter::OnBeginTracing( const std::vector<std::string>& included_categories, const std::vector<std::string>& excluded_categories) { - base::debug::TraceLog::GetInstance()->SetEnabled(included_categories, - excluded_categories); + TraceLog::GetInstance()->SetEnabled(included_categories, + excluded_categories); } void ChildTraceMessageFilter::OnEndTracing() { - // SetDisabled may generate a callback to OnTraceDataCollected. - // It's important that the last OnTraceDataCollected gets called before - // EndTracingAck below. - // We are already on the IO thread, so it is guaranteed that - // OnTraceDataCollected is not deferred. - base::debug::TraceLog::GetInstance()->SetDisabled(); + TraceLog::GetInstance()->SetDisabled(); + + // Flush will generate one or more callbacks to OnTraceDataCollected. It's + // important that the last OnTraceDataCollected gets called before + // EndTracingAck below. We are already on the IO thread, so the + // OnTraceDataCollected calls will not be deferred. + TraceLog::GetInstance()->Flush( + base::Bind(&ChildTraceMessageFilter::OnTraceDataCollected, this)); std::vector<std::string> categories; - base::debug::TraceLog::GetInstance()->GetKnownCategories(&categories); + TraceLog::GetInstance()->GetKnownCategories(&categories); channel_->Send(new ChildProcessHostMsg_EndTracingAck(categories)); } void ChildTraceMessageFilter::OnGetTraceBufferPercentFull() { - float bpf = base::debug::TraceLog::GetInstance()->GetBufferPercentFull(); + float bpf = TraceLog::GetInstance()->GetBufferPercentFull(); channel_->Send(new ChildProcessHostMsg_TraceBufferPercentFullReply(bpf)); } +void ChildTraceMessageFilter::OnSetWatchEvent(const std::string& category_name, + const std::string& event_name) { + TraceLog::GetInstance()->SetWatchEvent(category_name.c_str(), + event_name.c_str()); +} + +void ChildTraceMessageFilter::OnCancelWatchEvent() { + TraceLog::GetInstance()->CancelWatchEvent(); +} + void ChildTraceMessageFilter::OnTraceDataCollected( const scoped_refptr<base::RefCountedString>& events_str_ptr) { if (MessageLoop::current() != ChildProcess::current()->io_message_loop()) { @@ -79,16 +90,16 @@ void ChildTraceMessageFilter::OnTraceDataCollected( } channel_->Send(new ChildProcessHostMsg_TraceDataCollected( - events_str_ptr->data())); + events_str_ptr->data())); } -void ChildTraceMessageFilter::OnTraceBufferFull() { +void ChildTraceMessageFilter::OnTraceNotification(int notification) { if (MessageLoop::current() != ChildProcess::current()->io_message_loop()) { ChildProcess::current()->io_message_loop()->PostTask(FROM_HERE, - base::Bind(&ChildTraceMessageFilter::OnTraceBufferFull, this)); + base::Bind(&ChildTraceMessageFilter::OnTraceNotification, this, + notification)); return; } - channel_->Send(new ChildProcessHostMsg_TraceBufferFull()); + channel_->Send(new ChildProcessHostMsg_TraceNotification(notification)); } - diff --git a/content/common/child_trace_message_filter.h b/content/common/child_trace_message_filter.h index d913d6a..946344a 100644 --- a/content/common/child_trace_message_filter.h +++ b/content/common/child_trace_message_filter.h @@ -30,11 +30,14 @@ class ChildTraceMessageFilter : public IPC::ChannelProxy::MessageFilter { const std::vector<std::string>& excluded_categories); void OnEndTracing(); void OnGetTraceBufferPercentFull(); + void OnSetWatchEvent(const std::string& category_name, + const std::string& event_name); + void OnCancelWatchEvent(); // Callback from trace subsystem. void OnTraceDataCollected( const scoped_refptr<base::RefCountedString>& events_str_ptr); - void OnTraceBufferFull(); + void OnTraceNotification(int notification); IPC::Channel* channel_; diff --git a/content/public/browser/trace_controller.h b/content/public/browser/trace_controller.h index 0558363..6bdff6c 100644 --- a/content/public/browser/trace_controller.h +++ b/content/public/browser/trace_controller.h @@ -68,6 +68,16 @@ class TraceController { // the caller is not the current subscriber. virtual bool GetTraceBufferPercentFullAsync(TraceSubscriber* subscriber) = 0; + // |subscriber->OnEventWatchNotification()| will be called every time the + // given event occurs on any process. + virtual bool SetWatchEvent(TraceSubscriber* subscriber, + const std::string& category_name, + const std::string& event_name) = 0; + + // Cancel the watch event. If tracing is enabled, this may race with the + // watch event notification firing. + virtual bool CancelWatchEvent(TraceSubscriber* subscriber) = 0; + // Cancel the subscriber so that it will not be called when EndTracingAsync is // acked by all child processes. This will also call EndTracingAsync // internally if necessary. diff --git a/content/public/browser/trace_subscriber.h b/content/public/browser/trace_subscriber.h index 08e408c1..ec8d070 100644 --- a/content/public/browser/trace_subscriber.h +++ b/content/public/browser/trace_subscriber.h @@ -11,7 +11,8 @@ namespace content { -// Objects interested in receiving trace data derive from TraceSubscriber. +// Objects interested in receiving trace data derive from TraceSubscriber. All +// callbacks occur on the UI thread. // See also: trace_message_filter.h // See also: child_trace_message_filter.h class TraceSubscriber { @@ -31,6 +32,8 @@ class TraceSubscriber { virtual void OnTraceBufferPercentFullReply(float percent_full) {} + virtual void OnEventWatchNotification() {} + protected: virtual ~TraceSubscriber() {} }; diff --git a/content/renderer/render_view_impl.cc b/content/renderer/render_view_impl.cc index b32cfa0..8ec9fbe 100644 --- a/content/renderer/render_view_impl.cc +++ b/content/renderer/render_view_impl.cc @@ -13,6 +13,7 @@ #include "base/bind_helpers.h" #include "base/command_line.h" #include "base/compiler_specific.h" +#include "base/debug/trace_event.h" #include "base/json/json_reader.h" #include "base/json/json_writer.h" #include "base/lazy_instance.h" @@ -1204,6 +1205,8 @@ void RenderViewImpl::OnNavigate(const ViewMsg_Navigate_Params& params) { // In case LoadRequest failed before DidCreateDataSource was called. pending_navigation_params_.reset(); + + UNSHIPPED_TRACE_EVENT_INSTANT0("test_tracing", "RenderViewImpl::OnNavigate"); } bool RenderViewImpl::IsBackForwardToStaleEntry( |