scheib@chromium.org | 603f46e | 2011-05-10 11:23:58 +0900 | [diff] [blame] | 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 | |
jbates@chromium.org | b3cab86 | 2011-05-14 08:30:35 +0900 | [diff] [blame] | 24 | struct JsonKeyValue { |
| 25 | const char* key; |
| 26 | const char* value; |
| 27 | }; |
| 28 | |
scheib@chromium.org | 603f46e | 2011-05-10 11:23:58 +0900 | [diff] [blame] | 29 | class TraceEventTestFixture : public testing::Test { |
| 30 | public: |
| 31 | void ManualTestSetUp(); |
ajwong@chromium.org | ec1750a | 2011-06-27 01:22:50 +0900 | [diff] [blame^] | 32 | void OnTraceDataCollected( |
| 33 | scoped_refptr<TraceLog::RefCountedString> json_events_str); |
jbates@chromium.org | b3cab86 | 2011-05-14 08:30:35 +0900 | [diff] [blame] | 34 | bool FindMatchingTraceEntry(const JsonKeyValue* key_values); |
| 35 | bool FindNamePhase(const char* name, const char* phase); |
scheib@chromium.org | 603f46e | 2011-05-10 11:23:58 +0900 | [diff] [blame] | 36 | |
| 37 | std::string trace_string_; |
| 38 | ListValue trace_parsed_; |
| 39 | |
| 40 | private: |
| 41 | // We want our singleton torn down after each test. |
| 42 | ShadowingAtExitManager at_exit_manager_; |
| 43 | }; |
| 44 | |
| 45 | void TraceEventTestFixture::ManualTestSetUp() { |
| 46 | TraceLog::Resurrect(); |
| 47 | TraceLog* tracelog = TraceLog::GetInstance(); |
| 48 | ASSERT_TRUE(tracelog); |
| 49 | ASSERT_FALSE(tracelog->IsEnabled()); |
| 50 | tracelog->SetOutputCallback( |
| 51 | base::Bind(&TraceEventTestFixture::OnTraceDataCollected, |
| 52 | base::Unretained(this))); |
| 53 | } |
| 54 | |
| 55 | void TraceEventTestFixture::OnTraceDataCollected( |
ajwong@chromium.org | ec1750a | 2011-06-27 01:22:50 +0900 | [diff] [blame^] | 56 | scoped_refptr<TraceLog::RefCountedString> json_events_str) { |
scheib@chromium.org | 603f46e | 2011-05-10 11:23:58 +0900 | [diff] [blame] | 57 | trace_string_ += json_events_str->data; |
| 58 | |
| 59 | scoped_ptr<Value> root; |
| 60 | root.reset(base::JSONReader::Read(json_events_str->data, false)); |
| 61 | |
| 62 | ListValue* root_list = NULL; |
| 63 | ASSERT_TRUE(root.get()); |
| 64 | ASSERT_TRUE(root->GetAsList(&root_list)); |
| 65 | |
| 66 | // Move items into our aggregate collection |
| 67 | while (root_list->GetSize()) { |
| 68 | Value* item = NULL; |
| 69 | root_list->Remove(0, &item); |
| 70 | trace_parsed_.Append(item); |
| 71 | } |
| 72 | } |
| 73 | |
jbates@chromium.org | b3cab86 | 2011-05-14 08:30:35 +0900 | [diff] [blame] | 74 | static bool IsKeyValueInDict(const JsonKeyValue* key_value, |
| 75 | DictionaryValue* dict) { |
| 76 | Value* value = NULL; |
| 77 | std::string value_str; |
| 78 | if (dict->Get(key_value->key, &value) && |
| 79 | value->GetAsString(&value_str) && |
| 80 | value_str == key_value->value) |
| 81 | return true; |
| 82 | |
| 83 | // Recurse to test arguments |
| 84 | DictionaryValue* args_dict = NULL; |
| 85 | dict->GetDictionary("args", &args_dict); |
| 86 | if (args_dict) |
| 87 | return IsKeyValueInDict(key_value, args_dict); |
| 88 | |
| 89 | return false; |
| 90 | } |
| 91 | |
| 92 | static bool IsAllKeyValueInDict(const JsonKeyValue* key_values, |
| 93 | DictionaryValue* dict) { |
| 94 | // Scan all key_values, they must all be present and equal. |
| 95 | while (key_values && key_values->key) { |
| 96 | if (!IsKeyValueInDict(key_values, dict)) |
| 97 | return false; |
| 98 | ++key_values; |
| 99 | } |
| 100 | return true; |
| 101 | } |
| 102 | |
| 103 | bool TraceEventTestFixture::FindMatchingTraceEntry( |
| 104 | const JsonKeyValue* key_values) { |
| 105 | // Scan all items |
| 106 | size_t trace_parsed_count = trace_parsed_.GetSize(); |
| 107 | for (size_t i = 0; i < trace_parsed_count; i++) { |
| 108 | Value* value = NULL; |
| 109 | trace_parsed_.Get(i, &value); |
| 110 | if (!value || value->GetType() != Value::TYPE_DICTIONARY) |
| 111 | continue; |
| 112 | DictionaryValue* dict = static_cast<DictionaryValue*>(value); |
| 113 | |
| 114 | if (IsAllKeyValueInDict(key_values, dict)) |
| 115 | return true; |
| 116 | } |
| 117 | return false; |
| 118 | } |
| 119 | |
| 120 | bool TraceEventTestFixture::FindNamePhase(const char* name, const char* phase) { |
| 121 | JsonKeyValue key_values[] = { |
| 122 | {"name", name}, |
| 123 | {"ph", phase}, |
| 124 | {0, 0} |
| 125 | }; |
| 126 | return FindMatchingTraceEntry(key_values); |
| 127 | } |
| 128 | |
scheib@chromium.org | 603f46e | 2011-05-10 11:23:58 +0900 | [diff] [blame] | 129 | bool IsStringInDict(const char* string_to_match, DictionaryValue* dict) { |
| 130 | for (DictionaryValue::key_iterator ikey = dict->begin_keys(); |
| 131 | ikey != dict->end_keys(); ++ikey) { |
| 132 | Value* child = NULL; |
| 133 | if (!dict->GetWithoutPathExpansion(*ikey, &child)) |
| 134 | continue; |
| 135 | |
| 136 | if ((*ikey).find(string_to_match) != std::string::npos) |
| 137 | return true; |
| 138 | |
| 139 | std::string value_str; |
| 140 | child->GetAsString(&value_str); |
| 141 | if (value_str.find(string_to_match) != std::string::npos) |
| 142 | return true; |
| 143 | } |
| 144 | |
| 145 | // Recurse to test arguments |
| 146 | DictionaryValue* args_dict = NULL; |
| 147 | dict->GetDictionary("args", &args_dict); |
| 148 | if (args_dict) |
| 149 | return IsStringInDict(string_to_match, args_dict); |
| 150 | |
| 151 | return false; |
| 152 | } |
| 153 | |
| 154 | DictionaryValue* FindTraceEntry(const ListValue& trace_parsed, |
| 155 | const char *string_to_match, |
| 156 | DictionaryValue* match_after_this_item = NULL) { |
| 157 | // Scan all items |
| 158 | size_t trace_parsed_count = trace_parsed.GetSize(); |
| 159 | for (size_t i = 0; i < trace_parsed_count; i++) { |
| 160 | Value* value = NULL; |
| 161 | trace_parsed.Get(i, &value); |
| 162 | if (match_after_this_item) { |
| 163 | if (value == match_after_this_item) |
| 164 | match_after_this_item = NULL; |
| 165 | continue; |
| 166 | } |
| 167 | if (!value || value->GetType() != Value::TYPE_DICTIONARY) |
| 168 | continue; |
| 169 | DictionaryValue* dict = static_cast<DictionaryValue*>(value); |
| 170 | |
| 171 | if (IsStringInDict(string_to_match, dict)) |
| 172 | return dict; |
| 173 | } |
| 174 | return NULL; |
| 175 | } |
| 176 | |
| 177 | void DataCapturedCallTraces(WaitableEvent* task_complete_event) { |
| 178 | { |
| 179 | TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 1122, "extrastring1"); |
| 180 | TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 3344, "extrastring2"); |
| 181 | TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW call", |
| 182 | 5566, "extrastring3"); |
| 183 | |
| 184 | TRACE_EVENT0("all", "TRACE_EVENT0 call"); |
| 185 | TRACE_EVENT1("all", "TRACE_EVENT1 call", "name1", "value1"); |
| 186 | TRACE_EVENT2("all", "TRACE_EVENT2 call", |
| 187 | "name1", "value1", |
| 188 | "name2", "value2"); |
| 189 | |
| 190 | TRACE_EVENT_INSTANT0("all", "TRACE_EVENT_INSTANT0 call"); |
| 191 | TRACE_EVENT_INSTANT1("all", "TRACE_EVENT_INSTANT1 call", "name1", "value1"); |
| 192 | TRACE_EVENT_INSTANT2("all", "TRACE_EVENT_INSTANT2 call", |
| 193 | "name1", "value1", |
| 194 | "name2", "value2"); |
| 195 | |
| 196 | TRACE_EVENT_BEGIN0("all", "TRACE_EVENT_BEGIN0 call"); |
| 197 | TRACE_EVENT_BEGIN1("all", "TRACE_EVENT_BEGIN1 call", "name1", "value1"); |
| 198 | TRACE_EVENT_BEGIN2("all", "TRACE_EVENT_BEGIN2 call", |
| 199 | "name1", "value1", |
| 200 | "name2", "value2"); |
| 201 | |
| 202 | TRACE_EVENT_END0("all", "TRACE_EVENT_END0 call"); |
| 203 | TRACE_EVENT_END1("all", "TRACE_EVENT_END1 call", "name1", "value1"); |
| 204 | TRACE_EVENT_END2("all", "TRACE_EVENT_END2 call", |
| 205 | "name1", "value1", |
| 206 | "name2", "value2"); |
| 207 | } // Scope close causes TRACE_EVENT0 etc to send their END events. |
| 208 | |
| 209 | if (task_complete_event) |
| 210 | task_complete_event->Signal(); |
| 211 | } |
| 212 | |
| 213 | void DataCapturedValidateTraces(const ListValue& trace_parsed, |
| 214 | const std::string& trace_string) { |
| 215 | DictionaryValue* item = NULL; |
| 216 | |
| 217 | #define EXPECT_FIND_(string) \ |
| 218 | EXPECT_TRUE((item = FindTraceEntry(trace_parsed, string))); |
| 219 | #define EXPECT_NOT_FIND_(string) \ |
| 220 | EXPECT_FALSE((item = FindTraceEntry(trace_parsed, string))); |
| 221 | #define EXPECT_SUB_FIND_(string) \ |
| 222 | if (item) EXPECT_TRUE((IsStringInDict(string, item))); |
| 223 | |
| 224 | EXPECT_FIND_("ETW Trace Event"); |
| 225 | EXPECT_FIND_("all"); |
| 226 | EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW call"); |
| 227 | { |
| 228 | int int_val = 0; |
| 229 | EXPECT_TRUE(item && item->GetInteger("args.id", &int_val)); |
| 230 | EXPECT_EQ(1122, int_val); |
| 231 | } |
| 232 | EXPECT_SUB_FIND_("extrastring1"); |
| 233 | EXPECT_FIND_("TRACE_EVENT_END_ETW call"); |
| 234 | EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW call"); |
| 235 | EXPECT_FIND_("TRACE_EVENT0 call"); |
| 236 | { |
| 237 | std::string ph_begin; |
| 238 | std::string ph_end; |
| 239 | EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call"))); |
| 240 | EXPECT_TRUE((item && item->GetString("ph", &ph_begin))); |
| 241 | EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call", |
| 242 | item))); |
| 243 | EXPECT_TRUE((item && item->GetString("ph", &ph_end))); |
| 244 | EXPECT_EQ("B", ph_begin); |
| 245 | EXPECT_EQ("E", ph_end); |
| 246 | } |
| 247 | EXPECT_FIND_("TRACE_EVENT1 call"); |
| 248 | EXPECT_FIND_("TRACE_EVENT2 call"); |
| 249 | EXPECT_SUB_FIND_("name1"); |
| 250 | EXPECT_SUB_FIND_("value1"); |
| 251 | EXPECT_SUB_FIND_("name2"); |
| 252 | EXPECT_SUB_FIND_("value2"); |
| 253 | EXPECT_FIND_("TRACE_EVENT_INSTANT0 call"); |
| 254 | EXPECT_FIND_("TRACE_EVENT_INSTANT1 call"); |
| 255 | EXPECT_FIND_("TRACE_EVENT_INSTANT2 call"); |
| 256 | EXPECT_SUB_FIND_("name1"); |
| 257 | EXPECT_SUB_FIND_("value1"); |
| 258 | EXPECT_SUB_FIND_("name2"); |
| 259 | EXPECT_SUB_FIND_("value2"); |
| 260 | EXPECT_FIND_("TRACE_EVENT_BEGIN0 call"); |
| 261 | EXPECT_FIND_("TRACE_EVENT_BEGIN1 call"); |
| 262 | EXPECT_FIND_("TRACE_EVENT_BEGIN2 call"); |
| 263 | EXPECT_SUB_FIND_("name1"); |
| 264 | EXPECT_SUB_FIND_("value1"); |
| 265 | EXPECT_SUB_FIND_("name2"); |
| 266 | EXPECT_SUB_FIND_("value2"); |
| 267 | EXPECT_FIND_("TRACE_EVENT_END0 call"); |
| 268 | EXPECT_FIND_("TRACE_EVENT_END1 call"); |
| 269 | EXPECT_FIND_("TRACE_EVENT_END2 call"); |
| 270 | EXPECT_SUB_FIND_("name1"); |
| 271 | EXPECT_SUB_FIND_("value1"); |
| 272 | EXPECT_SUB_FIND_("name2"); |
| 273 | EXPECT_SUB_FIND_("value2"); |
| 274 | } |
| 275 | |
| 276 | } // namespace |
| 277 | |
| 278 | // Simple Test for emitting data and validating it was received. |
| 279 | TEST_F(TraceEventTestFixture, DataCaptured) { |
| 280 | ManualTestSetUp(); |
| 281 | TraceLog::GetInstance()->SetEnabled(true); |
| 282 | |
| 283 | DataCapturedCallTraces(NULL); |
| 284 | |
| 285 | TraceLog::GetInstance()->SetEnabled(false); |
| 286 | |
| 287 | DataCapturedValidateTraces(trace_parsed_, trace_string_); |
| 288 | } |
| 289 | |
jbates@chromium.org | b3cab86 | 2011-05-14 08:30:35 +0900 | [diff] [blame] | 290 | // Simple Test for time threshold events. |
| 291 | TEST_F(TraceEventTestFixture, DataCapturedThreshold) { |
| 292 | ManualTestSetUp(); |
| 293 | TraceLog::GetInstance()->SetEnabled(true); |
| 294 | |
| 295 | // Test that events at the same level are properly filtered by threshold. |
| 296 | { |
| 297 | TRACE_EVENT_IF_LONGER_THAN0(100, "time", "threshold 100"); |
| 298 | TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "threshold 1000"); |
| 299 | TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "threshold 10000"); |
| 300 | // 100+ seconds to avoid flakiness. |
| 301 | TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "threshold long1"); |
| 302 | TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "threshold long2"); |
| 303 | base::PlatformThread::Sleep(20); // 20000 us |
| 304 | } |
| 305 | |
| 306 | // Test that a normal nested event remains after it's parent event is dropped. |
| 307 | { |
| 308 | TRACE_EVENT_IF_LONGER_THAN0(1000000, "time", "2threshold10000"); |
| 309 | { |
| 310 | TRACE_EVENT0("time", "nonthreshold1"); |
| 311 | } |
| 312 | } |
| 313 | |
| 314 | // Test that parent thresholded events are dropped while some nested events |
| 315 | // remain. |
| 316 | { |
| 317 | TRACE_EVENT0("time", "nonthreshold3"); |
| 318 | { |
| 319 | TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "3thresholdlong2"); |
| 320 | { |
| 321 | TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "3thresholdlong1"); |
| 322 | { |
| 323 | TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "3threshold10000"); |
| 324 | { |
| 325 | TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "3threshold1000"); |
| 326 | { |
| 327 | TRACE_EVENT_IF_LONGER_THAN0(100, "time", "3threshold100"); |
| 328 | base::PlatformThread::Sleep(20); |
| 329 | } |
| 330 | } |
| 331 | } |
| 332 | } |
| 333 | } |
| 334 | } |
| 335 | |
| 336 | // Test that child thresholded events are dropped while some parent events |
| 337 | // remain. |
| 338 | { |
| 339 | TRACE_EVENT0("time", "nonthreshold4"); |
| 340 | { |
| 341 | TRACE_EVENT_IF_LONGER_THAN0(100, "time", "4threshold100"); |
| 342 | { |
| 343 | TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "4threshold1000"); |
| 344 | { |
| 345 | TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "4threshold10000"); |
| 346 | { |
| 347 | TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", |
| 348 | "4thresholdlong1"); |
| 349 | { |
| 350 | TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", |
| 351 | "4thresholdlong2"); |
| 352 | base::PlatformThread::Sleep(20); |
| 353 | } |
| 354 | } |
| 355 | } |
| 356 | } |
| 357 | } |
| 358 | } |
| 359 | |
| 360 | TraceLog::GetInstance()->SetEnabled(false); |
| 361 | |
| 362 | #define EXPECT_FIND_BE_(str) \ |
| 363 | EXPECT_TRUE(FindNamePhase(str, "B")); \ |
| 364 | EXPECT_TRUE(FindNamePhase(str, "E")) |
| 365 | #define EXPECT_NOT_FIND_BE_(str) \ |
| 366 | EXPECT_FALSE(FindNamePhase(str, "B")); \ |
| 367 | EXPECT_FALSE(FindNamePhase(str, "E")) |
| 368 | |
| 369 | EXPECT_FIND_BE_("threshold 100"); |
| 370 | EXPECT_FIND_BE_("threshold 1000"); |
| 371 | EXPECT_FIND_BE_("threshold 10000"); |
| 372 | EXPECT_NOT_FIND_BE_("threshold long1"); |
| 373 | EXPECT_NOT_FIND_BE_("threshold long2"); |
| 374 | |
| 375 | EXPECT_NOT_FIND_BE_("2threshold10000"); |
| 376 | EXPECT_FIND_BE_("nonthreshold1"); |
| 377 | |
| 378 | EXPECT_FIND_BE_("nonthreshold3"); |
| 379 | EXPECT_FIND_BE_("3threshold100"); |
| 380 | EXPECT_FIND_BE_("3threshold1000"); |
| 381 | EXPECT_FIND_BE_("3threshold10000"); |
| 382 | EXPECT_NOT_FIND_BE_("3thresholdlong1"); |
| 383 | EXPECT_NOT_FIND_BE_("3thresholdlong2"); |
| 384 | |
| 385 | EXPECT_FIND_BE_("nonthreshold4"); |
| 386 | EXPECT_FIND_BE_("4threshold100"); |
| 387 | EXPECT_FIND_BE_("4threshold1000"); |
| 388 | EXPECT_FIND_BE_("4threshold10000"); |
| 389 | EXPECT_NOT_FIND_BE_("4thresholdlong1"); |
| 390 | EXPECT_NOT_FIND_BE_("4thresholdlong2"); |
| 391 | } |
| 392 | |
scheib@chromium.org | 603f46e | 2011-05-10 11:23:58 +0900 | [diff] [blame] | 393 | // Test that data sent from other threads is gathered |
| 394 | TEST_F(TraceEventTestFixture, DataCapturedOnThread) { |
| 395 | ManualTestSetUp(); |
| 396 | TraceLog::GetInstance()->SetEnabled(true); |
| 397 | |
| 398 | Thread thread("1"); |
| 399 | WaitableEvent task_complete_event(false, false); |
| 400 | thread.Start(); |
| 401 | |
| 402 | thread.message_loop()->PostTask( |
| 403 | FROM_HERE, NewRunnableFunction(&DataCapturedCallTraces, |
| 404 | &task_complete_event)); |
| 405 | task_complete_event.Wait(); |
| 406 | |
| 407 | TraceLog::GetInstance()->SetEnabled(false); |
| 408 | thread.Stop(); |
| 409 | DataCapturedValidateTraces(trace_parsed_, trace_string_); |
| 410 | } |
| 411 | |
| 412 | namespace { |
| 413 | |
| 414 | void DataCapturedCallManyTraces(int thread_id, int num_events, |
| 415 | WaitableEvent* task_complete_event) { |
| 416 | for (int i = 0; i < num_events; i++) { |
| 417 | TRACE_EVENT_INSTANT2("all", "multi thread event", |
| 418 | "thread", thread_id, |
| 419 | "event", i); |
| 420 | } |
| 421 | |
| 422 | if (task_complete_event) |
| 423 | task_complete_event->Signal(); |
| 424 | } |
| 425 | |
| 426 | void DataCapturedValidateManyTraces(const ListValue& trace_parsed, |
| 427 | const std::string& trace_string, |
| 428 | int num_threads, int num_events) { |
| 429 | std::map<int, std::map<int, bool> > results; |
| 430 | |
| 431 | size_t trace_parsed_count = trace_parsed.GetSize(); |
| 432 | for (size_t i = 0; i < trace_parsed_count; i++) { |
| 433 | Value* value = NULL; |
| 434 | trace_parsed.Get(i, &value); |
| 435 | if (!value || value->GetType() != Value::TYPE_DICTIONARY) |
| 436 | continue; |
| 437 | DictionaryValue* dict = static_cast<DictionaryValue*>(value); |
| 438 | std::string name; |
| 439 | dict->GetString("name", &name); |
| 440 | if (name != "multi thread event") |
| 441 | continue; |
| 442 | |
| 443 | int thread = 0; |
| 444 | int event = 0; |
| 445 | EXPECT_TRUE(dict->GetInteger("args.thread", &thread)); |
| 446 | EXPECT_TRUE(dict->GetInteger("args.event", &event)); |
| 447 | results[thread][event] = true; |
| 448 | } |
| 449 | |
| 450 | EXPECT_FALSE(results[-1][-1]); |
| 451 | for (int thread = 0; thread < num_threads; thread++) { |
| 452 | for (int event = 0; event < num_events; event++) { |
| 453 | EXPECT_TRUE(results[thread][event]); |
| 454 | } |
| 455 | } |
| 456 | } |
| 457 | |
| 458 | } // namespace |
| 459 | |
| 460 | // Test that data sent from multiple threads is gathered |
| 461 | TEST_F(TraceEventTestFixture, DataCapturedManyThreads) { |
| 462 | ManualTestSetUp(); |
| 463 | TraceLog::GetInstance()->SetEnabled(true); |
| 464 | |
| 465 | const int num_threads = 4; |
| 466 | const int num_events = 4000; |
| 467 | Thread* threads[num_threads]; |
| 468 | WaitableEvent* task_complete_events[num_threads]; |
| 469 | for (int i = 0; i < num_threads; i++) { |
| 470 | threads[i] = new Thread(StringPrintf("Thread %d", i).c_str()); |
| 471 | task_complete_events[i] = new WaitableEvent(false, false); |
| 472 | threads[i]->Start(); |
| 473 | threads[i]->message_loop()->PostTask( |
| 474 | FROM_HERE, NewRunnableFunction(&DataCapturedCallManyTraces, |
| 475 | i, num_events, task_complete_events[i])); |
| 476 | } |
| 477 | |
| 478 | for (int i = 0; i < num_threads; i++) { |
| 479 | task_complete_events[i]->Wait(); |
| 480 | } |
| 481 | |
| 482 | TraceLog::GetInstance()->SetEnabled(false); |
| 483 | |
| 484 | for (int i = 0; i < num_threads; i++) { |
| 485 | threads[i]->Stop(); |
| 486 | delete threads[i]; |
| 487 | delete task_complete_events[i]; |
| 488 | } |
| 489 | |
| 490 | DataCapturedValidateManyTraces(trace_parsed_, trace_string_, |
| 491 | num_threads, num_events); |
| 492 | } |
| 493 | |
| 494 | void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) { |
| 495 | TRACE_EVENT0("category name1", name_str); |
| 496 | TRACE_EVENT_INSTANT0("category name2", name_str); |
| 497 | TRACE_EVENT_BEGIN0("category name3", name_str); |
| 498 | TRACE_EVENT_END0("category name4", name_str); |
| 499 | } |
| 500 | |
| 501 | // Test trace calls made after tracing singleton shut down. |
| 502 | // |
| 503 | // The singleton is destroyed by our base::AtExitManager, but there can be |
| 504 | // code still executing as the C++ static objects are destroyed. This test |
| 505 | // forces the singleton to destroy early, and intentinally makes trace calls |
| 506 | // afterwards. |
| 507 | TEST_F(TraceEventTestFixture, AtExit) { |
| 508 | // Repeat this test a few times. Besides just showing robustness, it also |
| 509 | // allows us to test that events at shutdown do not appear with valid events |
| 510 | // recorded after the system is started again. |
| 511 | for (int i = 0; i < 4; i++) { |
| 512 | // Scope to contain the then destroy the TraceLog singleton. |
| 513 | { |
| 514 | base::ShadowingAtExitManager exit_manager_will_destroy_singletons; |
| 515 | |
| 516 | // Setup TraceLog singleton inside this test's exit manager scope |
| 517 | // so that it will be destroyed when this scope closes. |
| 518 | ManualTestSetUp(); |
| 519 | |
| 520 | TRACE_EVENT_INSTANT0("all", "not recorded; system not enabled"); |
| 521 | |
| 522 | TraceLog::GetInstance()->SetEnabled(true); |
| 523 | |
| 524 | TRACE_EVENT_INSTANT0("all", "is recorded 1; system has been enabled"); |
| 525 | // Trace calls that will cache pointers to categories; they're valid here |
| 526 | TraceCallsWithCachedCategoryPointersPointers( |
| 527 | "is recorded 2; system has been enabled"); |
| 528 | |
| 529 | TraceLog::GetInstance()->SetEnabled(false); |
| 530 | } // scope to destroy singleton |
| 531 | ASSERT_FALSE(TraceLog::GetInstance()); |
| 532 | |
| 533 | // Now that singleton is destroyed, check what trace events were recorded |
| 534 | DictionaryValue* item = NULL; |
| 535 | ListValue& trace_parsed = trace_parsed_; |
| 536 | EXPECT_FIND_("is recorded 1"); |
| 537 | EXPECT_FIND_("is recorded 2"); |
| 538 | EXPECT_NOT_FIND_("not recorded"); |
| 539 | |
| 540 | // Make additional trace event calls on the shutdown system. They should |
| 541 | // all pass cleanly, but the data not be recorded. We'll verify that next |
| 542 | // time around the loop (the only way to flush the trace buffers). |
| 543 | TRACE_EVENT_BEGIN_ETW("not recorded; system shutdown", 0, NULL); |
| 544 | TRACE_EVENT_END_ETW("not recorded; system shutdown", 0, NULL); |
| 545 | TRACE_EVENT_INSTANT_ETW("not recorded; system shutdown", 0, NULL); |
| 546 | TRACE_EVENT0("all", "not recorded; system shutdown"); |
| 547 | TRACE_EVENT_INSTANT0("all", "not recorded; system shutdown"); |
| 548 | TRACE_EVENT_BEGIN0("all", "not recorded; system shutdown"); |
| 549 | TRACE_EVENT_END0("all", "not recorded; system shutdown"); |
| 550 | |
| 551 | TRACE_EVENT0("new category 0!", "not recorded; system shutdown"); |
| 552 | TRACE_EVENT_INSTANT0("new category 1!", "not recorded; system shutdown"); |
| 553 | TRACE_EVENT_BEGIN0("new category 2!", "not recorded; system shutdown"); |
| 554 | TRACE_EVENT_END0("new category 3!", "not recorded; system shutdown"); |
| 555 | |
| 556 | // Cached categories should be safe to check, and still disable traces |
| 557 | TraceCallsWithCachedCategoryPointersPointers( |
| 558 | "not recorded; system shutdown"); |
| 559 | } |
| 560 | } |
| 561 | |
| 562 | } // namespace debug |
| 563 | } // namespace base |