Merge gpu_trace_event back into base/debug/trace_event

base/debug/trace_event_unittest.cc

+// 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/json/json_reader.h"
+#include "base/json/json_writer.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 {

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

is there commonly an anonymous namespace nested inside other namespaces? I
haven't seen this before, but if it's common practice in other tests, it's fine.

[scheib, 2011/05/04 02:14:15]

I think the same reasoning applies for anonymous NS even if it's nested?

+
+class TraceEventTestFixture: public testing::Test {

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nit: spaces both side of : 
http://google-styleguide.googlecode.com/svn/trunk/cppguide.xml?showone=Class_...

[scheib, 2011/05/04 02:14:15]

Done.

+ public:
+  TraceEventTestFixture() {};

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nit: no semicolon after the body.

[scheib, 2011/05/04 02:14:15]

Done.

+
+  void ManualTestSetUp();
+  void OnTraceDataCollected(const std::string& data);
+
+  ListValue trace_parsed_;
+  std::string trace_string_;
+
+ 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(
+    NewCallback(this, &TraceEventTestFixture::OnTraceDataCollected));

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nit: 4 space indent on continuation.

[scheib, 2011/05/04 02:14:15]

Done.

+}
+
+void TraceEventTestFixture::OnTraceDataCollected(const std::string& data) {
+  if (0 && "Enable for visualizing what data was collected and parsed") {

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

either remove, or e.g. control through the command line (CommandLine::HasSwitch
is your friend).

[scheib, 2011/05/04 02:14:15]

Done.

+    fprintf(stderr, "\n\nRawJSON:\n%s\n", data.c_str());
+  }
+  trace_string_ += data;
+
+  scoped_ptr<Value> root;
+  root.reset(base::JSONReader::Read(data, false));
+
+  ListValue* root_list = NULL;
+  EXPECT_TRUE(root.get());

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

ASSERT_TRUE will return from a void function on failure.

[scheib, 2011/05/04 02:14:15]

Done.

+  if (!root.get())
+    return;
+  EXPECT_TRUE(root->GetAsList(&root_list));
+  if (!root_list)
+    return;
+
+  // Move items into our aggregate collection
+  while (root_list->GetSize()) {
+    Value* item = NULL;
+    root_list->Remove(0, &item);
+    trace_parsed_.Append(item);
+  }
+
+  if (0 && "Enable for visualizing what data was collected and parsed") {
+    std::string parsed;
+    base::JSONWriter::Write(&trace_parsed_, true, &parsed);
+    fprintf(stderr, "\nParsedJSON:\n%s\n\n", parsed.c_str());
+  }
+}
+
+bool IsStringInDict(const char* string_to_match, DictionaryValue* dict) {
+  if (0 && "Enable for visualizing what data is being tested") {
+    std::string parsed;
+    base::JSONWriter::Write(dict, true, &parsed);
+    fprintf(stderr, "\n\nParsedJSON:\n%s\n\n", parsed.c_str());
+  }
+
+  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,

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

http://google-styleguide.googlecode.com/svn/trunk/cppguide.xml?showone=Functi...

[scheib, 2011/05/04 02:14:15]

Done.

+    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 DataCaptured_CallTraces(WaitableEvent* task_complete_event) {

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

why the _ in the function name?

[scheib, 2011/05/04 02:14:15]

Done.

+  TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 0xaa, "extrastring1");
+  TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 0xbb, "extrastring2");
+  TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW call", 0xcc, "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");
+
+
+  if (task_complete_event)
+    task_complete_event->Signal();
+}
+
+void DataCaptured_ValidateTraces(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");
+  EXPECT_SUB_FIND_("0xaa");
+  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);
+
+  DataCaptured_CallTraces(NULL);
+
+  TraceLog::GetInstance()->SetEnabled(false);
+
+  DataCaptured_ValidateTraces(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(&DataCaptured_CallTraces,
+                                   &task_complete_event));
+  task_complete_event.Wait();
+
+  TraceLog::GetInstance()->SetEnabled(false);
+  thread.Stop();
+  DataCaptured_ValidateTraces(trace_parsed_, trace_string_);
+}
+
+namespace {
+
+void DataCaptured_CallManyTraces(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 DataCaptured_ValidateManyTraces(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 = 10;
+  const int num_events = 1000;
+  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(&DataCaptured_CallManyTraces,
+                                     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];
+  }
+
+  DataCaptured_ValidateManyTraces(trace_parsed_, trace_string_,
+                                  num_threads, num_events);
+}
+
+void TraceCallsWillCacheStaticCategory() {
+  TRACE_EVENT0("category name1", "name1");
+  TRACE_EVENT_INSTANT0("category name2", "name2");
+  TRACE_EVENT_BEGIN0("category name3", "name3");
+  TRACE_EVENT_END0("category name4", "name4");
+}
+
+// Test trace calls made after tracing singleton shut down
+TEST_F(TraceEventTestFixture, AtExit) {
+  for (int i = 0; i < 4; i++) {
+    { // scope to destroy singleton

[Sigurður Ásgeirsson, 2011/05/02 19:28:41]

nice test!. It could do with a little bit of running commentary explaining what
you're testing and what you expect to happen at major transition points, since
the stuff you're testing here is pretty arcane - to put it mildly:).

[scheib, 2011/05/04 02:14:15]

Done.

+      base::ShadowingAtExitManager exit_manager_will_destroy_singletons;
+
+      ManualTestSetUp(); // Inside this test's exit manager scope
+
+      TRACE_EVENT_INSTANT0("all", "not recorded; system not enabled");
+
+      TraceLog::GetInstance()->SetEnabled(true);
+      TRACE_EVENT_INSTANT0("all", "is recorded; system has been enabled");
+      TraceCallsWillCacheStaticCategory();
+      TraceLog::GetInstance()->SetEnabled(false);
+    } // scope to destroy singleton
+    ASSERT_FALSE(TraceLog::GetInstance());
+
+    DictionaryValue* item = NULL;
+    ListValue& trace_parsed = trace_parsed_;
+    EXPECT_FIND_("is recorded");
+    EXPECT_NOT_FIND_("not recorded");
+
+    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");
+
+    // static categories should disable traces
+    TraceCallsWillCacheStaticCategory();
+  }
+}
+
+}  // namespace debug
+}  // namespace base