blob: b5909845f27c1053b29b68278db598b1e7a14530 [file] [log] [blame]
jbates@chromium.org59c27602012-01-13 12:12:44 +09001// Copyright (c) 2012 The Chromium Authors. All rights reserved.
scheib@chromium.org603f46e2011-05-10 11:23:58 +09002// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
jbates@chromium.org5e2f67d2012-08-16 13:32:49 +09005#include "base/debug/trace_event_unittest.h"
scheib@chromium.org603f46e2011-05-10 11:23:58 +09006
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +09007#include <cstdlib>
8
scheib@chromium.org603f46e2011-05-10 11:23:58 +09009#include "base/bind.h"
10#include "base/command_line.h"
jbates@chromium.org5e2f67d2012-08-16 13:32:49 +090011#include "base/debug/trace_event.h"
scheib@chromium.org603f46e2011-05-10 11:23:58 +090012#include "base/json/json_reader.h"
13#include "base/json/json_writer.h"
jbates@chromium.org1f18e462011-09-07 02:56:24 +090014#include "base/memory/ref_counted_memory.h"
scheib@chromium.org603f46e2011-05-10 11:23:58 +090015#include "base/memory/scoped_ptr.h"
joth@chromium.org088ae012011-11-11 01:26:23 +090016#include "base/memory/singleton.h"
rsesek@chromium.org687756f2013-07-26 06:38:23 +090017#include "base/process/process_handle.h"
avi@chromium.org94bd5732013-06-11 22:36:37 +090018#include "base/strings/stringprintf.h"
scheib@chromium.org603f46e2011-05-10 11:23:58 +090019#include "base/synchronization/waitable_event.h"
joth@chromium.org088ae012011-11-11 01:26:23 +090020#include "base/threading/platform_thread.h"
scheib@chromium.org603f46e2011-05-10 11:23:58 +090021#include "base/threading/thread.h"
22#include "base/values.h"
23#include "testing/gmock/include/gmock/gmock.h"
24#include "testing/gtest/include/gtest/gtest.h"
25
jbates@chromium.org5e2f67d2012-08-16 13:32:49 +090026using base::debug::HighResSleepForTraceTest;
27
scheib@chromium.org603f46e2011-05-10 11:23:58 +090028namespace base {
29namespace debug {
30
31namespace {
32
jbates@chromium.org11d4c362011-09-13 07:03:41 +090033enum CompareOp {
34 IS_EQUAL,
35 IS_NOT_EQUAL,
36};
37
jbates@chromium.orgb3cab862011-05-14 08:30:35 +090038struct JsonKeyValue {
39 const char* key;
40 const char* value;
jbates@chromium.org11d4c362011-09-13 07:03:41 +090041 CompareOp op;
jbates@chromium.orgb3cab862011-05-14 08:30:35 +090042};
43
nduca@chromium.org3e5cb752013-05-04 23:28:07 +090044const int kThreadId = 42;
45const int kAsyncId = 5;
46const char kAsyncIdStr[] = "0x5";
47const int kAsyncId2 = 6;
48const char kAsyncId2Str[] = "0x6";
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +090049
scheib@chromium.org603f46e2011-05-10 11:23:58 +090050class TraceEventTestFixture : public testing::Test {
51 public:
ajwong@chromium.orgec1750a2011-06-27 01:22:50 +090052 void OnTraceDataCollected(
husky@chromium.org3b366292012-02-24 13:17:06 +090053 const scoped_refptr<base::RefCountedString>& events_str);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +090054 void OnTraceNotification(int notification) {
55 if (notification & TraceLog::EVENT_WATCH_NOTIFICATION)
56 ++event_watch_notification_;
jbroman@chromium.org4b3fba72013-08-13 12:06:42 +090057 notifications_received_ |= notification;
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +090058 }
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +090059 DictionaryValue* FindMatchingTraceEntry(const JsonKeyValue* key_values);
60 DictionaryValue* FindNamePhase(const char* name, const char* phase);
61 DictionaryValue* FindNamePhaseKeyValue(const char* name,
62 const char* phase,
63 const char* key,
64 const char* value);
jbates@chromium.org11d4c362011-09-13 07:03:41 +090065 bool FindMatchingValue(const char* key,
66 const char* value);
67 bool FindNonMatchingValue(const char* key,
68 const char* value);
69 void Clear() {
jbates@chromium.org11d4c362011-09-13 07:03:41 +090070 trace_parsed_.Clear();
jbates@chromium.org6a092d72011-10-25 01:34:08 +090071 json_output_.json_output.clear();
jbates@chromium.org11d4c362011-09-13 07:03:41 +090072 }
scheib@chromium.org603f46e2011-05-10 11:23:58 +090073
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +090074 void BeginTrace() {
dsinclair@chromium.org3f838632013-05-08 05:17:27 +090075 BeginSpecificTrace("*");
76 }
77
78 void BeginSpecificTrace(const std::string& filter) {
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +090079 event_watch_notification_ = 0;
caseq@google.com4cba9892013-04-29 18:08:28 +090080 notifications_received_ = 0;
dsinclair@chromium.org3f838632013-05-08 05:17:27 +090081 TraceLog::GetInstance()->SetEnabled(CategoryFilter(filter),
dsinclair@chromium.orga7fb8d62013-02-23 11:09:53 +090082 TraceLog::RECORD_UNTIL_FULL);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +090083 }
84
85 void EndTraceAndFlush() {
caseq@google.comedcf6262013-01-16 20:41:57 +090086 while (TraceLog::GetInstance()->IsEnabled())
87 TraceLog::GetInstance()->SetDisabled();
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +090088 TraceLog::GetInstance()->Flush(
89 base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
90 base::Unretained(this)));
91 }
92
rsleevi@chromium.orgde3a6cf2012-04-06 12:53:02 +090093 virtual void SetUp() OVERRIDE {
dsinclair@chromium.org38608f82013-01-26 05:41:19 +090094 const char* name = PlatformThread::GetName();
95 old_thread_name_ = name ? strdup(name) : NULL;
caseq@google.com4bdbd862013-04-29 21:22:48 +090096 notifications_received_ = 0;
jam@chromium.orga15c6772013-07-09 08:26:14 +090097
98 TraceLog::DeleteForTesting();
99 TraceLog* tracelog = TraceLog::GetInstance();
100 ASSERT_TRUE(tracelog);
101 ASSERT_FALSE(tracelog->IsEnabled());
102 tracelog->SetNotificationCallback(
103 base::Bind(&TraceEventTestFixture::OnTraceNotification,
104 base::Unretained(this)));
105 trace_buffer_.SetOutputCallback(json_output_.GetCallback());
joth@chromium.org088ae012011-11-11 01:26:23 +0900106 }
rsleevi@chromium.orgde3a6cf2012-04-06 12:53:02 +0900107 virtual void TearDown() OVERRIDE {
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900108 if (TraceLog::GetInstance())
109 EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
dsinclair@chromium.org38608f82013-01-26 05:41:19 +0900110 PlatformThread::SetName(old_thread_name_ ? old_thread_name_ : "");
111 free(old_thread_name_);
112 old_thread_name_ = NULL;
jam@chromium.orga15c6772013-07-09 08:26:14 +0900113 // We want our singleton torn down after each test.
114 TraceLog::DeleteForTesting();
joth@chromium.org088ae012011-11-11 01:26:23 +0900115 }
116
dsinclair@chromium.org38608f82013-01-26 05:41:19 +0900117 char* old_thread_name_;
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900118 ListValue trace_parsed_;
jbates@chromium.org6a092d72011-10-25 01:34:08 +0900119 base::debug::TraceResultBuffer trace_buffer_;
120 base::debug::TraceResultBuffer::SimpleOutput json_output_;
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +0900121 int event_watch_notification_;
caseq@google.com4cba9892013-04-29 18:08:28 +0900122 int notifications_received_;
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900123
124 private:
125 // We want our singleton torn down after each test.
126 ShadowingAtExitManager at_exit_manager_;
jbates@chromium.orgb84db522011-10-04 02:51:25 +0900127 Lock lock_;
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900128};
129
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900130void TraceEventTestFixture::OnTraceDataCollected(
husky@chromium.org3b366292012-02-24 13:17:06 +0900131 const scoped_refptr<base::RefCountedString>& events_str) {
jbates@chromium.orgb84db522011-10-04 02:51:25 +0900132 AutoLock lock(lock_);
jbates@chromium.org6a092d72011-10-25 01:34:08 +0900133 json_output_.json_output.clear();
134 trace_buffer_.Start();
husky@chromium.org3b366292012-02-24 13:17:06 +0900135 trace_buffer_.AddFragment(events_str->data());
jbates@chromium.org6a092d72011-10-25 01:34:08 +0900136 trace_buffer_.Finish();
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900137
138 scoped_ptr<Value> root;
rsesek@chromium.orgc2d2b202012-05-17 00:23:30 +0900139 root.reset(base::JSONReader::Read(json_output_.json_output,
140 JSON_PARSE_RFC | JSON_DETACHABLE_CHILDREN));
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900141
jbates@chromium.org59c27602012-01-13 12:12:44 +0900142 if (!root.get()) {
143 LOG(ERROR) << json_output_.json_output;
144 }
145
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900146 ListValue* root_list = NULL;
147 ASSERT_TRUE(root.get());
148 ASSERT_TRUE(root->GetAsList(&root_list));
149
150 // Move items into our aggregate collection
151 while (root_list->GetSize()) {
bauerb@chromium.orgae43e0a2013-08-06 22:33:04 +0900152 scoped_ptr<Value> item;
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900153 root_list->Remove(0, &item);
bauerb@chromium.orgae43e0a2013-08-06 22:33:04 +0900154 trace_parsed_.Append(item.release());
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900155 }
156}
157
jbates@chromium.org11d4c362011-09-13 07:03:41 +0900158static bool CompareJsonValues(const std::string& lhs,
159 const std::string& rhs,
160 CompareOp op) {
161 switch (op) {
162 case IS_EQUAL:
163 return lhs == rhs;
164 case IS_NOT_EQUAL:
165 return lhs != rhs;
166 default:
167 CHECK(0);
168 }
169 return false;
170}
171
jbates@chromium.orgb3cab862011-05-14 08:30:35 +0900172static bool IsKeyValueInDict(const JsonKeyValue* key_value,
173 DictionaryValue* dict) {
174 Value* value = NULL;
175 std::string value_str;
176 if (dict->Get(key_value->key, &value) &&
177 value->GetAsString(&value_str) &&
jbates@chromium.org11d4c362011-09-13 07:03:41 +0900178 CompareJsonValues(value_str, key_value->value, key_value->op))
jbates@chromium.orgb3cab862011-05-14 08:30:35 +0900179 return true;
180
181 // Recurse to test arguments
182 DictionaryValue* args_dict = NULL;
183 dict->GetDictionary("args", &args_dict);
184 if (args_dict)
185 return IsKeyValueInDict(key_value, args_dict);
186
187 return false;
188}
189
190static bool IsAllKeyValueInDict(const JsonKeyValue* key_values,
191 DictionaryValue* dict) {
192 // Scan all key_values, they must all be present and equal.
193 while (key_values && key_values->key) {
194 if (!IsKeyValueInDict(key_values, dict))
195 return false;
196 ++key_values;
197 }
198 return true;
199}
200
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +0900201DictionaryValue* TraceEventTestFixture::FindMatchingTraceEntry(
jbates@chromium.orgb3cab862011-05-14 08:30:35 +0900202 const JsonKeyValue* key_values) {
203 // Scan all items
204 size_t trace_parsed_count = trace_parsed_.GetSize();
205 for (size_t i = 0; i < trace_parsed_count; i++) {
206 Value* value = NULL;
207 trace_parsed_.Get(i, &value);
208 if (!value || value->GetType() != Value::TYPE_DICTIONARY)
209 continue;
210 DictionaryValue* dict = static_cast<DictionaryValue*>(value);
211
212 if (IsAllKeyValueInDict(key_values, dict))
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +0900213 return dict;
jbates@chromium.orgb3cab862011-05-14 08:30:35 +0900214 }
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +0900215 return NULL;
jbates@chromium.orgb3cab862011-05-14 08:30:35 +0900216}
217
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +0900218DictionaryValue* TraceEventTestFixture::FindNamePhase(const char* name,
219 const char* phase) {
jbates@chromium.orgb3cab862011-05-14 08:30:35 +0900220 JsonKeyValue key_values[] = {
jbates@chromium.org11d4c362011-09-13 07:03:41 +0900221 {"name", name, IS_EQUAL},
222 {"ph", phase, IS_EQUAL},
223 {0, 0, IS_EQUAL}
224 };
225 return FindMatchingTraceEntry(key_values);
226}
227
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +0900228DictionaryValue* TraceEventTestFixture::FindNamePhaseKeyValue(
229 const char* name,
230 const char* phase,
231 const char* key,
232 const char* value) {
233 JsonKeyValue key_values[] = {
234 {"name", name, IS_EQUAL},
235 {"ph", phase, IS_EQUAL},
236 {key, value, IS_EQUAL},
237 {0, 0, IS_EQUAL}
238 };
239 return FindMatchingTraceEntry(key_values);
240}
241
jbates@chromium.org11d4c362011-09-13 07:03:41 +0900242bool TraceEventTestFixture::FindMatchingValue(const char* key,
243 const char* value) {
244 JsonKeyValue key_values[] = {
245 {key, value, IS_EQUAL},
246 {0, 0, IS_EQUAL}
247 };
248 return FindMatchingTraceEntry(key_values);
249}
250
251bool TraceEventTestFixture::FindNonMatchingValue(const char* key,
252 const char* value) {
253 JsonKeyValue key_values[] = {
254 {key, value, IS_NOT_EQUAL},
255 {0, 0, IS_EQUAL}
jbates@chromium.orgb3cab862011-05-14 08:30:35 +0900256 };
257 return FindMatchingTraceEntry(key_values);
258}
259
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900260bool IsStringInDict(const char* string_to_match, const DictionaryValue* dict) {
pneubeck@chromium.orga2fbefc2013-01-18 23:43:27 +0900261 for (DictionaryValue::Iterator it(*dict); !it.IsAtEnd(); it.Advance()) {
262 if (it.key().find(string_to_match) != std::string::npos)
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900263 return true;
264
265 std::string value_str;
pneubeck@chromium.orga2fbefc2013-01-18 23:43:27 +0900266 it.value().GetAsString(&value_str);
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900267 if (value_str.find(string_to_match) != std::string::npos)
268 return true;
269 }
270
271 // Recurse to test arguments
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900272 const DictionaryValue* args_dict = NULL;
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900273 dict->GetDictionary("args", &args_dict);
274 if (args_dict)
275 return IsStringInDict(string_to_match, args_dict);
276
277 return false;
278}
279
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900280const DictionaryValue* FindTraceEntry(
281 const ListValue& trace_parsed,
282 const char* string_to_match,
283 const DictionaryValue* match_after_this_item = NULL) {
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900284 // Scan all items
285 size_t trace_parsed_count = trace_parsed.GetSize();
286 for (size_t i = 0; i < trace_parsed_count; i++) {
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900287 const Value* value = NULL;
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900288 trace_parsed.Get(i, &value);
289 if (match_after_this_item) {
290 if (value == match_after_this_item)
291 match_after_this_item = NULL;
292 continue;
293 }
294 if (!value || value->GetType() != Value::TYPE_DICTIONARY)
295 continue;
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900296 const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900297
298 if (IsStringInDict(string_to_match, dict))
299 return dict;
300 }
301 return NULL;
302}
303
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900304std::vector<const DictionaryValue*> FindTraceEntries(
nduca@chromium.org6d048772011-08-10 00:16:25 +0900305 const ListValue& trace_parsed,
306 const char* string_to_match) {
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900307 std::vector<const DictionaryValue*> hits;
nduca@chromium.org6d048772011-08-10 00:16:25 +0900308 size_t trace_parsed_count = trace_parsed.GetSize();
309 for (size_t i = 0; i < trace_parsed_count; i++) {
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900310 const Value* value = NULL;
nduca@chromium.org6d048772011-08-10 00:16:25 +0900311 trace_parsed.Get(i, &value);
312 if (!value || value->GetType() != Value::TYPE_DICTIONARY)
313 continue;
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900314 const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
nduca@chromium.org6d048772011-08-10 00:16:25 +0900315
316 if (IsStringInDict(string_to_match, dict))
317 hits.push_back(dict);
318 }
319 return hits;
320}
321
322void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900323 {
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +0900324 TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 0x1122, "extrastring1");
325 TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 0x3344, "extrastring2");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900326 TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW call",
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +0900327 0x5566, "extrastring3");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900328
329 TRACE_EVENT0("all", "TRACE_EVENT0 call");
330 TRACE_EVENT1("all", "TRACE_EVENT1 call", "name1", "value1");
331 TRACE_EVENT2("all", "TRACE_EVENT2 call",
jbates@chromium.org788d5a12011-09-07 09:43:11 +0900332 "name1", "\"value1\"",
333 "name2", "value\\2");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900334
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +0900335 TRACE_EVENT_INSTANT0("all", "TRACE_EVENT_INSTANT0 call",
336 TRACE_EVENT_SCOPE_GLOBAL);
337 TRACE_EVENT_INSTANT1("all", "TRACE_EVENT_INSTANT1 call",
338 TRACE_EVENT_SCOPE_PROCESS, "name1", "value1");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900339 TRACE_EVENT_INSTANT2("all", "TRACE_EVENT_INSTANT2 call",
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +0900340 TRACE_EVENT_SCOPE_THREAD,
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900341 "name1", "value1",
342 "name2", "value2");
343
344 TRACE_EVENT_BEGIN0("all", "TRACE_EVENT_BEGIN0 call");
345 TRACE_EVENT_BEGIN1("all", "TRACE_EVENT_BEGIN1 call", "name1", "value1");
346 TRACE_EVENT_BEGIN2("all", "TRACE_EVENT_BEGIN2 call",
347 "name1", "value1",
348 "name2", "value2");
349
350 TRACE_EVENT_END0("all", "TRACE_EVENT_END0 call");
351 TRACE_EVENT_END1("all", "TRACE_EVENT_END1 call", "name1", "value1");
352 TRACE_EVENT_END2("all", "TRACE_EVENT_END2 call",
353 "name1", "value1",
354 "name2", "value2");
nduca@chromium.org62210b02011-11-18 18:36:36 +0900355
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900356 TRACE_EVENT_ASYNC_BEGIN0("all", "TRACE_EVENT_ASYNC_BEGIN0 call", kAsyncId);
357 TRACE_EVENT_ASYNC_BEGIN1("all", "TRACE_EVENT_ASYNC_BEGIN1 call", kAsyncId,
jbates@chromium.org88295f92012-03-01 12:04:59 +0900358 "name1", "value1");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900359 TRACE_EVENT_ASYNC_BEGIN2("all", "TRACE_EVENT_ASYNC_BEGIN2 call", kAsyncId,
jbates@chromium.org88295f92012-03-01 12:04:59 +0900360 "name1", "value1",
361 "name2", "value2");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900362
jbates@chromium.orgbd9d20a2012-09-11 14:56:05 +0900363 TRACE_EVENT_ASYNC_STEP0("all", "TRACE_EVENT_ASYNC_STEP0 call",
simonjam@chromium.org87d003c2012-03-28 09:14:11 +0900364 5, "step1");
jbates@chromium.orgbd9d20a2012-09-11 14:56:05 +0900365 TRACE_EVENT_ASYNC_STEP1("all", "TRACE_EVENT_ASYNC_STEP1 call",
simonjam@chromium.org87d003c2012-03-28 09:14:11 +0900366 5, "step2", "name1", "value1");
jbates@chromium.org88295f92012-03-01 12:04:59 +0900367
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900368 TRACE_EVENT_ASYNC_END0("all", "TRACE_EVENT_ASYNC_END0 call", kAsyncId);
369 TRACE_EVENT_ASYNC_END1("all", "TRACE_EVENT_ASYNC_END1 call", kAsyncId,
jbates@chromium.org88295f92012-03-01 12:04:59 +0900370 "name1", "value1");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900371 TRACE_EVENT_ASYNC_END2("all", "TRACE_EVENT_ASYNC_END2 call", kAsyncId,
jbates@chromium.org88295f92012-03-01 12:04:59 +0900372 "name1", "value1",
373 "name2", "value2");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900374
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900375 TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW0 call", kAsyncId, NULL);
376 TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW1 call", kAsyncId, "value");
377 TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW0 call", kAsyncId, NULL);
378 TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW1 call", kAsyncId, "value");
379 TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW0 call", kAsyncId, NULL);
380 TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW1 call", kAsyncId, "value");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900381
nduca@chromium.org62210b02011-11-18 18:36:36 +0900382 TRACE_COUNTER1("all", "TRACE_COUNTER1 call", 31415);
383 TRACE_COUNTER2("all", "TRACE_COUNTER2 call",
384 "a", 30000,
385 "b", 1415);
piman@chromium.org902b2952011-12-16 10:19:06 +0900386
387 TRACE_COUNTER_ID1("all", "TRACE_COUNTER_ID1 call", 0x319009, 31415);
388 TRACE_COUNTER_ID2("all", "TRACE_COUNTER_ID2 call", 0x319009,
389 "a", 30000, "b", 1415);
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900390
391 TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
392 "TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
393 kAsyncId, kThreadId, 12345);
394 TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0("all",
395 "TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call",
396 kAsyncId, kThreadId, 23456);
397
398 TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
399 "TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900400 kAsyncId2, kThreadId, 34567);
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900401 TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0("all",
402 "TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call",
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900403 kAsyncId2, kThreadId, 45678);
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900404
caseq@google.coma88a9c52013-02-26 23:33:33 +0900405 TRACE_EVENT_OBJECT_CREATED_WITH_ID("all", "tracked object 1", 0x42);
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900406 TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(
407 "all", "tracked object 1", 0x42, "hello");
caseq@google.coma88a9c52013-02-26 23:33:33 +0900408 TRACE_EVENT_OBJECT_DELETED_WITH_ID("all", "tracked object 1", 0x42);
409
410 TraceScopedTrackableObject<int> trackable("all", "tracked object 2",
411 0x2128506);
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900412 trackable.snapshot("world");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900413 } // Scope close causes TRACE_EVENT0 etc to send their END events.
414
415 if (task_complete_event)
416 task_complete_event->Signal();
417}
418
jbates@chromium.org6a092d72011-10-25 01:34:08 +0900419void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900420 const DictionaryValue* item = NULL;
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900421
422#define EXPECT_FIND_(string) \
jbates@chromium.orgb84db522011-10-04 02:51:25 +0900423 EXPECT_TRUE((item = FindTraceEntry(trace_parsed, string)));
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900424#define EXPECT_NOT_FIND_(string) \
jbates@chromium.orgb84db522011-10-04 02:51:25 +0900425 EXPECT_FALSE((item = FindTraceEntry(trace_parsed, string)));
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900426#define EXPECT_SUB_FIND_(string) \
jbates@chromium.orgb84db522011-10-04 02:51:25 +0900427 if (item) EXPECT_TRUE((IsStringInDict(string, item)));
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900428
429 EXPECT_FIND_("ETW Trace Event");
430 EXPECT_FIND_("all");
431 EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW call");
432 {
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +0900433 std::string str_val;
434 EXPECT_TRUE(item && item->GetString("args.id", &str_val));
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900435 EXPECT_STREQ("0x1122", str_val.c_str());
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900436 }
437 EXPECT_SUB_FIND_("extrastring1");
438 EXPECT_FIND_("TRACE_EVENT_END_ETW call");
439 EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW call");
440 EXPECT_FIND_("TRACE_EVENT0 call");
441 {
442 std::string ph_begin;
443 std::string ph_end;
444 EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call")));
445 EXPECT_TRUE((item && item->GetString("ph", &ph_begin)));
446 EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call",
447 item)));
448 EXPECT_TRUE((item && item->GetString("ph", &ph_end)));
449 EXPECT_EQ("B", ph_begin);
450 EXPECT_EQ("E", ph_end);
451 }
452 EXPECT_FIND_("TRACE_EVENT1 call");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900453 EXPECT_SUB_FIND_("name1");
454 EXPECT_SUB_FIND_("value1");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900455 EXPECT_FIND_("TRACE_EVENT2 call");
456 EXPECT_SUB_FIND_("name1");
jbates@chromium.org788d5a12011-09-07 09:43:11 +0900457 EXPECT_SUB_FIND_("\"value1\"");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900458 EXPECT_SUB_FIND_("name2");
jbates@chromium.org788d5a12011-09-07 09:43:11 +0900459 EXPECT_SUB_FIND_("value\\2");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900460
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900461 EXPECT_FIND_("TRACE_EVENT_INSTANT0 call");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +0900462 {
463 std::string scope;
464 EXPECT_TRUE((item && item->GetString("s", &scope)));
465 EXPECT_EQ("g", scope);
466 }
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900467 EXPECT_FIND_("TRACE_EVENT_INSTANT1 call");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +0900468 {
469 std::string scope;
470 EXPECT_TRUE((item && item->GetString("s", &scope)));
471 EXPECT_EQ("p", scope);
472 }
jbates@chromium.org59c27602012-01-13 12:12:44 +0900473 EXPECT_SUB_FIND_("name1");
474 EXPECT_SUB_FIND_("value1");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900475 EXPECT_FIND_("TRACE_EVENT_INSTANT2 call");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +0900476 {
477 std::string scope;
478 EXPECT_TRUE((item && item->GetString("s", &scope)));
479 EXPECT_EQ("t", scope);
480 }
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900481 EXPECT_SUB_FIND_("name1");
482 EXPECT_SUB_FIND_("value1");
483 EXPECT_SUB_FIND_("name2");
484 EXPECT_SUB_FIND_("value2");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900485
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900486 EXPECT_FIND_("TRACE_EVENT_BEGIN0 call");
487 EXPECT_FIND_("TRACE_EVENT_BEGIN1 call");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900488 EXPECT_SUB_FIND_("name1");
489 EXPECT_SUB_FIND_("value1");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900490 EXPECT_FIND_("TRACE_EVENT_BEGIN2 call");
491 EXPECT_SUB_FIND_("name1");
492 EXPECT_SUB_FIND_("value1");
493 EXPECT_SUB_FIND_("name2");
494 EXPECT_SUB_FIND_("value2");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900495
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900496 EXPECT_FIND_("TRACE_EVENT_END0 call");
497 EXPECT_FIND_("TRACE_EVENT_END1 call");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900498 EXPECT_SUB_FIND_("name1");
499 EXPECT_SUB_FIND_("value1");
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900500 EXPECT_FIND_("TRACE_EVENT_END2 call");
501 EXPECT_SUB_FIND_("name1");
502 EXPECT_SUB_FIND_("value1");
503 EXPECT_SUB_FIND_("name2");
504 EXPECT_SUB_FIND_("value2");
nduca@chromium.org62210b02011-11-18 18:36:36 +0900505
jbates@chromium.org88295f92012-03-01 12:04:59 +0900506 EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN0 call");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900507 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900508 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org88295f92012-03-01 12:04:59 +0900509 EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN1 call");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900510 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900511 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org59c27602012-01-13 12:12:44 +0900512 EXPECT_SUB_FIND_("name1");
513 EXPECT_SUB_FIND_("value1");
jbates@chromium.org88295f92012-03-01 12:04:59 +0900514 EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN2 call");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900515 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900516 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org59c27602012-01-13 12:12:44 +0900517 EXPECT_SUB_FIND_("name1");
518 EXPECT_SUB_FIND_("value1");
519 EXPECT_SUB_FIND_("name2");
520 EXPECT_SUB_FIND_("value2");
521
jbates@chromium.orgbd9d20a2012-09-11 14:56:05 +0900522 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP0 call");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900523 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900524 EXPECT_SUB_FIND_(kAsyncIdStr);
simonjam@chromium.org87d003c2012-03-28 09:14:11 +0900525 EXPECT_SUB_FIND_("step1");
jbates@chromium.orgbd9d20a2012-09-11 14:56:05 +0900526 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP1 call");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900527 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900528 EXPECT_SUB_FIND_(kAsyncIdStr);
simonjam@chromium.org87d003c2012-03-28 09:14:11 +0900529 EXPECT_SUB_FIND_("step2");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900530 EXPECT_SUB_FIND_("name1");
531 EXPECT_SUB_FIND_("value1");
jbates@chromium.org88295f92012-03-01 12:04:59 +0900532
533 EXPECT_FIND_("TRACE_EVENT_ASYNC_END0 call");
534 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900535 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org88295f92012-03-01 12:04:59 +0900536 EXPECT_FIND_("TRACE_EVENT_ASYNC_END1 call");
537 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900538 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org88295f92012-03-01 12:04:59 +0900539 EXPECT_SUB_FIND_("name1");
540 EXPECT_SUB_FIND_("value1");
541 EXPECT_FIND_("TRACE_EVENT_ASYNC_END2 call");
jbates@chromium.org59c27602012-01-13 12:12:44 +0900542 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900543 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org59c27602012-01-13 12:12:44 +0900544 EXPECT_SUB_FIND_("name1");
545 EXPECT_SUB_FIND_("value1");
546 EXPECT_SUB_FIND_("name2");
547 EXPECT_SUB_FIND_("value2");
548
549 EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW0 call");
550 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900551 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org59c27602012-01-13 12:12:44 +0900552 EXPECT_SUB_FIND_("extra");
553 EXPECT_SUB_FIND_("NULL");
554 EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW1 call");
555 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900556 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org59c27602012-01-13 12:12:44 +0900557 EXPECT_SUB_FIND_("extra");
558 EXPECT_SUB_FIND_("value");
559 EXPECT_FIND_("TRACE_EVENT_END_ETW0 call");
560 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900561 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org59c27602012-01-13 12:12:44 +0900562 EXPECT_SUB_FIND_("extra");
563 EXPECT_SUB_FIND_("NULL");
564 EXPECT_FIND_("TRACE_EVENT_END_ETW1 call");
565 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900566 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org59c27602012-01-13 12:12:44 +0900567 EXPECT_SUB_FIND_("extra");
568 EXPECT_SUB_FIND_("value");
569 EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW0 call");
570 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900571 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org59c27602012-01-13 12:12:44 +0900572 EXPECT_SUB_FIND_("extra");
573 EXPECT_SUB_FIND_("NULL");
574 EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW1 call");
575 EXPECT_SUB_FIND_("id");
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900576 EXPECT_SUB_FIND_(kAsyncIdStr);
jbates@chromium.org59c27602012-01-13 12:12:44 +0900577 EXPECT_SUB_FIND_("extra");
578 EXPECT_SUB_FIND_("value");
579
nduca@chromium.org62210b02011-11-18 18:36:36 +0900580 EXPECT_FIND_("TRACE_COUNTER1 call");
581 {
582 std::string ph;
583 EXPECT_TRUE((item && item->GetString("ph", &ph)));
584 EXPECT_EQ("C", ph);
585
586 int value;
587 EXPECT_TRUE((item && item->GetInteger("args.value", &value)));
588 EXPECT_EQ(31415, value);
589 }
590
591 EXPECT_FIND_("TRACE_COUNTER2 call");
592 {
593 std::string ph;
594 EXPECT_TRUE((item && item->GetString("ph", &ph)));
595 EXPECT_EQ("C", ph);
596
597 int value;
598 EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
599 EXPECT_EQ(30000, value);
600
601 EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
602 EXPECT_EQ(1415, value);
603 }
604
piman@chromium.org902b2952011-12-16 10:19:06 +0900605 EXPECT_FIND_("TRACE_COUNTER_ID1 call");
606 {
607 std::string id;
608 EXPECT_TRUE((item && item->GetString("id", &id)));
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900609 EXPECT_EQ("0x319009", id);
piman@chromium.org902b2952011-12-16 10:19:06 +0900610
611 std::string ph;
612 EXPECT_TRUE((item && item->GetString("ph", &ph)));
613 EXPECT_EQ("C", ph);
614
615 int value;
616 EXPECT_TRUE((item && item->GetInteger("args.value", &value)));
617 EXPECT_EQ(31415, value);
618 }
619
620 EXPECT_FIND_("TRACE_COUNTER_ID2 call");
621 {
622 std::string id;
623 EXPECT_TRUE((item && item->GetString("id", &id)));
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900624 EXPECT_EQ("0x319009", id);
piman@chromium.org902b2952011-12-16 10:19:06 +0900625
626 std::string ph;
627 EXPECT_TRUE((item && item->GetString("ph", &ph)));
628 EXPECT_EQ("C", ph);
629
630 int value;
631 EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
632 EXPECT_EQ(30000, value);
633
634 EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
635 EXPECT_EQ(1415, value);
636 }
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900637
638 EXPECT_FIND_("TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
639 {
640 int val;
641 EXPECT_TRUE((item && item->GetInteger("ts", &val)));
642 EXPECT_EQ(12345, val);
643 EXPECT_TRUE((item && item->GetInteger("tid", &val)));
644 EXPECT_EQ(kThreadId, val);
645 std::string id;
646 EXPECT_TRUE((item && item->GetString("id", &id)));
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900647 EXPECT_EQ(kAsyncIdStr, id);
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900648 }
649
650 EXPECT_FIND_("TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call");
651 {
652 int val;
653 EXPECT_TRUE((item && item->GetInteger("ts", &val)));
654 EXPECT_EQ(23456, val);
655 EXPECT_TRUE((item && item->GetInteger("tid", &val)));
656 EXPECT_EQ(kThreadId, val);
657 std::string id;
658 EXPECT_TRUE((item && item->GetString("id", &id)));
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900659 EXPECT_EQ(kAsyncIdStr, id);
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900660 }
661
662 EXPECT_FIND_("TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
663 {
664 int val;
665 EXPECT_TRUE((item && item->GetInteger("ts", &val)));
666 EXPECT_EQ(34567, val);
667 EXPECT_TRUE((item && item->GetInteger("tid", &val)));
668 EXPECT_EQ(kThreadId, val);
669 std::string id;
670 EXPECT_TRUE((item && item->GetString("id", &id)));
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900671 EXPECT_EQ(kAsyncId2Str, id);
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900672 }
673
674 EXPECT_FIND_("TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call");
675 {
676 int val;
677 EXPECT_TRUE((item && item->GetInteger("ts", &val)));
678 EXPECT_EQ(45678, val);
679 EXPECT_TRUE((item && item->GetInteger("tid", &val)));
680 EXPECT_EQ(kThreadId, val);
681 std::string id;
682 EXPECT_TRUE((item && item->GetString("id", &id)));
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900683 EXPECT_EQ(kAsyncId2Str, id);
dsinclair@chromium.org9aed8362013-02-16 03:58:25 +0900684 }
caseq@google.coma88a9c52013-02-26 23:33:33 +0900685
686 EXPECT_FIND_("tracked object 1");
687 {
688 std::string phase;
689 std::string id;
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900690 std::string snapshot;
caseq@google.coma88a9c52013-02-26 23:33:33 +0900691
692 EXPECT_TRUE((item && item->GetString("ph", &phase)));
693 EXPECT_EQ("N", phase);
694 EXPECT_TRUE((item && item->GetString("id", &id)));
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900695 EXPECT_EQ("0x42", id);
696
697 item = FindTraceEntry(trace_parsed, "tracked object 1", item);
698 EXPECT_TRUE(item);
699 EXPECT_TRUE(item && item->GetString("ph", &phase));
700 EXPECT_EQ("O", phase);
701 EXPECT_TRUE(item && item->GetString("id", &id));
702 EXPECT_EQ("0x42", id);
703 EXPECT_TRUE(item && item->GetString("args.snapshot", &snapshot));
704 EXPECT_EQ("hello", snapshot);
705
706 item = FindTraceEntry(trace_parsed, "tracked object 1", item);
707 EXPECT_TRUE(item);
708 EXPECT_TRUE(item && item->GetString("ph", &phase));
caseq@google.coma88a9c52013-02-26 23:33:33 +0900709 EXPECT_EQ("D", phase);
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900710 EXPECT_TRUE(item && item->GetString("id", &id));
711 EXPECT_EQ("0x42", id);
caseq@google.coma88a9c52013-02-26 23:33:33 +0900712 }
713
714 EXPECT_FIND_("tracked object 2");
715 {
716 std::string phase;
717 std::string id;
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900718 std::string snapshot;
caseq@google.coma88a9c52013-02-26 23:33:33 +0900719
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900720 EXPECT_TRUE(item && item->GetString("ph", &phase));
caseq@google.coma88a9c52013-02-26 23:33:33 +0900721 EXPECT_EQ("N", phase);
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900722 EXPECT_TRUE(item && item->GetString("id", &id));
723 EXPECT_EQ("0x2128506", id);
724
725 item = FindTraceEntry(trace_parsed, "tracked object 2", item);
726 EXPECT_TRUE(item);
727 EXPECT_TRUE(item && item->GetString("ph", &phase));
728 EXPECT_EQ("O", phase);
729 EXPECT_TRUE(item && item->GetString("id", &id));
730 EXPECT_EQ("0x2128506", id);
731 EXPECT_TRUE(item && item->GetString("args.snapshot", &snapshot));
732 EXPECT_EQ("world", snapshot);
733
734 item = FindTraceEntry(trace_parsed, "tracked object 2", item);
735 EXPECT_TRUE(item);
736 EXPECT_TRUE(item && item->GetString("ph", &phase));
caseq@google.coma88a9c52013-02-26 23:33:33 +0900737 EXPECT_EQ("D", phase);
nduca@chromium.org3e5cb752013-05-04 23:28:07 +0900738 EXPECT_TRUE(item && item->GetString("id", &id));
739 EXPECT_EQ("0x2128506", id);
caseq@google.coma88a9c52013-02-26 23:33:33 +0900740 }
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900741}
742
nduca@chromium.org6d048772011-08-10 00:16:25 +0900743void TraceManyInstantEvents(int thread_id, int num_events,
jbates@chromium.org6a092d72011-10-25 01:34:08 +0900744 WaitableEvent* task_complete_event) {
nduca@chromium.org6d048772011-08-10 00:16:25 +0900745 for (int i = 0; i < num_events; i++) {
746 TRACE_EVENT_INSTANT2("all", "multi thread event",
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +0900747 TRACE_EVENT_SCOPE_THREAD,
nduca@chromium.org6d048772011-08-10 00:16:25 +0900748 "thread", thread_id,
749 "event", i);
750 }
751
752 if (task_complete_event)
753 task_complete_event->Signal();
754}
755
756void ValidateInstantEventPresentOnEveryThread(const ListValue& trace_parsed,
jbates@chromium.org6a092d72011-10-25 01:34:08 +0900757 int num_threads,
758 int num_events) {
nduca@chromium.org6d048772011-08-10 00:16:25 +0900759 std::map<int, std::map<int, bool> > results;
760
761 size_t trace_parsed_count = trace_parsed.GetSize();
762 for (size_t i = 0; i < trace_parsed_count; i++) {
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900763 const Value* value = NULL;
nduca@chromium.org6d048772011-08-10 00:16:25 +0900764 trace_parsed.Get(i, &value);
765 if (!value || value->GetType() != Value::TYPE_DICTIONARY)
766 continue;
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +0900767 const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
nduca@chromium.org6d048772011-08-10 00:16:25 +0900768 std::string name;
769 dict->GetString("name", &name);
770 if (name != "multi thread event")
771 continue;
772
773 int thread = 0;
774 int event = 0;
775 EXPECT_TRUE(dict->GetInteger("args.thread", &thread));
776 EXPECT_TRUE(dict->GetInteger("args.event", &event));
777 results[thread][event] = true;
778 }
779
780 EXPECT_FALSE(results[-1][-1]);
781 for (int thread = 0; thread < num_threads; thread++) {
782 for (int event = 0; event < num_events; event++) {
783 EXPECT_TRUE(results[thread][event]);
784 }
785 }
786}
787
788void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) {
789 TRACE_EVENT0("category name1", name_str);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +0900790 TRACE_EVENT_INSTANT0("category name2", name_str, TRACE_EVENT_SCOPE_THREAD);
nduca@chromium.org6d048772011-08-10 00:16:25 +0900791 TRACE_EVENT_BEGIN0("category name3", name_str);
792 TRACE_EVENT_END0("category name4", name_str);
793}
794
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900795} // namespace
796
jbates@chromium.org5e2f67d2012-08-16 13:32:49 +0900797void HighResSleepForTraceTest(base::TimeDelta elapsed) {
798 base::TimeTicks end_time = base::TimeTicks::HighResNow() + elapsed;
799 do {
800 base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(1));
801 } while (base::TimeTicks::HighResNow() < end_time);
802}
803
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900804// Simple Test for emitting data and validating it was received.
805TEST_F(TraceEventTestFixture, DataCaptured) {
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900806 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
807 TraceLog::RECORD_UNTIL_FULL);
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900808
nduca@chromium.org6d048772011-08-10 00:16:25 +0900809 TraceWithAllMacroVariants(NULL);
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900810
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +0900811 EndTraceAndFlush();
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900812
jbates@chromium.org6a092d72011-10-25 01:34:08 +0900813 ValidateAllTraceMacrosCreatedData(trace_parsed_);
scheib@chromium.org603f46e2011-05-10 11:23:58 +0900814}
815
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900816class MockEnabledStateChangedObserver :
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900817 public base::debug::TraceLog::EnabledStateObserver {
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900818 public:
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900819 MOCK_METHOD0(OnTraceLogEnabled, void());
820 MOCK_METHOD0(OnTraceLogDisabled, void());
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900821};
822
823TEST_F(TraceEventTestFixture, EnabledObserverFiresOnEnable) {
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900824 MockEnabledStateChangedObserver observer;
825 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
826
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900827 EXPECT_CALL(observer, OnTraceLogEnabled())
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900828 .Times(1);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900829 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
830 TraceLog::RECORD_UNTIL_FULL);
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900831 testing::Mock::VerifyAndClear(&observer);
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900832 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900833
834 // Cleanup.
835 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900836 TraceLog::GetInstance()->SetDisabled();
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900837}
838
839TEST_F(TraceEventTestFixture, EnabledObserverDoesntFireOnSecondEnable) {
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900840 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
841 TraceLog::RECORD_UNTIL_FULL);
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900842
843 testing::StrictMock<MockEnabledStateChangedObserver> observer;
844 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
845
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900846 EXPECT_CALL(observer, OnTraceLogEnabled())
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900847 .Times(0);
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900848 EXPECT_CALL(observer, OnTraceLogDisabled())
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900849 .Times(0);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900850 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
851 TraceLog::RECORD_UNTIL_FULL);
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900852 testing::Mock::VerifyAndClear(&observer);
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900853 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900854
855 // Cleanup.
856 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900857 TraceLog::GetInstance()->SetDisabled();
858 TraceLog::GetInstance()->SetDisabled();
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900859}
860
caseq@google.comedcf6262013-01-16 20:41:57 +0900861TEST_F(TraceEventTestFixture, EnabledObserverDoesntFireOnNestedDisable) {
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900862 CategoryFilter cf_inc_all("*");
863 TraceLog::GetInstance()->SetEnabled(cf_inc_all, TraceLog::RECORD_UNTIL_FULL);
864 TraceLog::GetInstance()->SetEnabled(cf_inc_all, TraceLog::RECORD_UNTIL_FULL);
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900865
866 testing::StrictMock<MockEnabledStateChangedObserver> observer;
867 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
868
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900869 EXPECT_CALL(observer, OnTraceLogEnabled())
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900870 .Times(0);
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900871 EXPECT_CALL(observer, OnTraceLogDisabled())
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900872 .Times(0);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900873 TraceLog::GetInstance()->SetDisabled();
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900874 testing::Mock::VerifyAndClear(&observer);
875
876 // Cleanup.
877 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900878 TraceLog::GetInstance()->SetDisabled();
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900879}
880
881TEST_F(TraceEventTestFixture, EnabledObserverFiresOnDisable) {
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900882 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
883 TraceLog::RECORD_UNTIL_FULL);
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900884
885 MockEnabledStateChangedObserver observer;
886 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
887
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900888 EXPECT_CALL(observer, OnTraceLogDisabled())
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900889 .Times(1);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900890 TraceLog::GetInstance()->SetDisabled();
nduca@chromium.org6a7360c2012-02-20 15:35:15 +0900891 testing::Mock::VerifyAndClear(&observer);
892
893 // Cleanup.
894 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
895}
896
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900897// Tests the IsEnabled() state of TraceLog changes before callbacks.
898class AfterStateChangeEnabledStateObserver
899 : public base::debug::TraceLog::EnabledStateObserver {
900 public:
901 AfterStateChangeEnabledStateObserver() {}
902 virtual ~AfterStateChangeEnabledStateObserver() {}
903
904 // base::debug::TraceLog::EnabledStateObserver overrides:
905 virtual void OnTraceLogEnabled() OVERRIDE {
906 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
907 }
908
909 virtual void OnTraceLogDisabled() OVERRIDE {
910 EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
911 }
912};
913
914TEST_F(TraceEventTestFixture, ObserversFireAfterStateChange) {
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900915 AfterStateChangeEnabledStateObserver observer;
916 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
917
918 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
919 TraceLog::RECORD_UNTIL_FULL);
920 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
921
922 TraceLog::GetInstance()->SetDisabled();
923 EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
924
925 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
926}
927
928// Tests that a state observer can remove itself during a callback.
929class SelfRemovingEnabledStateObserver
930 : public base::debug::TraceLog::EnabledStateObserver {
931 public:
932 SelfRemovingEnabledStateObserver() {}
933 virtual ~SelfRemovingEnabledStateObserver() {}
934
935 // base::debug::TraceLog::EnabledStateObserver overrides:
936 virtual void OnTraceLogEnabled() OVERRIDE {}
937
938 virtual void OnTraceLogDisabled() OVERRIDE {
939 TraceLog::GetInstance()->RemoveEnabledStateObserver(this);
940 }
941};
942
943TEST_F(TraceEventTestFixture, SelfRemovingObserver) {
jamescook@chromium.orgd25d76b2013-06-14 02:44:56 +0900944 ASSERT_EQ(0u, TraceLog::GetInstance()->GetObserverCountForTest());
945
946 SelfRemovingEnabledStateObserver observer;
947 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
948 EXPECT_EQ(1u, TraceLog::GetInstance()->GetObserverCountForTest());
949
950 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
951 TraceLog::RECORD_UNTIL_FULL);
952 TraceLog::GetInstance()->SetDisabled();
953 // The observer removed itself on disable.
954 EXPECT_EQ(0u, TraceLog::GetInstance()->GetObserverCountForTest());
955}
956
nduca@chromium.orgcb323952013-06-04 10:31:52 +0900957bool IsNewTrace() {
958 bool is_new_trace;
959 TRACE_EVENT_IS_NEW_TRACE(&is_new_trace);
960 return is_new_trace;
961}
962
963TEST_F(TraceEventTestFixture, NewTraceRecording) {
nduca@chromium.orgcb323952013-06-04 10:31:52 +0900964 ASSERT_FALSE(IsNewTrace());
965 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
966 TraceLog::RECORD_UNTIL_FULL);
967 // First call to IsNewTrace() should succeed. But, the second shouldn't.
968 ASSERT_TRUE(IsNewTrace());
969 ASSERT_FALSE(IsNewTrace());
970 EndTraceAndFlush();
971
972 // IsNewTrace() should definitely be false now.
973 ASSERT_FALSE(IsNewTrace());
974
975 // Start another trace. IsNewTrace() should become true again, briefly, as
976 // before.
977 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
978 TraceLog::RECORD_UNTIL_FULL);
979 ASSERT_TRUE(IsNewTrace());
980 ASSERT_FALSE(IsNewTrace());
981
982 // Cleanup.
983 EndTraceAndFlush();
984}
985
986
jbates@chromium.org11d4c362011-09-13 07:03:41 +0900987// Test that categories work.
988TEST_F(TraceEventTestFixture, Categories) {
jbates@chromium.org11d4c362011-09-13 07:03:41 +0900989 // Test that categories that are used can be retrieved whether trace was
990 // enabled or disabled when the trace event was encountered.
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +0900991 TRACE_EVENT_INSTANT0("c1", "name", TRACE_EVENT_SCOPE_THREAD);
992 TRACE_EVENT_INSTANT0("c2", "name", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +0900993 BeginTrace();
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +0900994 TRACE_EVENT_INSTANT0("c3", "name", TRACE_EVENT_SCOPE_THREAD);
995 TRACE_EVENT_INSTANT0("c4", "name", TRACE_EVENT_SCOPE_THREAD);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +0900996 // Category groups containing more than one category.
997 TRACE_EVENT_INSTANT0("c5,c6", "name", TRACE_EVENT_SCOPE_THREAD);
998 TRACE_EVENT_INSTANT0("c7,c8", "name", TRACE_EVENT_SCOPE_THREAD);
dsinclair@chromium.org3f838632013-05-08 05:17:27 +0900999 TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("c9"), "name",
1000 TRACE_EVENT_SCOPE_THREAD);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001001
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001002 EndTraceAndFlush();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001003 std::vector<std::string> cat_groups;
1004 TraceLog::GetInstance()->GetKnownCategoryGroups(&cat_groups);
1005 EXPECT_TRUE(std::find(cat_groups.begin(),
1006 cat_groups.end(), "c1") != cat_groups.end());
1007 EXPECT_TRUE(std::find(cat_groups.begin(),
1008 cat_groups.end(), "c2") != cat_groups.end());
1009 EXPECT_TRUE(std::find(cat_groups.begin(),
1010 cat_groups.end(), "c3") != cat_groups.end());
1011 EXPECT_TRUE(std::find(cat_groups.begin(),
1012 cat_groups.end(), "c4") != cat_groups.end());
1013 EXPECT_TRUE(std::find(cat_groups.begin(),
1014 cat_groups.end(), "c5,c6") != cat_groups.end());
1015 EXPECT_TRUE(std::find(cat_groups.begin(),
1016 cat_groups.end(), "c7,c8") != cat_groups.end());
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001017 EXPECT_TRUE(std::find(cat_groups.begin(),
1018 cat_groups.end(),
1019 "disabled-by-default-c9") != cat_groups.end());
dsinclair@chromium.orgc61f1842013-04-20 06:29:21 +09001020 // Make sure metadata isn't returned.
1021 EXPECT_TRUE(std::find(cat_groups.begin(),
1022 cat_groups.end(), "__metadata") == cat_groups.end());
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001023
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001024 const std::vector<std::string> empty_categories;
1025 std::vector<std::string> included_categories;
1026 std::vector<std::string> excluded_categories;
1027
1028 // Test that category filtering works.
1029
1030 // Include nonexistent category -> no events
1031 Clear();
1032 included_categories.clear();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001033 TraceLog::GetInstance()->SetEnabled(CategoryFilter("not_found823564786"),
dsinclair@chromium.orga7fb8d62013-02-23 11:09:53 +09001034 TraceLog::RECORD_UNTIL_FULL);
junov@chromium.org5daaa152013-08-17 04:02:53 +09001035 TRACE_EVENT_INSTANT0("cat1", "name", TRACE_EVENT_SCOPE_THREAD);
1036 TRACE_EVENT_INSTANT0("cat2", "name", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001037 EndTraceAndFlush();
junov@chromium.org5daaa152013-08-17 04:02:53 +09001038 EXPECT_TRUE(trace_parsed_.empty());
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001039
1040 // Include existent category -> only events of that category
1041 Clear();
1042 included_categories.clear();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001043 TraceLog::GetInstance()->SetEnabled(CategoryFilter("inc"),
dsinclair@chromium.orga7fb8d62013-02-23 11:09:53 +09001044 TraceLog::RECORD_UNTIL_FULL);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001045 TRACE_EVENT_INSTANT0("inc", "name", TRACE_EVENT_SCOPE_THREAD);
1046 TRACE_EVENT_INSTANT0("inc2", "name", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001047 EndTraceAndFlush();
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001048 EXPECT_TRUE(FindMatchingValue("cat", "inc"));
junov@chromium.org5daaa152013-08-17 04:02:53 +09001049 EXPECT_FALSE(FindNonMatchingValue("cat", "inc"));
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001050
1051 // Include existent wildcard -> all categories matching wildcard
1052 Clear();
1053 included_categories.clear();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001054 TraceLog::GetInstance()->SetEnabled(
1055 CategoryFilter("inc_wildcard_*,inc_wildchar_?_end"),
1056 TraceLog::RECORD_UNTIL_FULL);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001057 TRACE_EVENT_INSTANT0("inc_wildcard_abc", "included",
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001058 TRACE_EVENT_SCOPE_THREAD);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001059 TRACE_EVENT_INSTANT0("inc_wildcard_", "included", TRACE_EVENT_SCOPE_THREAD);
1060 TRACE_EVENT_INSTANT0("inc_wildchar_x_end", "included",
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001061 TRACE_EVENT_SCOPE_THREAD);
junov@chromium.org5daaa152013-08-17 04:02:53 +09001062 TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "not_inc",
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001063 TRACE_EVENT_SCOPE_THREAD);
junov@chromium.org5daaa152013-08-17 04:02:53 +09001064 TRACE_EVENT_INSTANT0("cat1", "not_inc", TRACE_EVENT_SCOPE_THREAD);
1065 TRACE_EVENT_INSTANT0("cat2", "not_inc", TRACE_EVENT_SCOPE_THREAD);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001066 TRACE_EVENT_INSTANT0("inc_wildcard_category,other_category", "included",
1067 TRACE_EVENT_SCOPE_THREAD);
1068 TRACE_EVENT_INSTANT0(
1069 "non_included_category,inc_wildcard_category", "included",
1070 TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001071 EndTraceAndFlush();
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001072 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_abc"));
1073 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_"));
1074 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_x_end"));
junov@chromium.org5daaa152013-08-17 04:02:53 +09001075 EXPECT_FALSE(FindMatchingValue("name", "not_inc"));
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001076 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_category,other_category"));
1077 EXPECT_TRUE(FindMatchingValue("cat",
1078 "non_included_category,inc_wildcard_category"));
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001079
1080 included_categories.clear();
1081
1082 // Exclude nonexistent category -> all events
1083 Clear();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001084 TraceLog::GetInstance()->SetEnabled(CategoryFilter("-not_found823564786"),
dsinclair@chromium.orga7fb8d62013-02-23 11:09:53 +09001085 TraceLog::RECORD_UNTIL_FULL);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001086 TRACE_EVENT_INSTANT0("cat1", "name", TRACE_EVENT_SCOPE_THREAD);
1087 TRACE_EVENT_INSTANT0("cat2", "name", TRACE_EVENT_SCOPE_THREAD);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001088 TRACE_EVENT_INSTANT0("category1,category2", "name", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001089 EndTraceAndFlush();
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001090 EXPECT_TRUE(FindMatchingValue("cat", "cat1"));
1091 EXPECT_TRUE(FindMatchingValue("cat", "cat2"));
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001092 EXPECT_TRUE(FindMatchingValue("cat", "category1,category2"));
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001093
1094 // Exclude existent category -> only events of other categories
1095 Clear();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001096 TraceLog::GetInstance()->SetEnabled(CategoryFilter("-inc"),
dsinclair@chromium.orga7fb8d62013-02-23 11:09:53 +09001097 TraceLog::RECORD_UNTIL_FULL);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001098 TRACE_EVENT_INSTANT0("inc", "name", TRACE_EVENT_SCOPE_THREAD);
1099 TRACE_EVENT_INSTANT0("inc2", "name", TRACE_EVENT_SCOPE_THREAD);
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001100 TRACE_EVENT_INSTANT0("inc2,inc", "name", TRACE_EVENT_SCOPE_THREAD);
1101 TRACE_EVENT_INSTANT0("inc,inc2", "name", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001102 EndTraceAndFlush();
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001103 EXPECT_TRUE(FindMatchingValue("cat", "inc2"));
1104 EXPECT_FALSE(FindMatchingValue("cat", "inc"));
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001105 EXPECT_FALSE(FindMatchingValue("cat", "inc2,inc"));
1106 EXPECT_FALSE(FindMatchingValue("cat", "inc,inc2"));
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001107
1108 // Exclude existent wildcard -> all categories not matching wildcard
1109 Clear();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001110 TraceLog::GetInstance()->SetEnabled(
1111 CategoryFilter("-inc_wildcard_*,-inc_wildchar_?_end"),
1112 TraceLog::RECORD_UNTIL_FULL);
junov@chromium.org5daaa152013-08-17 04:02:53 +09001113 TRACE_EVENT_INSTANT0("inc_wildcard_abc", "not_inc",
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001114 TRACE_EVENT_SCOPE_THREAD);
1115 TRACE_EVENT_INSTANT0("inc_wildcard_", "not_inc",
1116 TRACE_EVENT_SCOPE_THREAD);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001117 TRACE_EVENT_INSTANT0("inc_wildchar_x_end", "not_inc",
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001118 TRACE_EVENT_SCOPE_THREAD);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001119 TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "included",
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001120 TRACE_EVENT_SCOPE_THREAD);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001121 TRACE_EVENT_INSTANT0("cat1", "included", TRACE_EVENT_SCOPE_THREAD);
1122 TRACE_EVENT_INSTANT0("cat2", "included", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001123 EndTraceAndFlush();
jbates@chromium.org11d4c362011-09-13 07:03:41 +09001124 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_bla_end"));
1125 EXPECT_TRUE(FindMatchingValue("cat", "cat1"));
1126 EXPECT_TRUE(FindMatchingValue("cat", "cat2"));
1127 EXPECT_FALSE(FindMatchingValue("name", "not_inc"));
1128}
1129
jbates@chromium.orgb3cab862011-05-14 08:30:35 +09001130
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001131// Test EVENT_WATCH_NOTIFICATION
1132TEST_F(TraceEventTestFixture, EventWatchNotification) {
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001133 // Basic one occurrence.
1134 BeginTrace();
1135 TraceLog::GetInstance()->SetWatchEvent("cat", "event");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001136 TRACE_EVENT_INSTANT0("cat", "event", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001137 EndTraceAndFlush();
1138 EXPECT_EQ(event_watch_notification_, 1);
1139
1140 // Basic one occurrence before Set.
1141 BeginTrace();
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001142 TRACE_EVENT_INSTANT0("cat", "event", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001143 TraceLog::GetInstance()->SetWatchEvent("cat", "event");
1144 EndTraceAndFlush();
1145 EXPECT_EQ(event_watch_notification_, 1);
1146
1147 // Auto-reset after end trace.
1148 BeginTrace();
1149 TraceLog::GetInstance()->SetWatchEvent("cat", "event");
1150 EndTraceAndFlush();
1151 BeginTrace();
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001152 TRACE_EVENT_INSTANT0("cat", "event", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001153 EndTraceAndFlush();
1154 EXPECT_EQ(event_watch_notification_, 0);
1155
1156 // Multiple occurrence.
1157 BeginTrace();
1158 int num_occurrences = 5;
1159 TraceLog::GetInstance()->SetWatchEvent("cat", "event");
1160 for (int i = 0; i < num_occurrences; ++i)
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001161 TRACE_EVENT_INSTANT0("cat", "event", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001162 EndTraceAndFlush();
1163 EXPECT_EQ(event_watch_notification_, num_occurrences);
1164
1165 // Wrong category.
1166 BeginTrace();
1167 TraceLog::GetInstance()->SetWatchEvent("cat", "event");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001168 TRACE_EVENT_INSTANT0("wrong_cat", "event", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001169 EndTraceAndFlush();
1170 EXPECT_EQ(event_watch_notification_, 0);
1171
1172 // Wrong name.
1173 BeginTrace();
1174 TraceLog::GetInstance()->SetWatchEvent("cat", "event");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001175 TRACE_EVENT_INSTANT0("cat", "wrong_event", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001176 EndTraceAndFlush();
1177 EXPECT_EQ(event_watch_notification_, 0);
1178
1179 // Canceled.
1180 BeginTrace();
1181 TraceLog::GetInstance()->SetWatchEvent("cat", "event");
1182 TraceLog::GetInstance()->CancelWatchEvent();
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001183 TRACE_EVENT_INSTANT0("cat", "event", TRACE_EVENT_SCOPE_THREAD);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001184 EndTraceAndFlush();
1185 EXPECT_EQ(event_watch_notification_, 0);
1186}
1187
jbates@chromium.org88295f92012-03-01 12:04:59 +09001188// Test ASYNC_BEGIN/END events
1189TEST_F(TraceEventTestFixture, AsyncBeginEndEvents) {
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001190 BeginTrace();
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001191
1192 unsigned long long id = 0xfeedbeeffeedbeefull;
jbates@chromium.org88295f92012-03-01 12:04:59 +09001193 TRACE_EVENT_ASYNC_BEGIN0( "cat", "name1", id);
jbates@chromium.orgbd9d20a2012-09-11 14:56:05 +09001194 TRACE_EVENT_ASYNC_STEP0( "cat", "name1", id, "step1");
jbates@chromium.org88295f92012-03-01 12:04:59 +09001195 TRACE_EVENT_ASYNC_END0("cat", "name1", id);
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001196 TRACE_EVENT_BEGIN0( "cat", "name2");
jbates@chromium.org88295f92012-03-01 12:04:59 +09001197 TRACE_EVENT_ASYNC_BEGIN0( "cat", "name3", 0);
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001198
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001199 EndTraceAndFlush();
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001200
1201 EXPECT_TRUE(FindNamePhase("name1", "S"));
jbates@chromium.org88295f92012-03-01 12:04:59 +09001202 EXPECT_TRUE(FindNamePhase("name1", "T"));
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001203 EXPECT_TRUE(FindNamePhase("name1", "F"));
1204
1205 std::string id_str;
nduca@chromium.org3e5cb752013-05-04 23:28:07 +09001206 StringAppendF(&id_str, "0x%llx", id);
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001207
1208 EXPECT_TRUE(FindNamePhaseKeyValue("name1", "S", "id", id_str.c_str()));
jbates@chromium.org88295f92012-03-01 12:04:59 +09001209 EXPECT_TRUE(FindNamePhaseKeyValue("name1", "T", "id", id_str.c_str()));
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001210 EXPECT_TRUE(FindNamePhaseKeyValue("name1", "F", "id", id_str.c_str()));
nduca@chromium.org3e5cb752013-05-04 23:28:07 +09001211 EXPECT_TRUE(FindNamePhaseKeyValue("name3", "S", "id", "0x0"));
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001212
1213 // BEGIN events should not have id
1214 EXPECT_FALSE(FindNamePhaseKeyValue("name2", "B", "id", "0"));
1215}
1216
jbates@chromium.org88295f92012-03-01 12:04:59 +09001217// Test ASYNC_BEGIN/END events
1218TEST_F(TraceEventTestFixture, AsyncBeginEndPointerMangling) {
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001219 void* ptr = this;
1220
1221 TraceLog::GetInstance()->SetProcessID(100);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001222 BeginTrace();
jbates@chromium.org88295f92012-03-01 12:04:59 +09001223 TRACE_EVENT_ASYNC_BEGIN0( "cat", "name1", ptr);
1224 TRACE_EVENT_ASYNC_BEGIN0( "cat", "name2", ptr);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001225 EndTraceAndFlush();
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001226
1227 TraceLog::GetInstance()->SetProcessID(200);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001228 BeginTrace();
jbates@chromium.org88295f92012-03-01 12:04:59 +09001229 TRACE_EVENT_ASYNC_END0( "cat", "name1", ptr);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001230 EndTraceAndFlush();
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001231
jbates@chromium.org88295f92012-03-01 12:04:59 +09001232 DictionaryValue* async_begin = FindNamePhase("name1", "S");
1233 DictionaryValue* async_begin2 = FindNamePhase("name2", "S");
1234 DictionaryValue* async_end = FindNamePhase("name1", "F");
1235 EXPECT_TRUE(async_begin);
1236 EXPECT_TRUE(async_begin2);
1237 EXPECT_TRUE(async_end);
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001238
1239 Value* value = NULL;
jbates@chromium.org88295f92012-03-01 12:04:59 +09001240 std::string async_begin_id_str;
1241 std::string async_begin2_id_str;
1242 std::string async_end_id_str;
1243 ASSERT_TRUE(async_begin->Get("id", &value));
1244 ASSERT_TRUE(value->GetAsString(&async_begin_id_str));
1245 ASSERT_TRUE(async_begin2->Get("id", &value));
1246 ASSERT_TRUE(value->GetAsString(&async_begin2_id_str));
1247 ASSERT_TRUE(async_end->Get("id", &value));
1248 ASSERT_TRUE(value->GetAsString(&async_end_id_str));
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001249
jbates@chromium.org88295f92012-03-01 12:04:59 +09001250 EXPECT_STREQ(async_begin_id_str.c_str(), async_begin2_id_str.c_str());
1251 EXPECT_STRNE(async_begin_id_str.c_str(), async_end_id_str.c_str());
jbates@chromium.org8bb0ee62011-12-03 02:17:38 +09001252}
1253
jbates@chromium.org1f18e462011-09-07 02:56:24 +09001254// Test that static strings are not copied.
1255TEST_F(TraceEventTestFixture, StaticStringVsString) {
jbates@chromium.org1f18e462011-09-07 02:56:24 +09001256 TraceLog* tracer = TraceLog::GetInstance();
1257 // Make sure old events are flushed:
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001258 EndTraceAndFlush();
jbates@chromium.org1f18e462011-09-07 02:56:24 +09001259 EXPECT_EQ(0u, tracer->GetEventsSize());
1260
1261 {
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001262 BeginTrace();
jbates@chromium.org1f18e462011-09-07 02:56:24 +09001263 // Test that string arguments are copied.
1264 TRACE_EVENT2("cat", "name1",
1265 "arg1", std::string("argval"), "arg2", std::string("argval"));
1266 // Test that static TRACE_STR_COPY string arguments are copied.
1267 TRACE_EVENT2("cat", "name2",
1268 "arg1", TRACE_STR_COPY("argval"),
1269 "arg2", TRACE_STR_COPY("argval"));
1270 size_t num_events = tracer->GetEventsSize();
1271 EXPECT_GT(num_events, 1u);
1272 const TraceEvent& event1 = tracer->GetEventAt(num_events - 2);
1273 const TraceEvent& event2 = tracer->GetEventAt(num_events - 1);
1274 EXPECT_STREQ("name1", event1.name());
1275 EXPECT_STREQ("name2", event2.name());
1276 EXPECT_TRUE(event1.parameter_copy_storage() != NULL);
1277 EXPECT_TRUE(event2.parameter_copy_storage() != NULL);
1278 EXPECT_GT(event1.parameter_copy_storage()->size(), 0u);
1279 EXPECT_GT(event2.parameter_copy_storage()->size(), 0u);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001280 EndTraceAndFlush();
jbates@chromium.org1f18e462011-09-07 02:56:24 +09001281 }
1282
1283 {
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001284 BeginTrace();
jbates@chromium.org1f18e462011-09-07 02:56:24 +09001285 // Test that static literal string arguments are not copied.
1286 TRACE_EVENT2("cat", "name1",
1287 "arg1", "argval", "arg2", "argval");
1288 // Test that static TRACE_STR_COPY NULL string arguments are not copied.
1289 const char* str1 = NULL;
1290 const char* str2 = NULL;
1291 TRACE_EVENT2("cat", "name2",
1292 "arg1", TRACE_STR_COPY(str1),
1293 "arg2", TRACE_STR_COPY(str2));
1294 size_t num_events = tracer->GetEventsSize();
1295 EXPECT_GT(num_events, 1u);
1296 const TraceEvent& event1 = tracer->GetEventAt(num_events - 2);
1297 const TraceEvent& event2 = tracer->GetEventAt(num_events - 1);
1298 EXPECT_STREQ("name1", event1.name());
1299 EXPECT_STREQ("name2", event2.name());
1300 EXPECT_TRUE(event1.parameter_copy_storage() == NULL);
1301 EXPECT_TRUE(event2.parameter_copy_storage() == NULL);
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001302 EndTraceAndFlush();
jbates@chromium.org1f18e462011-09-07 02:56:24 +09001303 }
1304}
1305
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001306// Test that data sent from other threads is gathered
1307TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001308 BeginTrace();
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001309
1310 Thread thread("1");
1311 WaitableEvent task_complete_event(false, false);
1312 thread.Start();
1313
1314 thread.message_loop()->PostTask(
jbates@chromium.org0b837e42011-10-06 01:58:20 +09001315 FROM_HERE, base::Bind(&TraceWithAllMacroVariants, &task_complete_event));
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001316 task_complete_event.Wait();
jbates@chromium.orgb84db522011-10-04 02:51:25 +09001317 thread.Stop();
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001318
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001319 EndTraceAndFlush();
jbates@chromium.org6a092d72011-10-25 01:34:08 +09001320 ValidateAllTraceMacrosCreatedData(trace_parsed_);
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001321}
1322
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001323// Test that data sent from multiple threads is gathered
1324TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001325 BeginTrace();
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001326
1327 const int num_threads = 4;
1328 const int num_events = 4000;
1329 Thread* threads[num_threads];
1330 WaitableEvent* task_complete_events[num_threads];
1331 for (int i = 0; i < num_threads; i++) {
1332 threads[i] = new Thread(StringPrintf("Thread %d", i).c_str());
1333 task_complete_events[i] = new WaitableEvent(false, false);
1334 threads[i]->Start();
1335 threads[i]->message_loop()->PostTask(
jbates@chromium.org0b837e42011-10-06 01:58:20 +09001336 FROM_HERE, base::Bind(&TraceManyInstantEvents,
1337 i, num_events, task_complete_events[i]));
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001338 }
1339
1340 for (int i = 0; i < num_threads; i++) {
1341 task_complete_events[i]->Wait();
1342 }
1343
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001344 for (int i = 0; i < num_threads; i++) {
1345 threads[i]->Stop();
1346 delete threads[i];
1347 delete task_complete_events[i];
1348 }
1349
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001350 EndTraceAndFlush();
jbates@chromium.orgb84db522011-10-04 02:51:25 +09001351
jbates@chromium.org6a092d72011-10-25 01:34:08 +09001352 ValidateInstantEventPresentOnEveryThread(trace_parsed_,
nduca@chromium.org6d048772011-08-10 00:16:25 +09001353 num_threads, num_events);
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001354}
1355
nduca@chromium.org6d048772011-08-10 00:16:25 +09001356// Test that thread and process names show up in the trace
1357TEST_F(TraceEventTestFixture, ThreadNames) {
nduca@chromium.org6d048772011-08-10 00:16:25 +09001358 // Create threads before we enable tracing to make sure
1359 // that tracelog still captures them.
1360 const int num_threads = 4;
1361 const int num_events = 10;
1362 Thread* threads[num_threads];
1363 PlatformThreadId thread_ids[num_threads];
1364 for (int i = 0; i < num_threads; i++)
1365 threads[i] = new Thread(StringPrintf("Thread %d", i).c_str());
1366
1367 // Enable tracing.
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001368 BeginTrace();
nduca@chromium.org6d048772011-08-10 00:16:25 +09001369
1370 // Now run some trace code on these threads.
1371 WaitableEvent* task_complete_events[num_threads];
1372 for (int i = 0; i < num_threads; i++) {
1373 task_complete_events[i] = new WaitableEvent(false, false);
1374 threads[i]->Start();
1375 thread_ids[i] = threads[i]->thread_id();
1376 threads[i]->message_loop()->PostTask(
jbates@chromium.org0b837e42011-10-06 01:58:20 +09001377 FROM_HERE, base::Bind(&TraceManyInstantEvents,
1378 i, num_events, task_complete_events[i]));
nduca@chromium.org6d048772011-08-10 00:16:25 +09001379 }
1380 for (int i = 0; i < num_threads; i++) {
1381 task_complete_events[i]->Wait();
1382 }
1383
1384 // Shut things down.
nduca@chromium.org6d048772011-08-10 00:16:25 +09001385 for (int i = 0; i < num_threads; i++) {
1386 threads[i]->Stop();
1387 delete threads[i];
1388 delete task_complete_events[i];
1389 }
1390
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001391 EndTraceAndFlush();
jbates@chromium.orgb84db522011-10-04 02:51:25 +09001392
nduca@chromium.org6d048772011-08-10 00:16:25 +09001393 std::string tmp;
1394 int tmp_int;
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +09001395 const DictionaryValue* item;
nduca@chromium.org6d048772011-08-10 00:16:25 +09001396
1397 // Make sure we get thread name metadata.
1398 // Note, the test suite may have created a ton of threads.
1399 // So, we'll have thread names for threads we didn't create.
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +09001400 std::vector<const DictionaryValue*> items =
nduca@chromium.org6d048772011-08-10 00:16:25 +09001401 FindTraceEntries(trace_parsed_, "thread_name");
1402 for (int i = 0; i < static_cast<int>(items.size()); i++) {
1403 item = items[i];
joth@chromium.org088ae012011-11-11 01:26:23 +09001404 ASSERT_TRUE(item);
nduca@chromium.org6d048772011-08-10 00:16:25 +09001405 EXPECT_TRUE(item->GetInteger("tid", &tmp_int));
1406
1407 // See if this thread name is one of the threads we just created
1408 for (int j = 0; j < num_threads; j++) {
1409 if(static_cast<int>(thread_ids[j]) != tmp_int)
1410 continue;
1411
jbates@chromium.org62a16662012-02-04 08:18:06 +09001412 std::string expected_name = StringPrintf("Thread %d", j);
nduca@chromium.org6d048772011-08-10 00:16:25 +09001413 EXPECT_TRUE(item->GetString("ph", &tmp) && tmp == "M");
1414 EXPECT_TRUE(item->GetInteger("pid", &tmp_int) &&
1415 tmp_int == static_cast<int>(base::GetCurrentProcId()));
jbates@chromium.org62a16662012-02-04 08:18:06 +09001416 // If the thread name changes or the tid gets reused, the name will be
1417 // a comma-separated list of thread names, so look for a substring.
nduca@chromium.org6d048772011-08-10 00:16:25 +09001418 EXPECT_TRUE(item->GetString("args.name", &tmp) &&
jbates@chromium.org62a16662012-02-04 08:18:06 +09001419 tmp.find(expected_name) != std::string::npos);
nduca@chromium.org6d048772011-08-10 00:16:25 +09001420 }
1421 }
scheib@chromium.org603f46e2011-05-10 11:23:58 +09001422}
1423
joth@chromium.org088ae012011-11-11 01:26:23 +09001424TEST_F(TraceEventTestFixture, ThreadNameChanges) {
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001425 BeginTrace();
joth@chromium.org088ae012011-11-11 01:26:23 +09001426
1427 PlatformThread::SetName("");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001428 TRACE_EVENT_INSTANT0("drink", "water", TRACE_EVENT_SCOPE_THREAD);
joth@chromium.org088ae012011-11-11 01:26:23 +09001429
1430 PlatformThread::SetName("cafe");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001431 TRACE_EVENT_INSTANT0("drink", "coffee", TRACE_EVENT_SCOPE_THREAD);
joth@chromium.org088ae012011-11-11 01:26:23 +09001432
1433 PlatformThread::SetName("shop");
1434 // No event here, so won't appear in combined name.
1435
1436 PlatformThread::SetName("pub");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001437 TRACE_EVENT_INSTANT0("drink", "beer", TRACE_EVENT_SCOPE_THREAD);
1438 TRACE_EVENT_INSTANT0("drink", "wine", TRACE_EVENT_SCOPE_THREAD);
joth@chromium.org088ae012011-11-11 01:26:23 +09001439
1440 PlatformThread::SetName(" bar");
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001441 TRACE_EVENT_INSTANT0("drink", "whisky", TRACE_EVENT_SCOPE_THREAD);
joth@chromium.org088ae012011-11-11 01:26:23 +09001442
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001443 EndTraceAndFlush();
joth@chromium.org088ae012011-11-11 01:26:23 +09001444
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +09001445 std::vector<const DictionaryValue*> items =
joth@chromium.org088ae012011-11-11 01:26:23 +09001446 FindTraceEntries(trace_parsed_, "thread_name");
1447 EXPECT_EQ(1u, items.size());
1448 ASSERT_GT(items.size(), 0u);
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +09001449 const DictionaryValue* item = items[0];
joth@chromium.org088ae012011-11-11 01:26:23 +09001450 ASSERT_TRUE(item);
1451 int tid;
1452 EXPECT_TRUE(item->GetInteger("tid", &tid));
1453 EXPECT_EQ(PlatformThread::CurrentId(), static_cast<PlatformThreadId>(tid));
1454
1455 std::string expected_name = "cafe,pub, bar";
1456 std::string tmp;
1457 EXPECT_TRUE(item->GetString("args.name", &tmp));
1458 EXPECT_EQ(expected_name, tmp);
1459}
nduca@chromium.org6d048772011-08-10 00:16:25 +09001460
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001461// Test that the disabled trace categories are included/excluded from the
1462// trace output correctly.
1463TEST_F(TraceEventTestFixture, DisabledCategories) {
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001464 BeginTrace();
1465 TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "first",
1466 TRACE_EVENT_SCOPE_THREAD);
1467 TRACE_EVENT_INSTANT0("included", "first", TRACE_EVENT_SCOPE_THREAD);
1468 EndTraceAndFlush();
1469 {
1470 const DictionaryValue* item = NULL;
1471 ListValue& trace_parsed = trace_parsed_;
1472 EXPECT_NOT_FIND_("disabled-by-default-cc");
1473 EXPECT_FIND_("included");
1474 }
1475 Clear();
1476
1477 BeginSpecificTrace("disabled-by-default-cc");
1478 TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "second",
1479 TRACE_EVENT_SCOPE_THREAD);
1480 TRACE_EVENT_INSTANT0("other_included", "second", TRACE_EVENT_SCOPE_THREAD);
1481 EndTraceAndFlush();
1482
1483 {
1484 const DictionaryValue* item = NULL;
1485 ListValue& trace_parsed = trace_parsed_;
1486 EXPECT_FIND_("disabled-by-default-cc");
1487 EXPECT_FIND_("other_included");
1488 }
1489}
1490
joth@chromium.org113de992011-07-21 21:28:59 +09001491TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) {
1492 // Test that the TRACE_EVENT macros do not deep-copy their string. If they
1493 // do so it may indicate a performance regression, but more-over it would
1494 // make the DEEP_COPY overloads redundant.
joth@chromium.org113de992011-07-21 21:28:59 +09001495 std::string name_string("event name");
1496
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001497 BeginTrace();
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001498 TRACE_EVENT_INSTANT0("category", name_string.c_str(),
1499 TRACE_EVENT_SCOPE_THREAD);
joth@chromium.org113de992011-07-21 21:28:59 +09001500
1501 // Modify the string in place (a wholesale reassignment may leave the old
1502 // string intact on the heap).
1503 name_string[0] = '@';
1504
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001505 EndTraceAndFlush();
joth@chromium.org113de992011-07-21 21:28:59 +09001506
1507 EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name"));
1508 EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str()));
1509}
1510
1511TEST_F(TraceEventTestFixture, DeepCopy) {
joth@chromium.org113de992011-07-21 21:28:59 +09001512 static const char kOriginalName1[] = "name1";
1513 static const char kOriginalName2[] = "name2";
1514 static const char kOriginalName3[] = "name3";
1515 std::string name1(kOriginalName1);
1516 std::string name2(kOriginalName2);
1517 std::string name3(kOriginalName3);
1518 std::string arg1("arg1");
1519 std::string arg2("arg2");
1520 std::string val1("val1");
1521 std::string val2("val2");
1522
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001523 BeginTrace();
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001524 TRACE_EVENT_COPY_INSTANT0("category", name1.c_str(),
1525 TRACE_EVENT_SCOPE_THREAD);
joth@chromium.org113de992011-07-21 21:28:59 +09001526 TRACE_EVENT_COPY_BEGIN1("category", name2.c_str(),
1527 arg1.c_str(), 5);
1528 TRACE_EVENT_COPY_END2("category", name3.c_str(),
jbates@chromium.org1f18e462011-09-07 02:56:24 +09001529 arg1.c_str(), val1,
1530 arg2.c_str(), val2);
joth@chromium.org113de992011-07-21 21:28:59 +09001531
1532 // As per NormallyNoDeepCopy, modify the strings in place.
1533 name1[0] = name2[0] = name3[0] = arg1[0] = arg2[0] = val1[0] = val2[0] = '@';
1534
jbates@chromium.org6f1b35c2012-09-01 09:52:15 +09001535 EndTraceAndFlush();
joth@chromium.org113de992011-07-21 21:28:59 +09001536
1537 EXPECT_FALSE(FindTraceEntry(trace_parsed_, name1.c_str()));
1538 EXPECT_FALSE(FindTraceEntry(trace_parsed_, name2.c_str()));
1539 EXPECT_FALSE(FindTraceEntry(trace_parsed_, name3.c_str()));
1540
vabr@chromium.orga8ca4fd2012-08-03 17:43:37 +09001541 const DictionaryValue* entry1 = FindTraceEntry(trace_parsed_, kOriginalName1);
1542 const DictionaryValue* entry2 = FindTraceEntry(trace_parsed_, kOriginalName2);
1543 const DictionaryValue* entry3 = FindTraceEntry(trace_parsed_, kOriginalName3);
joth@chromium.org113de992011-07-21 21:28:59 +09001544 ASSERT_TRUE(entry1);
1545 ASSERT_TRUE(entry2);
1546 ASSERT_TRUE(entry3);
1547
1548 int i;
1549 EXPECT_FALSE(entry2->GetInteger("args.@rg1", &i));
1550 EXPECT_TRUE(entry2->GetInteger("args.arg1", &i));
1551 EXPECT_EQ(5, i);
1552
1553 std::string s;
1554 EXPECT_TRUE(entry3->GetString("args.arg1", &s));
1555 EXPECT_EQ("val1", s);
1556 EXPECT_TRUE(entry3->GetString("args.arg2", &s));
1557 EXPECT_EQ("val2", s);
1558}
1559
jbates@chromium.org6a092d72011-10-25 01:34:08 +09001560// Test that TraceResultBuffer outputs the correct result whether it is added
1561// in chunks or added all at once.
1562TEST_F(TraceEventTestFixture, TraceResultBuffer) {
jbates@chromium.org6a092d72011-10-25 01:34:08 +09001563 Clear();
1564
1565 trace_buffer_.Start();
1566 trace_buffer_.AddFragment("bla1");
1567 trace_buffer_.AddFragment("bla2");
1568 trace_buffer_.AddFragment("bla3,bla4");
1569 trace_buffer_.Finish();
1570 EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1571
1572 Clear();
1573
1574 trace_buffer_.Start();
1575 trace_buffer_.AddFragment("bla1,bla2,bla3,bla4");
1576 trace_buffer_.Finish();
1577 EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1578}
1579
dsinclair@chromium.org1cde1592013-01-15 01:53:06 +09001580// Test that trace_event parameters are not evaluated if the tracing
1581// system is disabled.
1582TEST_F(TraceEventTestFixture, TracingIsLazy) {
dsinclair@chromium.org1cde1592013-01-15 01:53:06 +09001583 BeginTrace();
1584
1585 int a = 0;
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001586 TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
dsinclair@chromium.org1cde1592013-01-15 01:53:06 +09001587 EXPECT_EQ(1, a);
1588
1589 TraceLog::GetInstance()->SetDisabled();
1590
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001591 TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
dsinclair@chromium.org1cde1592013-01-15 01:53:06 +09001592 EXPECT_EQ(1, a);
1593
1594 EndTraceAndFlush();
1595}
1596
caseq@google.comedcf6262013-01-16 20:41:57 +09001597TEST_F(TraceEventTestFixture, TraceEnableDisable) {
caseq@google.comedcf6262013-01-16 20:41:57 +09001598 TraceLog* trace_log = TraceLog::GetInstance();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001599 CategoryFilter cf_inc_all("*");
1600 trace_log->SetEnabled(cf_inc_all, TraceLog::RECORD_UNTIL_FULL);
caseq@google.comedcf6262013-01-16 20:41:57 +09001601 EXPECT_TRUE(trace_log->IsEnabled());
1602 trace_log->SetDisabled();
1603 EXPECT_FALSE(trace_log->IsEnabled());
1604
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001605 trace_log->SetEnabled(cf_inc_all, TraceLog::RECORD_UNTIL_FULL);
caseq@google.comedcf6262013-01-16 20:41:57 +09001606 EXPECT_TRUE(trace_log->IsEnabled());
1607 const std::vector<std::string> empty;
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001608 trace_log->SetEnabled(CategoryFilter(""), TraceLog::RECORD_UNTIL_FULL);
caseq@google.comedcf6262013-01-16 20:41:57 +09001609 EXPECT_TRUE(trace_log->IsEnabled());
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001610 trace_log->SetDisabled();
caseq@google.comedcf6262013-01-16 20:41:57 +09001611 EXPECT_TRUE(trace_log->IsEnabled());
1612 trace_log->SetDisabled();
1613 EXPECT_FALSE(trace_log->IsEnabled());
1614}
1615
1616TEST_F(TraceEventTestFixture, TraceCategoriesAfterNestedEnable) {
caseq@google.comedcf6262013-01-16 20:41:57 +09001617 TraceLog* trace_log = TraceLog::GetInstance();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001618 trace_log->SetEnabled(CategoryFilter("foo,bar"), TraceLog::RECORD_UNTIL_FULL);
1619 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
1620 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
junov@chromium.org5daaa152013-08-17 04:02:53 +09001621 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001622 trace_log->SetEnabled(CategoryFilter("foo2"), TraceLog::RECORD_UNTIL_FULL);
1623 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo2"));
junov@chromium.org5daaa152013-08-17 04:02:53 +09001624 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001625 // The "" becomes the default catergory set when applied.
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001626 trace_log->SetEnabled(CategoryFilter(""), TraceLog::RECORD_UNTIL_FULL);
1627 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
1628 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001629 EXPECT_STREQ("-*Debug,-*Test",
1630 trace_log->GetCurrentCategoryFilter().ToString().c_str());
caseq@google.comedcf6262013-01-16 20:41:57 +09001631 trace_log->SetDisabled();
1632 trace_log->SetDisabled();
1633 trace_log->SetDisabled();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001634 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1635 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
caseq@google.comedcf6262013-01-16 20:41:57 +09001636
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001637 trace_log->SetEnabled(CategoryFilter("-foo,-bar"),
1638 TraceLog::RECORD_UNTIL_FULL);
1639 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1640 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1641 trace_log->SetEnabled(CategoryFilter("moo"), TraceLog::RECORD_UNTIL_FULL);
1642 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1643 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("moo"));
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001644 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1645 EXPECT_STREQ("-foo,-bar",
1646 trace_log->GetCurrentCategoryFilter().ToString().c_str());
1647 trace_log->SetDisabled();
1648 trace_log->SetDisabled();
1649
1650 // Make sure disabled categories aren't cleared if we set in the second.
1651 trace_log->SetEnabled(CategoryFilter("disabled-by-default-cc,foo"),
1652 TraceLog::RECORD_UNTIL_FULL);
junov@chromium.org5daaa152013-08-17 04:02:53 +09001653 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("bar"));
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001654 trace_log->SetEnabled(CategoryFilter("disabled-by-default-gpu"),
1655 TraceLog::RECORD_UNTIL_FULL);
1656 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-cc"));
1657 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-gpu"));
1658 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
1659 EXPECT_STREQ("disabled-by-default-cc,disabled-by-default-gpu",
1660 trace_log->GetCurrentCategoryFilter().ToString().c_str());
caseq@google.comedcf6262013-01-16 20:41:57 +09001661 trace_log->SetDisabled();
1662 trace_log->SetDisabled();
1663}
1664
dsinclair@chromium.orga7fb8d62013-02-23 11:09:53 +09001665TEST_F(TraceEventTestFixture, TraceOptionsParsing) {
dcheng@chromium.org8164c2c2013-04-09 17:46:45 +09001666 EXPECT_EQ(TraceLog::RECORD_UNTIL_FULL,
1667 TraceLog::TraceOptionsFromString(std::string()));
dsinclair@chromium.orga7fb8d62013-02-23 11:09:53 +09001668
1669 EXPECT_EQ(TraceLog::RECORD_UNTIL_FULL,
1670 TraceLog::TraceOptionsFromString("record-until-full"));
dsinclair@chromium.org9e717e82013-03-16 08:28:44 +09001671 EXPECT_EQ(TraceLog::RECORD_CONTINUOUSLY,
1672 TraceLog::TraceOptionsFromString("record-continuously"));
dsinclair@chromium.org7f451932013-06-25 08:25:01 +09001673 EXPECT_EQ(TraceLog::RECORD_UNTIL_FULL | TraceLog::ENABLE_SAMPLING,
1674 TraceLog::TraceOptionsFromString("enable-sampling"));
1675 EXPECT_EQ(TraceLog::RECORD_CONTINUOUSLY | TraceLog::ENABLE_SAMPLING,
1676 TraceLog::TraceOptionsFromString(
1677 "record-continuously,enable-sampling"));
dsinclair@chromium.orga7fb8d62013-02-23 11:09:53 +09001678}
1679
scottmg@chromium.orgcdd292f2013-02-26 10:39:52 +09001680TEST_F(TraceEventTestFixture, TraceSampling) {
scottmg@chromium.orgcdd292f2013-02-26 10:39:52 +09001681 event_watch_notification_ = 0;
1682 TraceLog::GetInstance()->SetEnabled(
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001683 CategoryFilter("*"),
scottmg@chromium.orgcdd292f2013-02-26 10:39:52 +09001684 TraceLog::Options(TraceLog::RECORD_UNTIL_FULL |
1685 TraceLog::ENABLE_SAMPLING));
1686
1687 WaitableEvent* sampled = new WaitableEvent(false, false);
1688 TraceLog::GetInstance()->InstallWaitableEventForSamplingTesting(sampled);
1689
haraken@chromium.org26881c62013-07-04 17:54:07 +09001690 TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "cc", "Stuff");
scottmg@chromium.orgcdd292f2013-02-26 10:39:52 +09001691 sampled->Wait();
haraken@chromium.org26881c62013-07-04 17:54:07 +09001692 TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "cc", "Things");
scottmg@chromium.orgcdd292f2013-02-26 10:39:52 +09001693 sampled->Wait();
1694
1695 EndTraceAndFlush();
1696
1697 // Make sure we hit at least once.
1698 EXPECT_TRUE(FindNamePhase("Stuff", "P"));
1699 EXPECT_TRUE(FindNamePhase("Things", "P"));
1700}
haraken@chromium.org26881c62013-07-04 17:54:07 +09001701
1702TEST_F(TraceEventTestFixture, TraceSamplingScope) {
haraken@chromium.org26881c62013-07-04 17:54:07 +09001703 event_watch_notification_ = 0;
1704 TraceLog::GetInstance()->SetEnabled(
1705 CategoryFilter("*"),
1706 TraceLog::Options(TraceLog::RECORD_UNTIL_FULL |
1707 TraceLog::ENABLE_SAMPLING));
1708
1709 WaitableEvent* sampled = new WaitableEvent(false, false);
1710 TraceLog::GetInstance()->InstallWaitableEventForSamplingTesting(sampled);
1711
1712 TRACE_EVENT_SCOPED_SAMPLING_STATE("AAA", "name");
1713 sampled->Wait();
1714 {
1715 EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "AAA");
1716 TRACE_EVENT_SCOPED_SAMPLING_STATE("BBB", "name");
1717 sampled->Wait();
1718 EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "BBB");
1719 }
1720 sampled->Wait();
1721 {
1722 EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "AAA");
1723 TRACE_EVENT_SCOPED_SAMPLING_STATE("CCC", "name");
1724 sampled->Wait();
1725 EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "CCC");
1726 }
1727 sampled->Wait();
1728 {
1729 EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "AAA");
1730 TRACE_EVENT_SET_SAMPLING_STATE("DDD", "name");
1731 sampled->Wait();
1732 EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "DDD");
1733 }
1734 sampled->Wait();
1735 EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "DDD");
1736
1737 EndTraceAndFlush();
1738}
scottmg@chromium.orgcdd292f2013-02-26 10:39:52 +09001739
tonyg@chromium.orgff79f832013-05-04 00:40:47 +09001740class MyData : public base::debug::ConvertableToTraceFormat {
1741 public:
1742 MyData() {}
1743 virtual ~MyData() {}
1744
1745 virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE {
1746 out->append("{\"foo\":1}");
1747 }
1748
1749 private:
1750 DISALLOW_COPY_AND_ASSIGN(MyData);
1751};
1752
1753TEST_F(TraceEventTestFixture, ConvertableTypes) {
tonyg@chromium.orgff79f832013-05-04 00:40:47 +09001754 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
1755 TraceLog::RECORD_UNTIL_FULL);
1756
1757 scoped_ptr<MyData> data(new MyData());
1758 scoped_ptr<MyData> data1(new MyData());
1759 scoped_ptr<MyData> data2(new MyData());
1760 TRACE_EVENT1("foo", "bar", "data",
1761 data.PassAs<base::debug::ConvertableToTraceFormat>());
1762 TRACE_EVENT2("foo", "baz",
1763 "data1", data1.PassAs<base::debug::ConvertableToTraceFormat>(),
1764 "data2", data2.PassAs<base::debug::ConvertableToTraceFormat>());
1765
dsinclair@chromium.orgca96ff42013-05-09 00:17:35 +09001766
1767 scoped_ptr<MyData> convertData1(new MyData());
1768 scoped_ptr<MyData> convertData2(new MyData());
1769 TRACE_EVENT2(
1770 "foo",
1771 "string_first",
1772 "str",
1773 "string value 1",
1774 "convert",
1775 convertData1.PassAs<base::debug::ConvertableToTraceFormat>());
1776 TRACE_EVENT2(
1777 "foo",
1778 "string_second",
1779 "convert",
1780 convertData2.PassAs<base::debug::ConvertableToTraceFormat>(),
1781 "str",
1782 "string value 2");
tonyg@chromium.orgff79f832013-05-04 00:40:47 +09001783 EndTraceAndFlush();
1784
dsinclair@chromium.orgca96ff42013-05-09 00:17:35 +09001785 // One arg version.
tonyg@chromium.orgff79f832013-05-04 00:40:47 +09001786 DictionaryValue* dict = FindNamePhase("bar", "B");
1787 ASSERT_TRUE(dict);
1788
1789 const DictionaryValue* args_dict = NULL;
1790 dict->GetDictionary("args", &args_dict);
1791 ASSERT_TRUE(args_dict);
1792
1793 const Value* value = NULL;
1794 const DictionaryValue* convertable_dict = NULL;
1795 EXPECT_TRUE(args_dict->Get("data", &value));
1796 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1797
1798 int foo_val;
1799 EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
1800 EXPECT_EQ(1, foo_val);
1801
dsinclair@chromium.orgca96ff42013-05-09 00:17:35 +09001802 // Two arg version.
tonyg@chromium.orgff79f832013-05-04 00:40:47 +09001803 dict = FindNamePhase("baz", "B");
1804 ASSERT_TRUE(dict);
dsinclair@chromium.orgca96ff42013-05-09 00:17:35 +09001805
tonyg@chromium.orgff79f832013-05-04 00:40:47 +09001806 args_dict = NULL;
1807 dict->GetDictionary("args", &args_dict);
1808 ASSERT_TRUE(args_dict);
1809
1810 value = NULL;
1811 convertable_dict = NULL;
1812 EXPECT_TRUE(args_dict->Get("data1", &value));
1813 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1814
1815 value = NULL;
1816 convertable_dict = NULL;
1817 EXPECT_TRUE(args_dict->Get("data2", &value));
1818 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
tonyg@chromium.orgff79f832013-05-04 00:40:47 +09001819
dsinclair@chromium.orgca96ff42013-05-09 00:17:35 +09001820 // Convertable with other types.
1821 dict = FindNamePhase("string_first", "B");
1822 ASSERT_TRUE(dict);
1823
1824 args_dict = NULL;
1825 dict->GetDictionary("args", &args_dict);
1826 ASSERT_TRUE(args_dict);
1827
1828 std::string str_value;
1829 EXPECT_TRUE(args_dict->GetString("str", &str_value));
1830 EXPECT_STREQ("string value 1", str_value.c_str());
1831
1832 value = NULL;
1833 convertable_dict = NULL;
1834 foo_val = 0;
1835 EXPECT_TRUE(args_dict->Get("convert", &value));
1836 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1837 EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
1838 EXPECT_EQ(1, foo_val);
1839
1840 dict = FindNamePhase("string_second", "B");
1841 ASSERT_TRUE(dict);
1842
1843 args_dict = NULL;
1844 dict->GetDictionary("args", &args_dict);
1845 ASSERT_TRUE(args_dict);
1846
1847 EXPECT_TRUE(args_dict->GetString("str", &str_value));
1848 EXPECT_STREQ("string value 2", str_value.c_str());
1849
1850 value = NULL;
1851 convertable_dict = NULL;
1852 foo_val = 0;
1853 EXPECT_TRUE(args_dict->Get("convert", &value));
1854 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1855 EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
1856 EXPECT_EQ(1, foo_val);
1857}
tonyg@chromium.orgff79f832013-05-04 00:40:47 +09001858
caseq@google.com5f3846c2013-02-27 18:11:12 +09001859class TraceEventCallbackTest : public TraceEventTestFixture {
1860 public:
1861 virtual void SetUp() OVERRIDE {
1862 TraceEventTestFixture::SetUp();
caseq@google.com5f3846c2013-02-27 18:11:12 +09001863 ASSERT_EQ(NULL, s_instance);
1864 s_instance = this;
1865 }
1866 virtual void TearDown() OVERRIDE {
1867 while (TraceLog::GetInstance()->IsEnabled())
1868 TraceLog::GetInstance()->SetDisabled();
1869 ASSERT_TRUE(!!s_instance);
1870 s_instance = NULL;
1871 TraceEventTestFixture::TearDown();
1872 }
1873
1874 protected:
1875 std::vector<std::string> collected_events_;
1876
1877 static TraceEventCallbackTest* s_instance;
1878 static void Callback(char phase,
1879 const unsigned char* category_enabled,
1880 const char* name,
1881 unsigned long long id,
1882 int num_args,
1883 const char* const arg_names[],
1884 const unsigned char arg_types[],
1885 const unsigned long long arg_values[],
1886 unsigned char flags) {
1887 s_instance->collected_events_.push_back(name);
1888 }
1889};
1890
1891TraceEventCallbackTest* TraceEventCallbackTest::s_instance;
1892
1893TEST_F(TraceEventCallbackTest, TraceEventCallback) {
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001894 TRACE_EVENT_INSTANT0("all", "before enable", TRACE_EVENT_SCOPE_THREAD);
1895 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
1896 TraceLog::RECORD_UNTIL_FULL);
1897 TRACE_EVENT_INSTANT0("all", "before callback set", TRACE_EVENT_SCOPE_THREAD);
caseq@google.com5f3846c2013-02-27 18:11:12 +09001898 TraceLog::GetInstance()->SetEventCallback(Callback);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001899 TRACE_EVENT_INSTANT0("all", "event1", TRACE_EVENT_SCOPE_GLOBAL);
1900 TRACE_EVENT_INSTANT0("all", "event2", TRACE_EVENT_SCOPE_GLOBAL);
caseq@google.com5f3846c2013-02-27 18:11:12 +09001901 TraceLog::GetInstance()->SetEventCallback(NULL);
simonjam@chromium.orgfd92ef32013-03-26 16:42:42 +09001902 TRACE_EVENT_INSTANT0("all", "after callback removed",
1903 TRACE_EVENT_SCOPE_GLOBAL);
caseq@google.com4cba9892013-04-29 18:08:28 +09001904 ASSERT_EQ(2u, collected_events_.size());
caseq@google.com5f3846c2013-02-27 18:11:12 +09001905 EXPECT_EQ("event1", collected_events_[0]);
1906 EXPECT_EQ("event2", collected_events_[1]);
1907}
1908
caseq@google.com4cba9892013-04-29 18:08:28 +09001909TEST_F(TraceEventCallbackTest, TraceEventCallbackWhileFull) {
1910 TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
1911 TraceLog::RECORD_UNTIL_FULL);
1912 do {
1913 TRACE_EVENT_INSTANT0("all", "badger badger", TRACE_EVENT_SCOPE_GLOBAL);
1914 } while ((notifications_received_ & TraceLog::TRACE_BUFFER_FULL) == 0);
1915 TraceLog::GetInstance()->SetEventCallback(Callback);
1916 TRACE_EVENT_INSTANT0("all", "a snake", TRACE_EVENT_SCOPE_GLOBAL);
1917 TraceLog::GetInstance()->SetEventCallback(NULL);
1918 ASSERT_EQ(1u, collected_events_.size());
1919 EXPECT_EQ("a snake", collected_events_[0]);
1920}
1921
dsinclair@chromium.org9e717e82013-03-16 08:28:44 +09001922// TODO(dsinclair): Continuous Tracing unit test.
1923
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001924// Test the category filter.
1925TEST_F(TraceEventTestFixture, CategoryFilter) {
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001926 // Using the default filter.
1927 CategoryFilter default_cf = CategoryFilter(
1928 CategoryFilter::kDefaultCategoryFilterString);
1929 std::string category_filter_str = default_cf.ToString();
1930 EXPECT_STREQ("-*Debug,-*Test", category_filter_str.c_str());
1931 EXPECT_TRUE(default_cf.IsCategoryGroupEnabled("not-excluded-category"));
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001932 EXPECT_FALSE(
1933 default_cf.IsCategoryGroupEnabled("disabled-by-default-category"));
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001934 EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("Category1,CategoryDebug"));
1935 EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryDebug,Category1"));
1936 EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryTest,Category2"));
1937
1938 // Make sure that upon an empty string, we fall back to the default filter.
1939 default_cf = CategoryFilter("");
1940 category_filter_str = default_cf.ToString();
1941 EXPECT_STREQ("-*Debug,-*Test", category_filter_str.c_str());
1942 EXPECT_TRUE(default_cf.IsCategoryGroupEnabled("not-excluded-category"));
1943 EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("Category1,CategoryDebug"));
1944 EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryDebug,Category1"));
1945 EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryTest,Category2"));
1946
1947 // Using an arbitrary non-empty filter.
1948 CategoryFilter cf("included,-excluded,inc_pattern*,-exc_pattern*");
1949 category_filter_str = cf.ToString();
1950 EXPECT_STREQ("included,inc_pattern*,-excluded,-exc_pattern*",
1951 category_filter_str.c_str());
1952 EXPECT_TRUE(cf.IsCategoryGroupEnabled("included"));
1953 EXPECT_TRUE(cf.IsCategoryGroupEnabled("inc_pattern_category"));
1954 EXPECT_FALSE(cf.IsCategoryGroupEnabled("exc_pattern_category"));
1955 EXPECT_FALSE(cf.IsCategoryGroupEnabled("excluded"));
junov@chromium.org5daaa152013-08-17 04:02:53 +09001956 EXPECT_FALSE(cf.IsCategoryGroupEnabled("not-excluded-nor-included"));
1957 EXPECT_FALSE(cf.IsCategoryGroupEnabled("Category1,CategoryDebug"));
1958 EXPECT_FALSE(cf.IsCategoryGroupEnabled("CategoryDebug,Category1"));
1959 EXPECT_FALSE(cf.IsCategoryGroupEnabled("CategoryTest,Category2"));
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001960
1961 cf.Merge(default_cf);
1962 category_filter_str = cf.ToString();
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001963 EXPECT_STREQ("-excluded,-exc_pattern*,-*Debug,-*Test",
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001964 category_filter_str.c_str());
1965 cf.Clear();
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001966
1967 CategoryFilter reconstructed_cf(category_filter_str);
1968 category_filter_str = reconstructed_cf.ToString();
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001969 EXPECT_STREQ("-excluded,-exc_pattern*,-*Debug,-*Test",
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09001970 category_filter_str.c_str());
1971
1972 // One included category.
1973 CategoryFilter one_inc_cf("only_inc_cat");
1974 category_filter_str = one_inc_cf.ToString();
1975 EXPECT_STREQ("only_inc_cat", category_filter_str.c_str());
1976
1977 // One excluded category.
1978 CategoryFilter one_exc_cf("-only_exc_cat");
1979 category_filter_str = one_exc_cf.ToString();
1980 EXPECT_STREQ("-only_exc_cat", category_filter_str.c_str());
1981
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09001982 // Enabling a disabled- category does not require all categories to be traced
1983 // to be included.
1984 CategoryFilter disabled_cat("disabled-by-default-cc,-excluded");
1985 EXPECT_STREQ("disabled-by-default-cc,-excluded",
1986 disabled_cat.ToString().c_str());
1987 EXPECT_TRUE(disabled_cat.IsCategoryGroupEnabled("disabled-by-default-cc"));
1988 EXPECT_TRUE(disabled_cat.IsCategoryGroupEnabled("some_other_group"));
1989 EXPECT_FALSE(disabled_cat.IsCategoryGroupEnabled("excluded"));
1990
1991 // Enabled a disabled- category and also including makes all categories to
1992 // be traced require including.
1993 CategoryFilter disabled_inc_cat("disabled-by-default-cc,included");
1994 EXPECT_STREQ("included,disabled-by-default-cc",
1995 disabled_inc_cat.ToString().c_str());
1996 EXPECT_TRUE(
1997 disabled_inc_cat.IsCategoryGroupEnabled("disabled-by-default-cc"));
1998 EXPECT_TRUE(disabled_inc_cat.IsCategoryGroupEnabled("included"));
junov@chromium.org5daaa152013-08-17 04:02:53 +09001999 EXPECT_FALSE(disabled_inc_cat.IsCategoryGroupEnabled("other_included"));
dsinclair@chromium.org3f838632013-05-08 05:17:27 +09002000
rubentopo@gmail.com56a2b642013-04-19 17:49:03 +09002001 // Test that IsEmptyOrContainsLeadingOrTrailingWhitespace actually catches
2002 // categories that are explicitly forbiden.
2003 // This method is called in a DCHECK to assert that we don't have these types
2004 // of strings as categories.
2005 EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2006 " bad_category "));
2007 EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2008 " bad_category"));
2009 EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2010 "bad_category "));
2011 EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2012 " bad_category"));
2013 EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2014 "bad_category "));
2015 EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2016 " bad_category "));
2017 EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2018 ""));
2019 EXPECT_FALSE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2020 "good_category"));
2021}
2022
scheib@chromium.org603f46e2011-05-10 11:23:58 +09002023} // namespace debug
2024} // namespace base