Merge gpu_trace_event back into base/debug/trace_event.
Initial land attempt at http://codereview.chromium.org/6551019/
gpu_trace_event fork at http://codereview.chromium.org/6691013
- gpu_trace_event renamed to base/debug/trace_event and modified as appropriate for base::debug
- Unit Tests implemented for trace_event
- gpu_common library removed (was added only for gpu_trace_event)
- Existing calls to trace_event suffixed with _ETW to make ETW calls (see decisions and incremental plans at end of 6551019)
- GPU trace calls renamed to new calls.
- Tracing switch removed from test_shell, as linux log file support removed.
BUG=79509
TEST=trace_event_win_unittest and about:gpu
Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=84284
Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=84486
Review URL: http://codereview.chromium.org/6862002
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@84739 0039d316-1c4b-4281-b951-d872f2087c98
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
new file mode 100644
index 0000000..360468d
--- /dev/null
+++ b/base/debug/trace_event_unittest.cc
@@ -0,0 +1,397 @@
+// Copyright (c) 2011 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "base/debug/trace_event.h"
+
+#include "base/bind.h"
+#include "base/command_line.h"
+#include "base/json/json_reader.h"
+#include "base/json/json_writer.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/stringprintf.h"
+#include "base/synchronization/waitable_event.h"
+#include "base/threading/thread.h"
+#include "base/values.h"
+#include "testing/gmock/include/gmock/gmock.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace base {
+namespace debug {
+
+namespace {
+
+class TraceEventTestFixture : public testing::Test {
+ public:
+ void ManualTestSetUp();
+ void OnTraceDataCollected(TraceLog::RefCountedString* json_events_str);
+
+ std::string trace_string_;
+ ListValue trace_parsed_;
+
+ private:
+ // We want our singleton torn down after each test.
+ ShadowingAtExitManager at_exit_manager_;
+};
+
+void TraceEventTestFixture::ManualTestSetUp() {
+ TraceLog::Resurrect();
+ TraceLog* tracelog = TraceLog::GetInstance();
+ ASSERT_TRUE(tracelog);
+ ASSERT_FALSE(tracelog->IsEnabled());
+ tracelog->SetOutputCallback(
+ base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
+ base::Unretained(this)));
+}
+
+void TraceEventTestFixture::OnTraceDataCollected(
+ TraceLog::RefCountedString* json_events_str) {
+ trace_string_ += json_events_str->data;
+
+ scoped_ptr<Value> root;
+ root.reset(base::JSONReader::Read(json_events_str->data, false));
+
+ ListValue* root_list = NULL;
+ ASSERT_TRUE(root.get());
+ ASSERT_TRUE(root->GetAsList(&root_list));
+
+ // Move items into our aggregate collection
+ while (root_list->GetSize()) {
+ Value* item = NULL;
+ root_list->Remove(0, &item);
+ trace_parsed_.Append(item);
+ }
+}
+
+bool IsStringInDict(const char* string_to_match, DictionaryValue* dict) {
+ for (DictionaryValue::key_iterator ikey = dict->begin_keys();
+ ikey != dict->end_keys(); ++ikey) {
+ Value* child = NULL;
+ if (!dict->GetWithoutPathExpansion(*ikey, &child))
+ continue;
+
+ if ((*ikey).find(string_to_match) != std::string::npos)
+ return true;
+
+ std::string value_str;
+ child->GetAsString(&value_str);
+ if (value_str.find(string_to_match) != std::string::npos)
+ return true;
+ }
+
+ // Recurse to test arguments
+ DictionaryValue* args_dict = NULL;
+ dict->GetDictionary("args", &args_dict);
+ if (args_dict)
+ return IsStringInDict(string_to_match, args_dict);
+
+ return false;
+}
+
+DictionaryValue* FindTraceEntry(const ListValue& trace_parsed,
+ const char *string_to_match,
+ DictionaryValue* match_after_this_item = NULL) {
+ // Scan all items
+ size_t trace_parsed_count = trace_parsed.GetSize();
+ for (size_t i = 0; i < trace_parsed_count; i++) {
+ Value* value = NULL;
+ trace_parsed.Get(i, &value);
+ if (match_after_this_item) {
+ if (value == match_after_this_item)
+ match_after_this_item = NULL;
+ continue;
+ }
+ if (!value || value->GetType() != Value::TYPE_DICTIONARY)
+ continue;
+ DictionaryValue* dict = static_cast<DictionaryValue*>(value);
+
+ if (IsStringInDict(string_to_match, dict))
+ return dict;
+ }
+ return NULL;
+}
+
+void DataCapturedCallTraces(WaitableEvent* task_complete_event) {
+ {
+ TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 1122, "extrastring1");
+ TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 3344, "extrastring2");
+ TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW call",
+ 5566, "extrastring3");
+
+ TRACE_EVENT0("all", "TRACE_EVENT0 call");
+ TRACE_EVENT1("all", "TRACE_EVENT1 call", "name1", "value1");
+ TRACE_EVENT2("all", "TRACE_EVENT2 call",
+ "name1", "value1",
+ "name2", "value2");
+
+ TRACE_EVENT_INSTANT0("all", "TRACE_EVENT_INSTANT0 call");
+ TRACE_EVENT_INSTANT1("all", "TRACE_EVENT_INSTANT1 call", "name1", "value1");
+ TRACE_EVENT_INSTANT2("all", "TRACE_EVENT_INSTANT2 call",
+ "name1", "value1",
+ "name2", "value2");
+
+ TRACE_EVENT_BEGIN0("all", "TRACE_EVENT_BEGIN0 call");
+ TRACE_EVENT_BEGIN1("all", "TRACE_EVENT_BEGIN1 call", "name1", "value1");
+ TRACE_EVENT_BEGIN2("all", "TRACE_EVENT_BEGIN2 call",
+ "name1", "value1",
+ "name2", "value2");
+
+ TRACE_EVENT_END0("all", "TRACE_EVENT_END0 call");
+ TRACE_EVENT_END1("all", "TRACE_EVENT_END1 call", "name1", "value1");
+ TRACE_EVENT_END2("all", "TRACE_EVENT_END2 call",
+ "name1", "value1",
+ "name2", "value2");
+ } // Scope close causes TRACE_EVENT0 etc to send their END events.
+
+ if (task_complete_event)
+ task_complete_event->Signal();
+}
+
+void DataCapturedValidateTraces(const ListValue& trace_parsed,
+ const std::string& trace_string) {
+ DictionaryValue* item = NULL;
+
+#define EXPECT_FIND_(string) \
+ EXPECT_TRUE((item = FindTraceEntry(trace_parsed, string)));
+#define EXPECT_NOT_FIND_(string) \
+ EXPECT_FALSE((item = FindTraceEntry(trace_parsed, string)));
+#define EXPECT_SUB_FIND_(string) \
+ if (item) EXPECT_TRUE((IsStringInDict(string, item)));
+
+ EXPECT_FIND_("ETW Trace Event");
+ EXPECT_FIND_("all");
+ EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW call");
+ {
+ int int_val = 0;
+ EXPECT_TRUE(item && item->GetInteger("args.id", &int_val));
+ EXPECT_EQ(1122, int_val);
+ }
+ EXPECT_SUB_FIND_("extrastring1");
+ EXPECT_FIND_("TRACE_EVENT_END_ETW call");
+ EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW call");
+ EXPECT_FIND_("TRACE_EVENT0 call");
+ {
+ std::string ph_begin;
+ std::string ph_end;
+ EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call")));
+ EXPECT_TRUE((item && item->GetString("ph", &ph_begin)));
+ EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call",
+ item)));
+ EXPECT_TRUE((item && item->GetString("ph", &ph_end)));
+ EXPECT_EQ("B", ph_begin);
+ EXPECT_EQ("E", ph_end);
+ }
+ EXPECT_FIND_("TRACE_EVENT1 call");
+ EXPECT_FIND_("TRACE_EVENT2 call");
+ EXPECT_SUB_FIND_("name1");
+ EXPECT_SUB_FIND_("value1");
+ EXPECT_SUB_FIND_("name2");
+ EXPECT_SUB_FIND_("value2");
+ EXPECT_FIND_("TRACE_EVENT_INSTANT0 call");
+ EXPECT_FIND_("TRACE_EVENT_INSTANT1 call");
+ EXPECT_FIND_("TRACE_EVENT_INSTANT2 call");
+ EXPECT_SUB_FIND_("name1");
+ EXPECT_SUB_FIND_("value1");
+ EXPECT_SUB_FIND_("name2");
+ EXPECT_SUB_FIND_("value2");
+ EXPECT_FIND_("TRACE_EVENT_BEGIN0 call");
+ EXPECT_FIND_("TRACE_EVENT_BEGIN1 call");
+ EXPECT_FIND_("TRACE_EVENT_BEGIN2 call");
+ EXPECT_SUB_FIND_("name1");
+ EXPECT_SUB_FIND_("value1");
+ EXPECT_SUB_FIND_("name2");
+ EXPECT_SUB_FIND_("value2");
+ EXPECT_FIND_("TRACE_EVENT_END0 call");
+ EXPECT_FIND_("TRACE_EVENT_END1 call");
+ EXPECT_FIND_("TRACE_EVENT_END2 call");
+ EXPECT_SUB_FIND_("name1");
+ EXPECT_SUB_FIND_("value1");
+ EXPECT_SUB_FIND_("name2");
+ EXPECT_SUB_FIND_("value2");
+}
+
+} // namespace
+
+// Simple Test for emitting data and validating it was received.
+TEST_F(TraceEventTestFixture, DataCaptured) {
+ ManualTestSetUp();
+ TraceLog::GetInstance()->SetEnabled(true);
+
+ DataCapturedCallTraces(NULL);
+
+ TraceLog::GetInstance()->SetEnabled(false);
+
+ DataCapturedValidateTraces(trace_parsed_, trace_string_);
+}
+
+// Test that data sent from other threads is gathered
+TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
+ ManualTestSetUp();
+ TraceLog::GetInstance()->SetEnabled(true);
+
+ Thread thread("1");
+ WaitableEvent task_complete_event(false, false);
+ thread.Start();
+
+ thread.message_loop()->PostTask(
+ FROM_HERE, NewRunnableFunction(&DataCapturedCallTraces,
+ &task_complete_event));
+ task_complete_event.Wait();
+
+ TraceLog::GetInstance()->SetEnabled(false);
+ thread.Stop();
+ DataCapturedValidateTraces(trace_parsed_, trace_string_);
+}
+
+namespace {
+
+void DataCapturedCallManyTraces(int thread_id, int num_events,
+ WaitableEvent* task_complete_event) {
+ for (int i = 0; i < num_events; i++) {
+ TRACE_EVENT_INSTANT2("all", "multi thread event",
+ "thread", thread_id,
+ "event", i);
+ }
+
+ if (task_complete_event)
+ task_complete_event->Signal();
+}
+
+void DataCapturedValidateManyTraces(const ListValue& trace_parsed,
+ const std::string& trace_string,
+ int num_threads, int num_events) {
+ std::map<int, std::map<int, bool> > results;
+
+ size_t trace_parsed_count = trace_parsed.GetSize();
+ for (size_t i = 0; i < trace_parsed_count; i++) {
+ Value* value = NULL;
+ trace_parsed.Get(i, &value);
+ if (!value || value->GetType() != Value::TYPE_DICTIONARY)
+ continue;
+ DictionaryValue* dict = static_cast<DictionaryValue*>(value);
+ std::string name;
+ dict->GetString("name", &name);
+ if (name != "multi thread event")
+ continue;
+
+ int thread = 0;
+ int event = 0;
+ EXPECT_TRUE(dict->GetInteger("args.thread", &thread));
+ EXPECT_TRUE(dict->GetInteger("args.event", &event));
+ results[thread][event] = true;
+ }
+
+ EXPECT_FALSE(results[-1][-1]);
+ for (int thread = 0; thread < num_threads; thread++) {
+ for (int event = 0; event < num_events; event++) {
+ EXPECT_TRUE(results[thread][event]);
+ }
+ }
+}
+
+} // namespace
+
+// Test that data sent from multiple threads is gathered
+TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
+ ManualTestSetUp();
+ TraceLog::GetInstance()->SetEnabled(true);
+
+ const int num_threads = 4;
+ const int num_events = 4000;
+ Thread* threads[num_threads];
+ WaitableEvent* task_complete_events[num_threads];
+ for (int i = 0; i < num_threads; i++) {
+ threads[i] = new Thread(StringPrintf("Thread %d", i).c_str());
+ task_complete_events[i] = new WaitableEvent(false, false);
+ threads[i]->Start();
+ threads[i]->message_loop()->PostTask(
+ FROM_HERE, NewRunnableFunction(&DataCapturedCallManyTraces,
+ 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];
+ }
+
+ DataCapturedValidateManyTraces(trace_parsed_, trace_string_,
+ num_threads, num_events);
+}
+
+void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) {
+ TRACE_EVENT0("category name1", name_str);
+ TRACE_EVENT_INSTANT0("category name2", name_str);
+ TRACE_EVENT_BEGIN0("category name3", name_str);
+ TRACE_EVENT_END0("category name4", name_str);
+}
+
+// Test trace calls made after tracing singleton shut down.
+//
+// The singleton is destroyed by our base::AtExitManager, but there can be
+// code still executing as the C++ static objects are destroyed. This test
+// forces the singleton to destroy early, and intentinally makes trace calls
+// afterwards.
+TEST_F(TraceEventTestFixture, AtExit) {
+ // Repeat this test a few times. Besides just showing robustness, it also
+ // allows us to test that events at shutdown do not appear with valid events
+ // recorded after the system is started again.
+ for (int i = 0; i < 4; i++) {
+ // Scope to contain the then destroy the TraceLog singleton.
+ {
+ base::ShadowingAtExitManager exit_manager_will_destroy_singletons;
+
+ // Setup TraceLog singleton inside this test's exit manager scope
+ // so that it will be destroyed when this scope closes.
+ ManualTestSetUp();
+
+ TRACE_EVENT_INSTANT0("all", "not recorded; system not enabled");
+
+ TraceLog::GetInstance()->SetEnabled(true);
+
+ 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);
+ } // scope to destroy singleton
+ ASSERT_FALSE(TraceLog::GetInstance());
+
+ // Now that singleton is destroyed, check what trace events were recorded
+ DictionaryValue* item = NULL;
+ ListValue& trace_parsed = trace_parsed_;
+ EXPECT_FIND_("is recorded 1");
+ EXPECT_FIND_("is recorded 2");
+ EXPECT_NOT_FIND_("not recorded");
+
+ // Make additional trace event calls on the shutdown system. They should
+ // all pass cleanly, but the data not be recorded. We'll verify that next
+ // time around the loop (the only way to flush the trace buffers).
+ TRACE_EVENT_BEGIN_ETW("not recorded; system shutdown", 0, NULL);
+ TRACE_EVENT_END_ETW("not recorded; system shutdown", 0, NULL);
+ TRACE_EVENT_INSTANT_ETW("not recorded; system shutdown", 0, NULL);
+ TRACE_EVENT0("all", "not recorded; system shutdown");
+ TRACE_EVENT_INSTANT0("all", "not recorded; system shutdown");
+ TRACE_EVENT_BEGIN0("all", "not recorded; system shutdown");
+ TRACE_EVENT_END0("all", "not recorded; system shutdown");
+
+ TRACE_EVENT0("new category 0!", "not recorded; system shutdown");
+ TRACE_EVENT_INSTANT0("new category 1!", "not recorded; system shutdown");
+ TRACE_EVENT_BEGIN0("new category 2!", "not recorded; system shutdown");
+ TRACE_EVENT_END0("new category 3!", "not recorded; system shutdown");
+
+ // Cached categories should be safe to check, and still disable traces
+ TraceCallsWithCachedCategoryPointersPointers(
+ "not recorded; system shutdown");
+ }
+}
+
+} // namespace debug
+} // namespace base
