| OLD | NEW |
|---|
| (Empty) |
| 1 // Copyright (c) 2011 The Chromium Authors. All rights reserved. | |
| 2 // Use of this source code is governed by a BSD-style license that can be | |
| 3 // found in the LICENSE file. | |
| 4 | |
| 5 #include "base/debug/trace_event.h" | |
| 6 | |
| 7 #include "base/bind.h" | |
| 8 #include "base/command_line.h" | |
| 9 #include "base/json/json_reader.h" | |
| 10 #include "base/json/json_writer.h" | |
| 11 #include "base/memory/scoped_ptr.h" | |
| 12 #include "base/stringprintf.h" | |
| 13 #include "base/synchronization/waitable_event.h" | |
| 14 #include "base/threading/thread.h" | |
| 15 #include "base/values.h" | |
| 16 #include "testing/gmock/include/gmock/gmock.h" | |
| 17 #include "testing/gtest/include/gtest/gtest.h" | |
| 18 | |
| 19 namespace base { | |
| 20 namespace debug { | |
| 21 | |
| 22 namespace { | |
| 23 | |
| 24 class TraceEventTestFixture : public testing::Test { | |
| 25 public: | |
| 26 void ManualTestSetUp(); | |
| 27 void OnTraceDataCollected(TraceLog::RefCountedString* json_events_str); | |
| 28 | |
| 29 std::string trace_string_; | |
| 30 ListValue trace_parsed_; | |
| 31 | |
| 32 private: | |
| 33 // We want our singleton torn down after each test. | |
| 34 ShadowingAtExitManager at_exit_manager_; | |
| 35 }; | |
| 36 | |
| 37 void TraceEventTestFixture::ManualTestSetUp() { | |
| 38 TraceLog::Resurrect(); | |
| 39 TraceLog* tracelog = TraceLog::GetInstance(); | |
| 40 ASSERT_TRUE(tracelog); | |
| 41 ASSERT_FALSE(tracelog->IsEnabled()); | |
| 42 tracelog->SetOutputCallback( | |
| 43 base::Bind(&TraceEventTestFixture::OnTraceDataCollected, | |
| 44 base::Unretained(this))); | |
| 45 } | |
| 46 | |
| 47 void TraceEventTestFixture::OnTraceDataCollected( | |
| 48 TraceLog::RefCountedString* json_events_str) { | |
| 49 trace_string_ += json_events_str->data; | |
| 50 | |
| 51 scoped_ptr<Value> root; | |
| 52 root.reset(base::JSONReader::Read(json_events_str->data, false)); | |
| 53 | |
| 54 ListValue* root_list = NULL; | |
| 55 ASSERT_TRUE(root.get()); | |
| 56 ASSERT_TRUE(root->GetAsList(&root_list)); | |
| 57 | |
| 58 // Move items into our aggregate collection | |
| 59 while (root_list->GetSize()) { | |
| 60 Value* item = NULL; | |
| 61 root_list->Remove(0, &item); | |
| 62 trace_parsed_.Append(item); | |
| 63 } | |
| 64 } | |
| 65 | |
| 66 bool IsStringInDict(const char* string_to_match, DictionaryValue* dict) { | |
| 67 for (DictionaryValue::key_iterator ikey = dict->begin_keys(); | |
| 68 ikey != dict->end_keys(); ++ikey) { | |
| 69 Value* child = NULL; | |
| 70 if (!dict->GetWithoutPathExpansion(*ikey, &child)) | |
| 71 continue; | |
| 72 | |
| 73 if ((*ikey).find(string_to_match) != std::string::npos) | |
| 74 return true; | |
| 75 | |
| 76 std::string value_str; | |
| 77 child->GetAsString(&value_str); | |
| 78 if (value_str.find(string_to_match) != std::string::npos) | |
| 79 return true; | |
| 80 } | |
| 81 | |
| 82 // Recurse to test arguments | |
| 83 DictionaryValue* args_dict = NULL; | |
| 84 dict->GetDictionary("args", &args_dict); | |
| 85 if (args_dict) | |
| 86 return IsStringInDict(string_to_match, args_dict); | |
| 87 | |
| 88 return false; | |
| 89 } | |
| 90 | |
| 91 DictionaryValue* FindTraceEntry(const ListValue& trace_parsed, | |
| 92 const char *string_to_match, | |
| 93 DictionaryValue* match_after_this_item = NULL) { | |
| 94 // Scan all items | |
| 95 size_t trace_parsed_count = trace_parsed.GetSize(); | |
| 96 for (size_t i = 0; i < trace_parsed_count; i++) { | |
| 97 Value* value = NULL; | |
| 98 trace_parsed.Get(i, &value); | |
| 99 if (match_after_this_item) { | |
| 100 if (value == match_after_this_item) | |
| 101 match_after_this_item = NULL; | |
| 102 continue; | |
| 103 } | |
| 104 if (!value || value->GetType() != Value::TYPE_DICTIONARY) | |
| 105 continue; | |
| 106 DictionaryValue* dict = static_cast<DictionaryValue*>(value); | |
| 107 | |
| 108 if (IsStringInDict(string_to_match, dict)) | |
| 109 return dict; | |
| 110 } | |
| 111 return NULL; | |
| 112 } | |
| 113 | |
| 114 void DataCapturedCallTraces(WaitableEvent* task_complete_event) { | |
| 115 { | |
| 116 TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 1122, "extrastring1"); | |
| 117 TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 3344, "extrastring2"); | |
| 118 TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW call", | |
| 119 5566, "extrastring3"); | |
| 120 | |
| 121 TRACE_EVENT0("all", "TRACE_EVENT0 call"); | |
| 122 TRACE_EVENT1("all", "TRACE_EVENT1 call", "name1", "value1"); | |
| 123 TRACE_EVENT2("all", "TRACE_EVENT2 call", | |
| 124 "name1", "value1", | |
| 125 "name2", "value2"); | |
| 126 | |
| 127 TRACE_EVENT_INSTANT0("all", "TRACE_EVENT_INSTANT0 call"); | |
| 128 TRACE_EVENT_INSTANT1("all", "TRACE_EVENT_INSTANT1 call", "name1", "value1"); | |
| 129 TRACE_EVENT_INSTANT2("all", "TRACE_EVENT_INSTANT2 call", | |
| 130 "name1", "value1", | |
| 131 "name2", "value2"); | |
| 132 | |
| 133 TRACE_EVENT_BEGIN0("all", "TRACE_EVENT_BEGIN0 call"); | |
| 134 TRACE_EVENT_BEGIN1("all", "TRACE_EVENT_BEGIN1 call", "name1", "value1"); | |
| 135 TRACE_EVENT_BEGIN2("all", "TRACE_EVENT_BEGIN2 call", | |
| 136 "name1", "value1", | |
| 137 "name2", "value2"); | |
| 138 | |
| 139 TRACE_EVENT_END0("all", "TRACE_EVENT_END0 call"); | |
| 140 TRACE_EVENT_END1("all", "TRACE_EVENT_END1 call", "name1", "value1"); | |
| 141 TRACE_EVENT_END2("all", "TRACE_EVENT_END2 call", | |
| 142 "name1", "value1", | |
| 143 "name2", "value2"); | |
| 144 } // Scope close causes TRACE_EVENT0 etc to send their END events. | |
| 145 | |
| 146 if (task_complete_event) | |
| 147 task_complete_event->Signal(); | |
| 148 } | |
| 149 | |
| 150 void DataCapturedValidateTraces(const ListValue& trace_parsed, | |
| 151 const std::string& trace_string) { | |
| 152 DictionaryValue* item = NULL; | |
| 153 | |
| 154 #define EXPECT_FIND_(string) \ | |
| 155 EXPECT_TRUE((item = FindTraceEntry(trace_parsed, string))); | |
| 156 #define EXPECT_NOT_FIND_(string) \ | |
| 157 EXPECT_FALSE((item = FindTraceEntry(trace_parsed, string))); | |
| 158 #define EXPECT_SUB_FIND_(string) \ | |
| 159 if (item) EXPECT_TRUE((IsStringInDict(string, item))); | |
| 160 | |
| 161 EXPECT_FIND_("ETW Trace Event"); | |
| 162 EXPECT_FIND_("all"); | |
| 163 EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW call"); | |
| 164 { | |
| 165 int int_val = 0; | |
| 166 EXPECT_TRUE(item && item->GetInteger("args.id", &int_val)); | |
| 167 EXPECT_EQ(1122, int_val); | |
| 168 } | |
| 169 EXPECT_SUB_FIND_("extrastring1"); | |
| 170 EXPECT_FIND_("TRACE_EVENT_END_ETW call"); | |
| 171 EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW call"); | |
| 172 EXPECT_FIND_("TRACE_EVENT0 call"); | |
| 173 { | |
| 174 std::string ph_begin; | |
| 175 std::string ph_end; | |
| 176 EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call"))); | |
| 177 EXPECT_TRUE((item && item->GetString("ph", &ph_begin))); | |
| 178 EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call", | |
| 179 item))); | |
| 180 EXPECT_TRUE((item && item->GetString("ph", &ph_end))); | |
| 181 EXPECT_EQ("B", ph_begin); | |
| 182 EXPECT_EQ("E", ph_end); | |
| 183 } | |
| 184 EXPECT_FIND_("TRACE_EVENT1 call"); | |
| 185 EXPECT_FIND_("TRACE_EVENT2 call"); | |
| 186 EXPECT_SUB_FIND_("name1"); | |
| 187 EXPECT_SUB_FIND_("value1"); | |
| 188 EXPECT_SUB_FIND_("name2"); | |
| 189 EXPECT_SUB_FIND_("value2"); | |
| 190 EXPECT_FIND_("TRACE_EVENT_INSTANT0 call"); | |
| 191 EXPECT_FIND_("TRACE_EVENT_INSTANT1 call"); | |
| 192 EXPECT_FIND_("TRACE_EVENT_INSTANT2 call"); | |
| 193 EXPECT_SUB_FIND_("name1"); | |
| 194 EXPECT_SUB_FIND_("value1"); | |
| 195 EXPECT_SUB_FIND_("name2"); | |
| 196 EXPECT_SUB_FIND_("value2"); | |
| 197 EXPECT_FIND_("TRACE_EVENT_BEGIN0 call"); | |
| 198 EXPECT_FIND_("TRACE_EVENT_BEGIN1 call"); | |
| 199 EXPECT_FIND_("TRACE_EVENT_BEGIN2 call"); | |
| 200 EXPECT_SUB_FIND_("name1"); | |
| 201 EXPECT_SUB_FIND_("value1"); | |
| 202 EXPECT_SUB_FIND_("name2"); | |
| 203 EXPECT_SUB_FIND_("value2"); | |
| 204 EXPECT_FIND_("TRACE_EVENT_END0 call"); | |
| 205 EXPECT_FIND_("TRACE_EVENT_END1 call"); | |
| 206 EXPECT_FIND_("TRACE_EVENT_END2 call"); | |
| 207 EXPECT_SUB_FIND_("name1"); | |
| 208 EXPECT_SUB_FIND_("value1"); | |
| 209 EXPECT_SUB_FIND_("name2"); | |
| 210 EXPECT_SUB_FIND_("value2"); | |
| 211 } | |
| 212 | |
| 213 } // namespace | |
| 214 | |
| 215 // Simple Test for emitting data and validating it was received. | |
| 216 TEST_F(TraceEventTestFixture, DataCaptured) { | |
| 217 ManualTestSetUp(); | |
| 218 TraceLog::GetInstance()->SetEnabled(true); | |
| 219 | |
| 220 DataCapturedCallTraces(NULL); | |
| 221 | |
| 222 TraceLog::GetInstance()->SetEnabled(false); | |
| 223 | |
| 224 DataCapturedValidateTraces(trace_parsed_, trace_string_); | |
| 225 } | |
| 226 | |
| 227 // Test that data sent from other threads is gathered | |
| 228 TEST_F(TraceEventTestFixture, DataCapturedOnThread) { | |
| 229 ManualTestSetUp(); | |
| 230 TraceLog::GetInstance()->SetEnabled(true); | |
| 231 | |
| 232 Thread thread("1"); | |
| 233 WaitableEvent task_complete_event(false, false); | |
| 234 thread.Start(); | |
| 235 | |
| 236 thread.message_loop()->PostTask( | |
| 237 FROM_HERE, NewRunnableFunction(&DataCapturedCallTraces, | |
| 238 &task_complete_event)); | |
| 239 task_complete_event.Wait(); | |
| 240 | |
| 241 TraceLog::GetInstance()->SetEnabled(false); | |
| 242 thread.Stop(); | |
| 243 DataCapturedValidateTraces(trace_parsed_, trace_string_); | |
| 244 } | |
| 245 | |
| 246 namespace { | |
| 247 | |
| 248 void DataCapturedCallManyTraces(int thread_id, int num_events, | |
| 249 WaitableEvent* task_complete_event) { | |
| 250 for (int i = 0; i < num_events; i++) { | |
| 251 TRACE_EVENT_INSTANT2("all", "multi thread event", | |
| 252 "thread", thread_id, | |
| 253 "event", i); | |
| 254 } | |
| 255 | |
| 256 if (task_complete_event) | |
| 257 task_complete_event->Signal(); | |
| 258 } | |
| 259 | |
| 260 void DataCapturedValidateManyTraces(const ListValue& trace_parsed, | |
| 261 const std::string& trace_string, | |
| 262 int num_threads, int num_events) { | |
| 263 std::map<int, std::map<int, bool> > results; | |
| 264 | |
| 265 size_t trace_parsed_count = trace_parsed.GetSize(); | |
| 266 for (size_t i = 0; i < trace_parsed_count; i++) { | |
| 267 Value* value = NULL; | |
| 268 trace_parsed.Get(i, &value); | |
| 269 if (!value || value->GetType() != Value::TYPE_DICTIONARY) | |
| 270 continue; | |
| 271 DictionaryValue* dict = static_cast<DictionaryValue*>(value); | |
| 272 std::string name; | |
| 273 dict->GetString("name", &name); | |
| 274 if (name != "multi thread event") | |
| 275 continue; | |
| 276 | |
| 277 int thread = 0; | |
| 278 int event = 0; | |
| 279 EXPECT_TRUE(dict->GetInteger("args.thread", &thread)); | |
| 280 EXPECT_TRUE(dict->GetInteger("args.event", &event)); | |
| 281 results[thread][event] = true; | |
| 282 } | |
| 283 | |
| 284 EXPECT_FALSE(results[-1][-1]); | |
| 285 for (int thread = 0; thread < num_threads; thread++) { | |
| 286 for (int event = 0; event < num_events; event++) { | |
| 287 EXPECT_TRUE(results[thread][event]); | |
| 288 } | |
| 289 } | |
| 290 } | |
| 291 | |
| 292 } // namespace | |
| 293 | |
| 294 // Test that data sent from multiple threads is gathered | |
| 295 TEST_F(TraceEventTestFixture, DataCapturedManyThreads) { | |
| 296 ManualTestSetUp(); | |
| 297 TraceLog::GetInstance()->SetEnabled(true); | |
| 298 | |
| 299 const int num_threads = 4; | |
| 300 const int num_events = 4000; | |
| 301 Thread* threads[num_threads]; | |
| 302 WaitableEvent* task_complete_events[num_threads]; | |
| 303 for (int i = 0; i < num_threads; i++) { | |
| 304 threads[i] = new Thread(StringPrintf("Thread %d", i).c_str()); | |
| 305 task_complete_events[i] = new WaitableEvent(false, false); | |
| 306 threads[i]->Start(); | |
| 307 threads[i]->message_loop()->PostTask( | |
| 308 FROM_HERE, NewRunnableFunction(&DataCapturedCallManyTraces, | |
| 309 i, num_events, task_complete_events[i])); | |
| 310 } | |
| 311 | |
| 312 for (int i = 0; i < num_threads; i++) { | |
| 313 task_complete_events[i]->Wait(); | |
| 314 } | |
| 315 | |
| 316 TraceLog::GetInstance()->SetEnabled(false); | |
| 317 | |
| 318 for (int i = 0; i < num_threads; i++) { | |
| 319 threads[i]->Stop(); | |
| 320 delete threads[i]; | |
| 321 delete task_complete_events[i]; | |
| 322 } | |
| 323 | |
| 324 DataCapturedValidateManyTraces(trace_parsed_, trace_string_, | |
| 325 num_threads, num_events); | |
| 326 } | |
| 327 | |
| 328 void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) { | |
| 329 TRACE_EVENT0("category name1", name_str); | |
| 330 TRACE_EVENT_INSTANT0("category name2", name_str); | |
| 331 TRACE_EVENT_BEGIN0("category name3", name_str); | |
| 332 TRACE_EVENT_END0("category name4", name_str); | |
| 333 } | |
| 334 | |
| 335 // Test trace calls made after tracing singleton shut down. | |
| 336 // | |
| 337 // The singleton is destroyed by our base::AtExitManager, but there can be | |
| 338 // code still executing as the C++ static objects are destroyed. This test | |
| 339 // forces the singleton to destroy early, and intentinally makes trace calls | |
| 340 // afterwards. | |
| 341 TEST_F(TraceEventTestFixture, AtExit) { | |
| 342 // Repeat this test a few times. Besides just showing robustness, it also | |
| 343 // allows us to test that events at shutdown do not appear with valid events | |
| 344 // recorded after the system is started again. | |
| 345 for (int i = 0; i < 4; i++) { | |
| 346 // Scope to contain the then destroy the TraceLog singleton. | |
| 347 { | |
| 348 base::ShadowingAtExitManager exit_manager_will_destroy_singletons; | |
| 349 | |
| 350 // Setup TraceLog singleton inside this test's exit manager scope | |
| 351 // so that it will be destroyed when this scope closes. | |
| 352 ManualTestSetUp(); | |
| 353 | |
| 354 TRACE_EVENT_INSTANT0("all", "not recorded; system not enabled"); | |
| 355 | |
| 356 TraceLog::GetInstance()->SetEnabled(true); | |
| 357 | |
| 358 TRACE_EVENT_INSTANT0("all", "is recorded 1; system has been enabled"); | |
| 359 // Trace calls that will cache pointers to categories; they're valid here | |
| 360 TraceCallsWithCachedCategoryPointersPointers( | |
| 361 "is recorded 2; system has been enabled"); | |
| 362 | |
| 363 TraceLog::GetInstance()->SetEnabled(false); | |
| 364 } // scope to destroy singleton | |
| 365 ASSERT_FALSE(TraceLog::GetInstance()); | |
| 366 | |
| 367 // Now that singleton is destroyed, check what trace events were recorded | |
| 368 DictionaryValue* item = NULL; | |
| 369 ListValue& trace_parsed = trace_parsed_; | |
| 370 EXPECT_FIND_("is recorded 1"); | |
| 371 EXPECT_FIND_("is recorded 2"); | |
| 372 EXPECT_NOT_FIND_("not recorded"); | |
| 373 | |
| 374 // Make additional trace event calls on the shutdown system. They should | |
| 375 // all pass cleanly, but the data not be recorded. We'll verify that next | |
| 376 // time around the loop (the only way to flush the trace buffers). | |
| 377 TRACE_EVENT_BEGIN_ETW("not recorded; system shutdown", 0, NULL); | |
| 378 TRACE_EVENT_END_ETW("not recorded; system shutdown", 0, NULL); | |
| 379 TRACE_EVENT_INSTANT_ETW("not recorded; system shutdown", 0, NULL); | |
| 380 TRACE_EVENT0("all", "not recorded; system shutdown"); | |
| 381 TRACE_EVENT_INSTANT0("all", "not recorded; system shutdown"); | |
| 382 TRACE_EVENT_BEGIN0("all", "not recorded; system shutdown"); | |
| 383 TRACE_EVENT_END0("all", "not recorded; system shutdown"); | |
| 384 | |
| 385 TRACE_EVENT0("new category 0!", "not recorded; system shutdown"); | |
| 386 TRACE_EVENT_INSTANT0("new category 1!", "not recorded; system shutdown"); | |
| 387 TRACE_EVENT_BEGIN0("new category 2!", "not recorded; system shutdown"); | |
| 388 TRACE_EVENT_END0("new category 3!", "not recorded; system shutdown"); | |
| 389 | |
| 390 // Cached categories should be safe to check, and still disable traces | |
| 391 TraceCallsWithCachedCategoryPointersPointers( | |
| 392 "not recorded; system shutdown"); | |
| 393 } | |
| 394 } | |
| 395 | |
| 396 } // namespace debug | |
| 397 } // namespace base | |
| OLD | NEW |
|---|
Chromium Code Reviews
Issue 6933035:
Revert 84284 - Merge gpu_trace_event back into base/debug/trace_event.Initial land attempt at htt... (Closed)
Base URL: svn://svn.chromium.org/chrome/trunk/src/