base/debug/trace_event_unittest.cc - chromium/src - Git at Google

 // 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 {

 struct JsonKeyValue {
   const char* key;
   const char* value;
 };

 class TraceEventTestFixture : public testing::Test {
  public:
   // This fixture does not use SetUp() because the fixture must be manually set
   // up multiple times when testing AtExit. Use ManualTestSetUp for this.
   void ManualTestSetUp();
   void OnTraceDataCollected(
       scoped_refptr<TraceLog::RefCountedString> json_events_str);
   bool FindMatchingTraceEntry(const JsonKeyValue* key_values);
   bool FindNamePhase(const char* name, const char* phase);

   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(
     scoped_refptr<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);
   }
 }

 static bool IsKeyValueInDict(const JsonKeyValue* key_value,
                              DictionaryValue* dict) {
   Value* value = NULL;
   std::string value_str;
   if (dict->Get(key_value->key, &value) &&
       value->GetAsString(&value_str) &&
       value_str == key_value->value)
     return true;

   // Recurse to test arguments
   DictionaryValue* args_dict = NULL;
   dict->GetDictionary("args", &args_dict);
   if (args_dict)
     return IsKeyValueInDict(key_value, args_dict);

   return false;
 }

 static bool IsAllKeyValueInDict(const JsonKeyValue* key_values,
                                 DictionaryValue* dict) {
   // Scan all key_values, they must all be present and equal.
   while (key_values && key_values->key) {
     if (!IsKeyValueInDict(key_values, dict))
       return false;
     ++key_values;
   }
   return true;
 }

 bool TraceEventTestFixture::FindMatchingTraceEntry(
     const JsonKeyValue* key_values) {
   // 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 (!value || value->GetType() != Value::TYPE_DICTIONARY)
       continue;
     DictionaryValue* dict = static_cast<DictionaryValue*>(value);

     if (IsAllKeyValueInDict(key_values, dict))
       return true;
   }
   return false;
 }

 bool TraceEventTestFixture::FindNamePhase(const char* name, const char* phase) {
   JsonKeyValue key_values[] = {
     {"name", name},
     {"ph", phase},
     {0, 0}
   };
   return FindMatchingTraceEntry(key_values);
 }

 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_);
 }

 // Simple Test for time threshold events.
 TEST_F(TraceEventTestFixture, DataCapturedThreshold) {
   ManualTestSetUp();
   TraceLog::GetInstance()->SetEnabled(true);

   // Test that events at the same level are properly filtered by threshold.
   {
     TRACE_EVENT_IF_LONGER_THAN0(100, "time", "threshold 100");
     TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "threshold 1000");
     TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "threshold 10000");
     // 100+ seconds to avoid flakiness.
     TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "threshold long1");
     TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "threshold long2");
     base::PlatformThread::Sleep(20); // 20000 us
   }

   // Test that a normal nested event remains after it's parent event is dropped.
   {
     TRACE_EVENT_IF_LONGER_THAN0(1000000, "time", "2threshold10000");
     {
       TRACE_EVENT0("time", "nonthreshold1");
     }
   }

   // Test that parent thresholded events are dropped while some nested events
   // remain.
   {
     TRACE_EVENT0("time", "nonthreshold3");
     {
       TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "3thresholdlong2");
       {
         TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "3thresholdlong1");
         {
           TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "3threshold10000");
           {
             TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "3threshold1000");
             {
               TRACE_EVENT_IF_LONGER_THAN0(100, "time", "3threshold100");
               base::PlatformThread::Sleep(20);
             }
           }
         }
       }
     }
   }

   // Test that child thresholded events are dropped while some parent events
   // remain.
   {
     TRACE_EVENT0("time", "nonthreshold4");
     {
       TRACE_EVENT_IF_LONGER_THAN0(100, "time", "4threshold100");
       {
         TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "4threshold1000");
         {
           TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "4threshold10000");
           {
             TRACE_EVENT_IF_LONGER_THAN0(100000000, "time",
                                         "4thresholdlong1");
             {
               TRACE_EVENT_IF_LONGER_THAN0(200000000, "time",
                                           "4thresholdlong2");
               base::PlatformThread::Sleep(20);
             }
           }
         }
       }
     }
   }

   TraceLog::GetInstance()->SetEnabled(false);

 #define EXPECT_FIND_BE_(str) \
   EXPECT_TRUE(FindNamePhase(str, "B")); \
   EXPECT_TRUE(FindNamePhase(str, "E"))
 #define EXPECT_NOT_FIND_BE_(str) \
   EXPECT_FALSE(FindNamePhase(str, "B")); \
   EXPECT_FALSE(FindNamePhase(str, "E"))

   EXPECT_FIND_BE_("threshold 100");
   EXPECT_FIND_BE_("threshold 1000");
   EXPECT_FIND_BE_("threshold 10000");
   EXPECT_NOT_FIND_BE_("threshold long1");
   EXPECT_NOT_FIND_BE_("threshold long2");

   EXPECT_NOT_FIND_BE_("2threshold10000");
   EXPECT_FIND_BE_("nonthreshold1");

   EXPECT_FIND_BE_("nonthreshold3");
   EXPECT_FIND_BE_("3threshold100");
   EXPECT_FIND_BE_("3threshold1000");
   EXPECT_FIND_BE_("3threshold10000");
   EXPECT_NOT_FIND_BE_("3thresholdlong1");
   EXPECT_NOT_FIND_BE_("3thresholdlong2");

   EXPECT_FIND_BE_("nonthreshold4");
   EXPECT_FIND_BE_("4threshold100");
   EXPECT_FIND_BE_("4threshold1000");
   EXPECT_FIND_BE_("4threshold10000");
   EXPECT_NOT_FIND_BE_("4thresholdlong1");
   EXPECT_NOT_FIND_BE_("4thresholdlong2");
 }

 // 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");
   }
 }

 TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) {
   // Test that the TRACE_EVENT macros do not deep-copy their string. If they
   // do so it may indicate a performance regression, but more-over it would
   // make the DEEP_COPY overloads redundant.
   ManualTestSetUp();

   std::string name_string("event name");

   TraceLog::GetInstance()->SetEnabled(true);
   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);

   EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name"));
   EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str()));
 }

 TEST_F(TraceEventTestFixture, DeepCopy) {
   ManualTestSetUp();

   static const char kOriginalName1[] = "name1";
   static const char kOriginalName2[] = "name2";
   static const char kOriginalName3[] = "name3";
   std::string name1(kOriginalName1);
   std::string name2(kOriginalName2);
   std::string name3(kOriginalName3);
   std::string arg1("arg1");
   std::string arg2("arg2");
   std::string val1("val1");
   std::string val2("val2");

   TraceLog::GetInstance()->SetEnabled(true);
   TRACE_EVENT_COPY_INSTANT0("category", name1.c_str());
   TRACE_EVENT_COPY_BEGIN1("category", name2.c_str(),
                           arg1.c_str(), 5);
   TRACE_EVENT_COPY_END2("category", name3.c_str(),
                         arg1.c_str(), val1.c_str(),
                         arg2.c_str(), val2.c_str());

   // 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);

   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name1.c_str()));
   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name2.c_str()));
   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name3.c_str()));

   DictionaryValue* entry1 = FindTraceEntry(trace_parsed_, kOriginalName1);
   DictionaryValue* entry2 = FindTraceEntry(trace_parsed_, kOriginalName2);
   DictionaryValue* entry3 = FindTraceEntry(trace_parsed_, kOriginalName3);
   ASSERT_TRUE(entry1);
   ASSERT_TRUE(entry2);
   ASSERT_TRUE(entry3);

   int i;
   EXPECT_FALSE(entry2->GetInteger("args.@rg1", &i));
   EXPECT_TRUE(entry2->GetInteger("args.arg1", &i));
   EXPECT_EQ(5, i);

   std::string s;
   EXPECT_TRUE(entry3->GetString("args.arg1", &s));
   EXPECT_EQ("val1", s);
   EXPECT_TRUE(entry3->GetString("args.arg2", &s));
   EXPECT_EQ("val2", s);
 }

 }  // namespace debug
 }  // namespace base
	// 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 {

	struct JsonKeyValue {
	const char* key;
	const char* value;
	};

	class TraceEventTestFixture : public testing::Test {
	public:
	// This fixture does not use SetUp() because the fixture must be manually set
	// up multiple times when testing AtExit. Use ManualTestSetUp for this.
	void ManualTestSetUp();
	void OnTraceDataCollected(
	scoped_refptr<TraceLog::RefCountedString> json_events_str);
	bool FindMatchingTraceEntry(const JsonKeyValue* key_values);
	bool FindNamePhase(const char* name, const char* phase);

	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(
	scoped_refptr<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);
	}
	}

	static bool IsKeyValueInDict(const JsonKeyValue* key_value,
	DictionaryValue* dict) {
	Value* value = NULL;
	std::string value_str;
	if (dict->Get(key_value->key, &value) &&
	value->GetAsString(&value_str) &&
	value_str == key_value->value)
	return true;

	// Recurse to test arguments
	DictionaryValue* args_dict = NULL;
	dict->GetDictionary("args", &args_dict);
	if (args_dict)
	return IsKeyValueInDict(key_value, args_dict);

	return false;
	}

	static bool IsAllKeyValueInDict(const JsonKeyValue* key_values,
	DictionaryValue* dict) {
	// Scan all key_values, they must all be present and equal.
	while (key_values && key_values->key) {
	if (!IsKeyValueInDict(key_values, dict))
	return false;
	++key_values;
	}
	return true;
	}

	bool TraceEventTestFixture::FindMatchingTraceEntry(
	const JsonKeyValue* key_values) {
	// 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 (!value \|\| value->GetType() != Value::TYPE_DICTIONARY)
	continue;
	DictionaryValue* dict = static_cast<DictionaryValue*>(value);

	if (IsAllKeyValueInDict(key_values, dict))
	return true;
	}
	return false;
	}

	bool TraceEventTestFixture::FindNamePhase(const char* name, const char* phase) {
	JsonKeyValue key_values[] = {
	{"name", name},
	{"ph", phase},
	{0, 0}
	};
	return FindMatchingTraceEntry(key_values);
	}

	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_);
	}

	// Simple Test for time threshold events.
	TEST_F(TraceEventTestFixture, DataCapturedThreshold) {
	ManualTestSetUp();
	TraceLog::GetInstance()->SetEnabled(true);

	// Test that events at the same level are properly filtered by threshold.
	{
	TRACE_EVENT_IF_LONGER_THAN0(100, "time", "threshold 100");
	TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "threshold 1000");
	TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "threshold 10000");
	// 100+ seconds to avoid flakiness.
	TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "threshold long1");
	TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "threshold long2");
	base::PlatformThread::Sleep(20); // 20000 us
	}

	// Test that a normal nested event remains after it's parent event is dropped.
	{
	TRACE_EVENT_IF_LONGER_THAN0(1000000, "time", "2threshold10000");
	{
	TRACE_EVENT0("time", "nonthreshold1");
	}
	}

	// Test that parent thresholded events are dropped while some nested events
	// remain.
	{
	TRACE_EVENT0("time", "nonthreshold3");
	{
	TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "3thresholdlong2");
	{
	TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "3thresholdlong1");
	{
	TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "3threshold10000");
	{
	TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "3threshold1000");
	{
	TRACE_EVENT_IF_LONGER_THAN0(100, "time", "3threshold100");
	base::PlatformThread::Sleep(20);
	}
	}
	}
	}
	}
	}

	// Test that child thresholded events are dropped while some parent events
	// remain.
	{
	TRACE_EVENT0("time", "nonthreshold4");
	{
	TRACE_EVENT_IF_LONGER_THAN0(100, "time", "4threshold100");
	{
	TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "4threshold1000");
	{
	TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "4threshold10000");
	{
	TRACE_EVENT_IF_LONGER_THAN0(100000000, "time",
	"4thresholdlong1");
	{
	TRACE_EVENT_IF_LONGER_THAN0(200000000, "time",
	"4thresholdlong2");
	base::PlatformThread::Sleep(20);
	}
	}
	}
	}
	}
	}

	TraceLog::GetInstance()->SetEnabled(false);

	#define EXPECT_FIND_BE_(str) \
	EXPECT_TRUE(FindNamePhase(str, "B")); \
	EXPECT_TRUE(FindNamePhase(str, "E"))
	#define EXPECT_NOT_FIND_BE_(str) \
	EXPECT_FALSE(FindNamePhase(str, "B")); \
	EXPECT_FALSE(FindNamePhase(str, "E"))

	EXPECT_FIND_BE_("threshold 100");
	EXPECT_FIND_BE_("threshold 1000");
	EXPECT_FIND_BE_("threshold 10000");
	EXPECT_NOT_FIND_BE_("threshold long1");
	EXPECT_NOT_FIND_BE_("threshold long2");

	EXPECT_NOT_FIND_BE_("2threshold10000");
	EXPECT_FIND_BE_("nonthreshold1");

	EXPECT_FIND_BE_("nonthreshold3");
	EXPECT_FIND_BE_("3threshold100");
	EXPECT_FIND_BE_("3threshold1000");
	EXPECT_FIND_BE_("3threshold10000");
	EXPECT_NOT_FIND_BE_("3thresholdlong1");
	EXPECT_NOT_FIND_BE_("3thresholdlong2");

	EXPECT_FIND_BE_("nonthreshold4");
	EXPECT_FIND_BE_("4threshold100");
	EXPECT_FIND_BE_("4threshold1000");
	EXPECT_FIND_BE_("4threshold10000");
	EXPECT_NOT_FIND_BE_("4thresholdlong1");
	EXPECT_NOT_FIND_BE_("4thresholdlong2");
	}

	// 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");
	}
	}

	TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) {
	// Test that the TRACE_EVENT macros do not deep-copy their string. If they
	// do so it may indicate a performance regression, but more-over it would
	// make the DEEP_COPY overloads redundant.
	ManualTestSetUp();

	std::string name_string("event name");

	TraceLog::GetInstance()->SetEnabled(true);
	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);

	EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name"));
	EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str()));
	}

	TEST_F(TraceEventTestFixture, DeepCopy) {
	ManualTestSetUp();

	static const char kOriginalName1[] = "name1";
	static const char kOriginalName2[] = "name2";
	static const char kOriginalName3[] = "name3";
	std::string name1(kOriginalName1);
	std::string name2(kOriginalName2);
	std::string name3(kOriginalName3);
	std::string arg1("arg1");
	std::string arg2("arg2");
	std::string val1("val1");
	std::string val2("val2");

	TraceLog::GetInstance()->SetEnabled(true);
	TRACE_EVENT_COPY_INSTANT0("category", name1.c_str());
	TRACE_EVENT_COPY_BEGIN1("category", name2.c_str(),
	arg1.c_str(), 5);
	TRACE_EVENT_COPY_END2("category", name3.c_str(),
	arg1.c_str(), val1.c_str(),
	arg2.c_str(), val2.c_str());

	// 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);

	EXPECT_FALSE(FindTraceEntry(trace_parsed_, name1.c_str()));
	EXPECT_FALSE(FindTraceEntry(trace_parsed_, name2.c_str()));
	EXPECT_FALSE(FindTraceEntry(trace_parsed_, name3.c_str()));

	DictionaryValue* entry1 = FindTraceEntry(trace_parsed_, kOriginalName1);
	DictionaryValue* entry2 = FindTraceEntry(trace_parsed_, kOriginalName2);
	DictionaryValue* entry3 = FindTraceEntry(trace_parsed_, kOriginalName3);
	ASSERT_TRUE(entry1);
	ASSERT_TRUE(entry2);
	ASSERT_TRUE(entry3);

	int i;
	EXPECT_FALSE(entry2->GetInteger("args.@rg1", &i));
	EXPECT_TRUE(entry2->GetInteger("args.arg1", &i));
	EXPECT_EQ(5, i);

	std::string s;
	EXPECT_TRUE(entry3->GetString("args.arg1", &s));
	EXPECT_EQ("val1", s);
	EXPECT_TRUE(entry3->GetString("args.arg2", &s));
	EXPECT_EQ("val2", s);
	}

	} // namespace debug
	} // namespace base