1 // Copyright 2015 The Chromium Authors
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include "base/trace_event/trace_event_etw_export_win.h"
6
7 #include <windows.h>
8
9 #include <evntrace.h>
10 #include <guiddef.h>
11 #include <stddef.h>
12 #include <stdlib.h>
13
14 #include <string_view>
15 #include <utility>
16
17 #include "base/at_exit.h"
18 #include "base/check_op.h"
19 #include "base/command_line.h"
20 #include "base/logging.h"
21 #include "base/memory/singleton.h"
22 #include "base/no_destructor.h"
23 #include "base/strings/string_tokenizer.h"
24 #include "base/strings/string_util.h"
25 #include "base/strings/utf_string_conversions.h"
26 #include "base/threading/platform_thread.h"
27 #include "base/trace_event/trace_event.h"
28 #include "base/trace_event/trace_event_impl.h"
29 #include "base/trace_event/trace_logging_minimal_win.h"
30
31 namespace {
32
33 // |kFilteredEventGroupNames| contains the event categories that can be
34 // exported individually. These categories can be enabled by passing the correct
35 // keyword when starting the trace. A keyword is a 64-bit flag and we attribute
36 // one bit per category. We can therefore enable a particular category by
37 // setting its corresponding bit in the keyword. For events that are not present
38 // in |kFilteredEventGroupNames|, we have two bits that control their
39 // behaviour. When bit 46 is enabled, any event that is not disabled by default
40 // (ie. doesn't start with disabled-by-default-) will be exported. Likewise,
41 // when bit 47 is enabled, any event that is disabled by default will be
42 // exported.
43 //
44 // Examples of passing keywords to the provider using xperf:
45 // # This exports "benchmark" and "cc" events
46 // xperf -start chrome -on Chrome:0x9
47 //
48 // # This exports "gpu", "netlog" and all other events that are not disabled by
49 // # default
50 // xperf -start chrome -on Chrome:0x4000000000A0
51 //
52 // More info about starting a trace and keyword can be obtained by using the
53 // help section of xperf (xperf -help start). Note that xperf documentation
54 // refers to keywords as flags and there are two ways to enable them, using
55 // group names or the hex representation. We only support the latter. Also, we
56 // ignore the level.
57 //
58 // To avoid continually having to bump MSEdge values to next higher bits, we
59 // are putting MSEdge values at the high end of the bit range and will grow
60 // 'down' to lower bits for future MSEdge entries.
61 //
62 // As the writing of this comment, we have 4 values:
63 // "navigation", // 0x40000000000
64 // "ServiceWorker", // 0x80000000000
65 // "edge_webview", // 0x100000000000
66 // "diagnostic_event", // 0x200000000000
67 //
68 // This means the next value added should be:
69 // "the_next_value", // 0x20000000000
70 // "navigation", // 0x40000000000
71 // "ServiceWorker", // 0x80000000000
72 // "edge_webview", // 0x100000000000
73 // "diagnostic_event", // 0x200000000000
74 //
75 // The addition of the "unused_bit_nn" entries keeps the existing code execution
76 // routines working (ex. TraceEventETWExport::UpdateEnabledCategories()) and
77 // enables others to see which bits are available.
78 //
79 // Example: For some new category group...
80 // "latency", // 0x8000
81 // "blink.user_timing", // 0x10000
82 // "unused_bit_18", // 0x20000
83 // "unused_bit_19", // 0x40000
84 // "unused_bit_20", // 0x80000
85 // ...
86 // becomes:
87 // "latency", // 0x8000
88 // "blink.user_timing", // 0x10000
89 // "new_upstream_value", // 0x20000
90 // "unused_bit_19", // 0x40000
91 // "unused_bit_20", // 0x80000
92 //
93 // The high 16 bits of the keyword have special semantics and should not be
94 // set for enabling individual categories as they are reserved by winmeta.xml.
95 // TODO(crbug.com/1497783): Move this to
96 // components/tracing/common/etw_export_win.cc once no longer used by
97 // TraceEventETWExport.
98 const char* const kFilteredEventGroupNames[] = {
99 "benchmark", // 0x1
100 "blink", // 0x2
101 "browser", // 0x4
102 "cc", // 0x8
103 "evdev", // 0x10
104 "gpu", // 0x20
105 "input", // 0x40
106 "netlog", // 0x80
107 "sequence_manager", // 0x100
108 "toplevel", // 0x200
109 "v8", // 0x400
110 "disabled-by-default-cc.debug", // 0x800
111 "disabled-by-default-cc.debug.picture", // 0x1000
112 "disabled-by-default-toplevel.flow", // 0x2000
113 "startup", // 0x4000
114 "latency", // 0x8000
115 "blink.user_timing", // 0x10000
116 "media", // 0x20000
117 "loading", // 0x40000
118 "base", // 0x80000
119 "devtools.timeline", // 0x100000
120 "unused_bit_21", // 0x200000
121 "unused_bit_22", // 0x400000
122 "unused_bit_23", // 0x800000
123 "unused_bit_24", // 0x1000000
124 "unused_bit_25", // 0x2000000
125 "unused_bit_26", // 0x4000000
126 "unused_bit_27", // 0x8000000
127 "unused_bit_28", // 0x10000000
128 "unused_bit_29", // 0x20000000
129 "unused_bit_30", // 0x40000000
130 "unused_bit_31", // 0x80000000
131 "unused_bit_32", // 0x100000000
132 "unused_bit_33", // 0x200000000
133 "unused_bit_34", // 0x400000000
134 "unused_bit_35", // 0x800000000
135 "unused_bit_36", // 0x1000000000
136 "unused_bit_37", // 0x2000000000
137 "unused_bit_38", // 0x4000000000
138 "unused_bit_39", // 0x8000000000
139 "unused_bit_40", // 0x10000000000
140 "unused_bit_41", // 0x20000000000
141 "navigation", // 0x40000000000
142 "ServiceWorker", // 0x80000000000
143 "edge_webview", // 0x100000000000
144 "diagnostic_event", // 0x200000000000
145 "__OTHER_EVENTS", // 0x400000000000 See below
146 "__DISABLED_OTHER_EVENTS", // 0x800000000000 See below
147 };
148
149 // These must be kept as the last two entries in the above array.
150 constexpr uint8_t kOtherEventsGroupNameIndex = 46;
151 constexpr uint8_t kDisabledOtherEventsGroupNameIndex = 47;
152 constexpr uint64_t kCategoryKeywordMask = ~0xFFFF000000000000;
153
154 // Max number of available keyword bits.
155 constexpr size_t kMaxNumberOfGroupNames = 48;
156
157 } // namespace
158
159 namespace base {
160 namespace trace_event {
161
TraceEventETWExport()162 TraceEventETWExport::TraceEventETWExport() {
163 // Construct the ETW provider. If construction fails then the event logging
164 // calls will fail. We're passing a callback function as part of registration.
165 // This allows us to detect changes to enable/disable/keyword changes.
166 etw_provider_ = std::make_unique<TlmProvider>(
167 "Google.Chrome", Chrome_GUID,
168 base::BindRepeating(&TraceEventETWExport::OnETWEnableUpdate,
169 base::Unretained(this)));
170 is_registration_complete_ = true;
171
172 // Make sure to initialize the map with all the group names. Subsequent
173 // modifications will be made by the background thread and only affect the
174 // values of the keys (no key addition/deletion). Therefore, the map does not
175 // require a lock for access.
176 // Also set up the map from category name to keyword.
177 for (size_t i = 0; i < std::size(kFilteredEventGroupNames); i++) {
178 categories_status_[kFilteredEventGroupNames[i]] = false;
179 }
180 // Make sure we stay at 48 entries, the maximum number of bits available
181 // for keyword use.
182 static_assert(std::size(kFilteredEventGroupNames) <= kMaxNumberOfGroupNames,
183 "Exceeded max ETW keyword bits");
184 }
185
~TraceEventETWExport()186 TraceEventETWExport::~TraceEventETWExport() {
187 is_registration_complete_ = false;
188 }
189
190 // static
EnableETWExport()191 void TraceEventETWExport::EnableETWExport() {
192 auto* instance = GetInstance();
193 if (instance) {
194 // Sync the enabled categories with ETW by calling UpdateEnabledCategories()
195 // that checks the keyword. We'll stay in sync via the EtwEnableCallback
196 // we register in TraceEventETWExport's constructor.
197 instance->UpdateEnabledCategories();
198 }
199 }
200
201 // static
AddEvent(char phase,const unsigned char * category_group_enabled,const char * name,unsigned long long id,TimeTicks timestamp,const TraceArguments * args)202 void TraceEventETWExport::AddEvent(char phase,
203 const unsigned char* category_group_enabled,
204 const char* name,
205 unsigned long long id,
206 TimeTicks timestamp,
207 const TraceArguments* args) {
208 // We bail early in case exporting is disabled or no consumer is listening.
209 auto* instance = GetInstance();
210 if (!instance) {
211 return;
212 }
213 uint64_t keyword =
214 instance->CategoryStateToETWKeyword(category_group_enabled);
215 if (!instance->etw_provider_->IsEnabled(TRACE_LEVEL_NONE, keyword)) {
216 return;
217 }
218
219 const char* phase_string = nullptr;
220
221 // Space to store the phase identifier and null-terminator, when needed.
222 char phase_buffer[2];
223 switch (phase) {
224 case TRACE_EVENT_PHASE_BEGIN:
225 phase_string = "Begin";
226 break;
227 case TRACE_EVENT_PHASE_END:
228 phase_string = "End";
229 break;
230 case TRACE_EVENT_PHASE_COMPLETE:
231 phase_string = "Complete";
232 break;
233 case TRACE_EVENT_PHASE_INSTANT:
234 phase_string = "Instant";
235 break;
236 case TRACE_EVENT_PHASE_ASYNC_BEGIN:
237 phase_string = "Async Begin";
238 break;
239 case TRACE_EVENT_PHASE_ASYNC_STEP_INTO:
240 phase_string = "Async Step Into";
241 break;
242 case TRACE_EVENT_PHASE_ASYNC_STEP_PAST:
243 phase_string = "Async Step Past";
244 break;
245 case TRACE_EVENT_PHASE_ASYNC_END:
246 phase_string = "Async End";
247 break;
248 case TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN:
249 phase_string = "Nestable Async Begin";
250 break;
251 case TRACE_EVENT_PHASE_NESTABLE_ASYNC_END:
252 phase_string = "Nestable Async End";
253 break;
254 case TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT:
255 phase_string = "Nestable Async Instant";
256 break;
257 case TRACE_EVENT_PHASE_FLOW_BEGIN:
258 phase_string = "Phase Flow Begin";
259 break;
260 case TRACE_EVENT_PHASE_FLOW_STEP:
261 phase_string = "Phase Flow Step";
262 break;
263 case TRACE_EVENT_PHASE_FLOW_END:
264 phase_string = "Phase Flow End";
265 break;
266 case TRACE_EVENT_PHASE_METADATA:
267 phase_string = "Phase Metadata";
268 break;
269 case TRACE_EVENT_PHASE_COUNTER:
270 phase_string = "Phase Counter";
271 break;
272 case TRACE_EVENT_PHASE_SAMPLE:
273 phase_string = "Phase Sample";
274 break;
275 case TRACE_EVENT_PHASE_CREATE_OBJECT:
276 phase_string = "Phase Create Object";
277 break;
278 case TRACE_EVENT_PHASE_SNAPSHOT_OBJECT:
279 phase_string = "Phase Snapshot Object";
280 break;
281 case TRACE_EVENT_PHASE_DELETE_OBJECT:
282 phase_string = "Phase Delete Object";
283 break;
284 default:
285 phase_buffer[0] = phase;
286 phase_buffer[1] = 0;
287 phase_string = phase_buffer;
288 break;
289 }
290
291 std::string arg_values_string[3];
292 size_t num_args = args ? args->size() : 0;
293 for (size_t i = 0; i < num_args; i++) {
294 const auto type = args->types()[i];
295 if (type == TRACE_VALUE_TYPE_CONVERTABLE ||
296 type == TRACE_VALUE_TYPE_PROTO) {
297 // For convertable types, temporarily do nothing here. This function
298 // consumes 1/3 to 1/2 of *total* process CPU time when ETW tracing, and
299 // many of the strings created exceed WPA's 4094 byte limit and are shown
300 // as "Unable to parse data". See crbug.com/488257.
301 //
302 // For protobuf-based values, there is no string serialization so skip
303 // those as well.
304 } else {
305 args->values()[i].AppendAsString(type, arg_values_string + i);
306 }
307 }
308
309 int64_t timestamp_ms = (timestamp - TimeTicks()).InMilliseconds();
310 // Log the event and include the info needed to decode it via TraceLogging
311 if (num_args == 0) {
312 instance->etw_provider_->WriteEvent(
313 name, TlmEventDescriptor(0, keyword),
314 TlmMbcsStringField("Phase", phase_string),
315 TlmInt64Field("Timestamp", timestamp_ms));
316 } else if (num_args == 1) {
317 instance->etw_provider_->WriteEvent(
318 name, TlmEventDescriptor(0, keyword),
319 TlmMbcsStringField("Phase", phase_string),
320 TlmInt64Field("Timestamp", timestamp_ms),
321 TlmMbcsStringField((args->names()[0]), (arg_values_string[0].c_str())));
322 } else if (num_args == 2) {
323 instance->etw_provider_->WriteEvent(
324 name, TlmEventDescriptor(0, keyword),
325 TlmMbcsStringField("Phase", phase_string),
326 TlmInt64Field("Timestamp", timestamp_ms),
327 TlmMbcsStringField((args->names()[0]), (arg_values_string[0].c_str())),
328 TlmMbcsStringField((args->names()[1]), (arg_values_string[1].c_str())));
329 } else {
330 NOTREACHED();
331 }
332 }
333
334 // static
AddCompleteEndEvent(const unsigned char * category_group_enabled,const char * name)335 void TraceEventETWExport::AddCompleteEndEvent(
336 const unsigned char* category_group_enabled,
337 const char* name) {
338 auto* instance = GetInstance();
339 if (!instance) {
340 return;
341 }
342 uint64_t keyword =
343 instance->CategoryStateToETWKeyword(category_group_enabled);
344 if (!instance->etw_provider_->IsEnabled(TRACE_LEVEL_NONE, keyword)) {
345 return;
346 }
347
348 // Log the event and include the info needed to decode it via TraceLogging
349 instance->etw_provider_->WriteEvent(
350 name, TlmEventDescriptor(0, keyword),
351 TlmMbcsStringField("Phase", "Complete End"));
352 }
353
354 // static
IsCategoryGroupEnabled(std::string_view category_group_name)355 bool TraceEventETWExport::IsCategoryGroupEnabled(
356 std::string_view category_group_name) {
357 DCHECK(!category_group_name.empty());
358
359 auto* instance = GetInstanceIfExists();
360 if (instance == nullptr)
361 return false;
362
363 if (!instance->etw_provider_->IsEnabled())
364 return false;
365
366 StringViewTokenizer category_group_tokens(category_group_name.begin(),
367 category_group_name.end(), ",");
368 while (category_group_tokens.GetNext()) {
369 std::string_view category_group_token = category_group_tokens.token_piece();
370 if (instance->IsCategoryEnabled(category_group_token)) {
371 return true;
372 }
373 }
374 return false;
375 }
376
UpdateEnabledCategories()377 bool TraceEventETWExport::UpdateEnabledCategories() {
378 if (etw_match_any_keyword_ ==
379 (etw_provider_->keyword_any() & kCategoryKeywordMask)) {
380 return false;
381 }
382
383 // If keyword_any() has changed, update each category. The global
384 // context is set by UIforETW (or other ETW trace recording tools)
385 // using the ETW infrastructure. When the global context changes the
386 // callback will be called to set the updated keyword bits in each
387 // process that has registered their ETW provider.
388 etw_match_any_keyword_ = etw_provider_->keyword_any() & kCategoryKeywordMask;
389 for (size_t i = 0; i < std::size(kFilteredEventGroupNames); i++) {
390 if (etw_match_any_keyword_ & (1ULL << i)) {
391 categories_status_[kFilteredEventGroupNames[i]] = true;
392 } else {
393 categories_status_[kFilteredEventGroupNames[i]] = false;
394 }
395 }
396
397 // Update the categories in TraceLog.
398 TraceLog::GetInstance()->UpdateETWCategoryGroupEnabledFlags();
399
400 return true;
401 }
402
IsCategoryEnabled(std::string_view category_name) const403 bool TraceEventETWExport::IsCategoryEnabled(
404 std::string_view category_name) const {
405 // Try to find the category and return its status if found
406 auto it = categories_status_.find(category_name);
407 if (it != categories_status_.end())
408 return it->second;
409
410 // Otherwise return the corresponding default status by first checking if the
411 // category is disabled by default.
412 if (StartsWith(category_name, "disabled-by-default")) {
413 DCHECK(categories_status_.find(
414 kFilteredEventGroupNames[kDisabledOtherEventsGroupNameIndex]) !=
415 categories_status_.end());
416 return categories_status_
417 .find(kFilteredEventGroupNames[kDisabledOtherEventsGroupNameIndex])
418 ->second;
419 } else {
420 DCHECK(categories_status_.find(
421 kFilteredEventGroupNames[kOtherEventsGroupNameIndex]) !=
422 categories_status_.end());
423 return categories_status_
424 .find(kFilteredEventGroupNames[kOtherEventsGroupNameIndex])
425 ->second;
426 }
427 }
428
CategoryStateToETWKeyword(const uint8_t * category_state)429 uint64_t TraceEventETWExport::CategoryStateToETWKeyword(
430 const uint8_t* category_state) {
431 const TraceCategory* category = TraceCategory::FromStatePtr(category_state);
432 uint64_t keyword = CategoryGroupToETWKeyword(category->name());
433 return keyword;
434 }
435
OnETWEnableUpdate(TlmProvider::EventControlCode enabled)436 void TraceEventETWExport::OnETWEnableUpdate(
437 TlmProvider::EventControlCode enabled) {
438 // During construction, if tracing is already enabled, we'll get
439 // a callback synchronously on the same thread. Calling GetInstance
440 // in that case will hang since we're in the process of creating the
441 // singleton.
442 if (is_registration_complete_) {
443 UpdateEnabledCategories();
444 }
445 }
446
447 // static
GetInstance()448 TraceEventETWExport* TraceEventETWExport::GetInstance() {
449 return Singleton<TraceEventETWExport,
450 StaticMemorySingletonTraits<TraceEventETWExport>>::get();
451 }
452
453 // static
GetInstanceIfExists()454 TraceEventETWExport* TraceEventETWExport::GetInstanceIfExists() {
455 return Singleton<
456 TraceEventETWExport,
457 StaticMemorySingletonTraits<TraceEventETWExport>>::GetIfExists();
458 }
459
CategoryGroupToETWKeyword(std::string_view category_group_name)460 uint64_t CategoryGroupToETWKeyword(std::string_view category_group_name) {
461 static NoDestructor<base::flat_map<std::string_view, uint64_t>>
462 categories_to_keyword([]() {
463 std::vector<std::pair<std::string_view, uint64_t>> items;
464 for (size_t i = 0; i < kOtherEventsGroupNameIndex; i++) {
465 uint64_t keyword = 1ULL << i;
466 items.emplace_back(kFilteredEventGroupNames[i], keyword);
467 }
468 std::sort(items.begin(), items.end());
469 return base::flat_map<std::string_view, uint64_t>(base::sorted_unique,
470 std::move(items));
471 }());
472
473 uint64_t keyword = 0;
474
475 // To enable multiple sessions with this provider enabled we need to log the
476 // level and keyword with the event so that if the sessions differ in the
477 // level or keywords enabled we log the right events and allow ETW to
478 // route the data to the appropriate session.
479 // TODO([email protected]) Explore better methods in future integration
480 // with perfetto.
481
482 StringViewTokenizer category_group_tokens(category_group_name.begin(),
483 category_group_name.end(), ",");
484 while (category_group_tokens.GetNext()) {
485 std::string_view category_group_token = category_group_tokens.token_piece();
486
487 // Lookup the keyword for this part of the category_group_name
488 // and or in the keyword.
489 auto it = categories_to_keyword->find(category_group_token);
490 if (it != categories_to_keyword->end()) {
491 keyword |= it->second;
492 } else {
493 if (StartsWith(category_group_token, "disabled-by-default")) {
494 keyword |= (1ULL << kDisabledOtherEventsGroupNameIndex);
495 } else {
496 keyword |= (1ULL << kOtherEventsGroupNameIndex);
497 }
498 }
499 }
500 return keyword;
501 }
502
503 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
504
ETWKeywordToTrackEventConfig(uint64_t keyword)505 perfetto::protos::gen::TrackEventConfig ETWKeywordToTrackEventConfig(
506 uint64_t keyword) {
507 perfetto::protos::gen::TrackEventConfig track_event_config;
508 for (size_t i = 0; i < kOtherEventsGroupNameIndex; ++i) {
509 if (keyword & (1ULL << i)) {
510 track_event_config.add_enabled_categories(kFilteredEventGroupNames[i]);
511 }
512 }
513 bool other_events_enabled = (keyword & (1ULL << kOtherEventsGroupNameIndex));
514 bool disabled_other_events_enables =
515 (keyword & (1ULL << kDisabledOtherEventsGroupNameIndex));
516 if (other_events_enabled) {
517 track_event_config.add_enabled_categories("*");
518 } else {
519 track_event_config.add_disabled_categories("*");
520 }
521 if (!disabled_other_events_enables) {
522 track_event_config.add_disabled_categories("disabled-by-default-*");
523 } else if (other_events_enabled) {
524 track_event_config.add_enabled_categories("disabled-by-default-*");
525 }
526 return track_event_config;
527 }
528
529 #endif // BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
530
531 } // namespace trace_event
532 } // namespace base
533