blob: b48260cebf06f465b2985ea6349510041bfee10d [file] [log] [blame]
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001// 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
19namespace base {
20namespace debug {
21
22namespace {
23
jbates@chromium.orgb3cab862011-05-14 08:30:35 +090024struct JsonKeyValue {
25 const char* key;
26 const char* value;
27};
28
scheib@chromium.org603f46e2011-05-10 11:23:58 +090029class TraceEventTestFixture : public testing::Test {
30 public:
31 void ManualTestSetUp();
ajwong@chromium.orgec1750a2011-06-27 01:22:50 +090032 void OnTraceDataCollected(
33 scoped_refptr<TraceLog::RefCountedString> json_events_str);
jbates@chromium.orgb3cab862011-05-14 08:30:35 +090034 bool FindMatchingTraceEntry(const JsonKeyValue* key_values);
35 bool FindNamePhase(const char* name, const char* phase);
scheib@chromium.org603f46e2011-05-10 11:23:58 +090036
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
45void 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
55void TraceEventTestFixture::OnTraceDataCollected(
ajwong@chromium.orgec1750a2011-06-27 01:22:50 +090056 scoped_refptr<TraceLog::RefCountedString> json_events_str) {
scheib@chromium.org603f46e2011-05-10 11:23:58 +090057 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.orgb3cab862011-05-14 08:30:35 +090074static 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
92static 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
103bool 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
120bool 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.org603f46e2011-05-10 11:23:58 +0900129bool 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
154DictionaryValue* 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
177void 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
213void 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.
279TEST_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.orgb3cab862011-05-14 08:30:35 +0900290// Simple Test for time threshold events.
291TEST_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.org603f46e2011-05-10 11:23:58 +0900393// Test that data sent from other threads is gathered
394TEST_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
412namespace {
413
414void 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
426void 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
461TEST_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
494void 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.
507TEST_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