trace_event_etw_export_win.cc 20 KB

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