base/trace_event/trace_event_etw_export_win.cc

   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
   5 #include "base/trace_event/trace_event_etw_export_win.h"
   6
   7 #include "base/command_line.h"
   8 #include "base/logging.h"
   9 #include "base/memory/singleton.h"
  10 #include "base/strings/string_tokenizer.h"
  11 #include "base/strings/utf_string_conversions.h"
  12 #include "base/threading/platform_thread.h"
  13 #include "base/trace_event/trace_event.h"
  14 #include "base/trace_event/trace_event_impl.h"
  15
  16 // The GetProcAddress technique is borrowed from
  17 // https://github.com/google/UIforETW/tree/master/ETWProviders
  18 //
  19 // EVNTAPI is used in evntprov.h which is included by chrome_events_win.h.
  20 // We define EVNTAPI without the DECLSPEC_IMPORT specifier so that we can
  21 // implement these functions locally instead of using the import library, and
  22 // can therefore still run on Windows XP.
  23 #define EVNTAPI __stdcall
  24 // Include the event register/write/unregister macros compiled from the manifest
  25 // file. Note that this includes evntprov.h which requires a Vista+ Windows SDK.
  26 //
  27 // In SHARED_INTERMEDIATE_DIR.
  28 #include "base/trace_event/etw_manifest/chrome_events_win.h"  // NOLINT
  29
  30 namespace {
  31 // Typedefs for use with GetProcAddress
  32 typedef ULONG(__stdcall* tEventRegister)(LPCGUID ProviderId,
  33                                          PENABLECALLBACK EnableCallback,
  34                                          PVOID CallbackContext,
  35                                          PREGHANDLE RegHandle);
  36 typedef ULONG(__stdcall* tEventWrite)(REGHANDLE RegHandle,
  37                                       PCEVENT_DESCRIPTOR EventDescriptor,
  38                                       ULONG UserDataCount,
  39                                       PEVENT_DATA_DESCRIPTOR UserData);
  40 typedef ULONG(__stdcall* tEventUnregister)(REGHANDLE RegHandle);
  41
  42 tEventRegister EventRegisterProc = nullptr;
  43 tEventWrite EventWriteProc = nullptr;
  44 tEventUnregister EventUnregisterProc = nullptr;
  45
  46 // |kFilteredEventGroupNames| contains the event categories that can be
  47 // exported individually. These categories can be enabled by passing the correct
  48 // keyword when starting the trace. A keyword is a 64-bit flag and we attribute
  49 // one bit per category. We can therefore enable a particular category by
  50 // setting its corresponding bit in the keyword. For events that are not present
  51 // in |kFilteredEventGroupNames|, we have two bits that control their
  52 // behaviour. When bit 61 is enabled, any event that is not disabled by default
  53 // (ie. doesn't start with disabled-by-default-) will be exported. Likewise,
  54 // when bit 62 is enabled, any event that is disabled by default will be
  55 // exported.
  56 //
  57 // Note that bit 63 (MSB) must always be set, otherwise tracing will be disabled
  58 // by ETW. Therefore, the keyword will always be greater than
  59 // 0x8000000000000000.
  60 //
  61 // Examples of passing keywords to the provider using xperf:
  62 // # This exports "benchmark" and "cc" events
  63 // xperf -start chrome -on Chrome:0x8000000000000009
  64 //
  65 // # This exports "gpu", "netlog" and all other events that are not disabled by
  66 // # default
  67 // xperf -start chrome -on Chrome:0xA0000000000000A0
  68 //
  69 // More info about starting a trace and keyword can be obtained by using the
  70 // help section of xperf (xperf -help start). Note that xperf documentation
  71 // refers to keywords as flags and there are two ways to enable them, using
  72 // group names or the hex representation. We only support the latter. Also, we
  73 // ignore the level.
  74 const char* const kFilteredEventGroupNames[] = {
  75     "benchmark",                                       // 0x1
  76     "blink",                                           // 0x2
  77     "browser",                                         // 0x4
  78     "cc",                                              // 0x8
  79     "evdev",                                           // 0x10
  80     "gpu",                                             // 0x20
  81     "input",                                           // 0x40
  82     "netlog",                                          // 0x80
  83     "renderer.scheduler",                              // 0x100
  84     "toplevel",                                        // 0x200
  85     "v8",                                              // 0x400
  86     "disabled-by-default-cc.debug",                    // 0x800
  87     "disabled-by-default-cc.debug.picture",            // 0x1000
  88     "disabled-by-default-toplevel.flow"};              // 0x2000
  89 const char kOtherEventsGroupName[] = "__OTHER_EVENTS";  // 0x2000000000000000
  90 const char kDisabledOtherEventsGroupName[] =
  91     "__DISABLED_OTHER_EVENTS";  // 0x4000000000000000
  92 const uint64 kOtherEventsKeywordBit = 1ULL << 61;
  93 const uint64 kDisabledOtherEventsKeywordBit = 1ULL << 62;
  94 const size_t kNumberOfCategories = ARRAYSIZE(kFilteredEventGroupNames) + 2U;
  95
  96 }  // namespace
  97
  98 // Redirector function for EventRegister. Called by macros in
  99 // chrome_events_win.h
 100 ULONG EVNTAPI EventRegister(LPCGUID ProviderId,
 101                             PENABLECALLBACK EnableCallback,
 102                             PVOID CallbackContext,
 103                             PREGHANDLE RegHandle) {
 104   if (EventRegisterProc)
 105     return EventRegisterProc(ProviderId, EnableCallback, CallbackContext,
 106                              RegHandle);
 107   *RegHandle = 0;
 108   return 0;
 109 }
 110
 111 // Redirector function for EventWrite. Called by macros in
 112 // chrome_events_win.h
 113 ULONG EVNTAPI EventWrite(REGHANDLE RegHandle,
 114                          PCEVENT_DESCRIPTOR EventDescriptor,
 115                          ULONG UserDataCount,
 116                          PEVENT_DATA_DESCRIPTOR UserData) {
 117   if (EventWriteProc)
 118     return EventWriteProc(RegHandle, EventDescriptor, UserDataCount, UserData);
 119   return 0;
 120 }
 121
 122 // Redirector function for EventUnregister. Called by macros in
 123 // chrome_events_win.h
 124 ULONG EVNTAPI EventUnregister(REGHANDLE RegHandle) {
 125   if (EventUnregisterProc)
 126     return EventUnregisterProc(RegHandle);
 127   return 0;
 128 }
 129
 130 namespace base {
 131 namespace trace_event {
 132
 133 // This object will be created by each process. It's a background (low-priority)
 134 // thread that will monitor the ETW keyword for any changes.
 135 class TraceEventETWExport::ETWKeywordUpdateThread
 136     : public base::PlatformThread::Delegate {
 137  public:
 138   ETWKeywordUpdateThread() {}
 139   ~ETWKeywordUpdateThread() override {}
 140
 141   // Implementation of PlatformThread::Delegate:
 142   void ThreadMain() override {
 143     base::PlatformThread::SetName("ETW Keyword Update Thread");
 144     base::TimeDelta sleep_time =
 145         base::TimeDelta::FromMilliseconds(kUpdateTimerDelayMs);
 146     while (1) {
 147       base::PlatformThread::Sleep(sleep_time);
 148       base::trace_event::TraceEventETWExport::UpdateETWKeyword();
 149     }
 150   }
 151
 152  private:
 153   // Time between checks for ETW keyword changes (in milliseconds).
 154   unsigned int kUpdateTimerDelayMs = 1000;
 155 };
 156
 157
 158 TraceEventETWExport::TraceEventETWExport()
 159     : etw_export_enabled_(false), etw_match_any_keyword_(0ULL) {
 160   // Find Advapi32.dll. This should always succeed.
 161   HMODULE AdvapiDLL = ::LoadLibraryW(L"Advapi32.dll");
 162   if (AdvapiDLL) {
 163     // Try to find the ETW functions. This will fail on XP.
 164     EventRegisterProc = reinterpret_cast<tEventRegister>(
 165         ::GetProcAddress(AdvapiDLL, "EventRegister"));
 166     EventWriteProc = reinterpret_cast<tEventWrite>(
 167         ::GetProcAddress(AdvapiDLL, "EventWrite"));
 168     EventUnregisterProc = reinterpret_cast<tEventUnregister>(
 169         ::GetProcAddress(AdvapiDLL, "EventUnregister"));
 170
 171     // Register the ETW provider. If registration fails then the event logging
 172     // calls will fail (on XP this call will do nothing).
 173     EventRegisterChrome();
 174   }
 175
 176   // Make sure to initialize the map with all the group names. Subsequent
 177   // modifications will be made by the background thread and only affect the
 178   // values of the keys (no key addition/deletion). Therefore, the map does not
 179   // require a lock for access.
 180   for (int i = 0; i < ARRAYSIZE(kFilteredEventGroupNames); i++)
 181     categories_status_[kFilteredEventGroupNames[i]] = false;
 182   categories_status_[kOtherEventsGroupName] = false;
 183   categories_status_[kDisabledOtherEventsGroupName] = false;
 184   DCHECK_EQ(kNumberOfCategories, categories_status_.size());
 185 }
 186
 187 TraceEventETWExport::~TraceEventETWExport() {
 188   EventUnregisterChrome();
 189 }
 190
 191 // static
 192 TraceEventETWExport* TraceEventETWExport::GetInstance() {
 193   return Singleton<TraceEventETWExport,
 194                    StaticMemorySingletonTraits<TraceEventETWExport>>::get();
 195 }
 196
 197 // static
 198 void TraceEventETWExport::EnableETWExport() {
 199   auto* instance = GetInstance();
 200   if (instance && !instance->etw_export_enabled_) {
 201     instance->etw_export_enabled_ = true;
 202     // Sync the enabled categories with ETW by calling UpdateEnabledCategories()
 203     // that checks the keyword. Then create a thread that will call that same
 204     // function periodically, to make sure we stay in sync.
 205     instance->UpdateEnabledCategories();
 206     if (instance->keyword_update_thread_handle_.is_null()) {
 207       instance->keyword_update_thread_.reset(new ETWKeywordUpdateThread);
 208       PlatformThread::CreateWithPriority(
 209           0, instance->keyword_update_thread_.get(),
 210           &instance->keyword_update_thread_handle_, ThreadPriority::BACKGROUND);
 211     }
 212   }
 213 }
 214
 215 // static
 216 void TraceEventETWExport::DisableETWExport() {
 217   auto* instance = GetInstance();
 218   if (instance && instance->etw_export_enabled_)
 219     instance->etw_export_enabled_ = false;
 220 }
 221
 222 // static
 223 bool TraceEventETWExport::IsETWExportEnabled() {
 224   auto* instance = GetInstance();
 225   return (instance && instance->etw_export_enabled_);
 226 }
 227
 228 // static
 229 void TraceEventETWExport::AddEvent(
 230     char phase,
 231     const unsigned char* category_group_enabled,
 232     const char* name,
 233     unsigned long long id,
 234     int num_args,
 235     const char** arg_names,
 236     const unsigned char* arg_types,
 237     const unsigned long long* arg_values,
 238     const scoped_refptr<ConvertableToTraceFormat>* convertable_values) {
 239   // We bail early in case exporting is disabled or no consumer is listening.
 240   auto* instance = GetInstance();
 241   if (!instance || !instance->etw_export_enabled_ || !EventEnabledChromeEvent())
 242     return;
 243
 244   const char* phase_string = nullptr;
 245   // Space to store the phase identifier and null-terminator, when needed.
 246   char phase_buffer[2];
 247   switch (phase) {
 248     case TRACE_EVENT_PHASE_BEGIN:
 249       phase_string = "Begin";
 250       break;
 251     case TRACE_EVENT_PHASE_END:
 252       phase_string = "End";
 253       break;
 254     case TRACE_EVENT_PHASE_COMPLETE:
 255       phase_string = "Complete";
 256       break;
 257     case TRACE_EVENT_PHASE_INSTANT:
 258       phase_string = "Instant";
 259       break;
 260     case TRACE_EVENT_PHASE_ASYNC_BEGIN:
 261       phase_string = "Async Begin";
 262       break;
 263     case TRACE_EVENT_PHASE_ASYNC_STEP_INTO:
 264       phase_string = "Async Step Into";
 265       break;
 266     case TRACE_EVENT_PHASE_ASYNC_STEP_PAST:
 267       phase_string = "Async Step Past";
 268       break;
 269     case TRACE_EVENT_PHASE_ASYNC_END:
 270       phase_string = "Async End";
 271       break;
 272     case TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN:
 273       phase_string = "Nestable Async Begin";
 274       break;
 275     case TRACE_EVENT_PHASE_NESTABLE_ASYNC_END:
 276       phase_string = "Nestable Async End";
 277       break;
 278     case TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT:
 279       phase_string = "Nestable Async Instant";
 280       break;
 281     case TRACE_EVENT_PHASE_FLOW_BEGIN:
 282       phase_string = "Phase Flow Begin";
 283       break;
 284     case TRACE_EVENT_PHASE_FLOW_STEP:
 285       phase_string = "Phase Flow Step";
 286       break;
 287     case TRACE_EVENT_PHASE_FLOW_END:
 288       phase_string = "Phase Flow End";
 289       break;
 290     case TRACE_EVENT_PHASE_METADATA:
 291       phase_string = "Phase Metadata";
 292       break;
 293     case TRACE_EVENT_PHASE_COUNTER:
 294       phase_string = "Phase Counter";
 295       break;
 296     case TRACE_EVENT_PHASE_SAMPLE:
 297       phase_string = "Phase Sample";
 298       break;
 299     case TRACE_EVENT_PHASE_CREATE_OBJECT:
 300       phase_string = "Phase Create Object";
 301       break;
 302     case TRACE_EVENT_PHASE_SNAPSHOT_OBJECT:
 303       phase_string = "Phase Snapshot Object";
 304       break;
 305     case TRACE_EVENT_PHASE_DELETE_OBJECT:
 306       phase_string = "Phase Delete Object";
 307       break;
 308     default:
 309       phase_buffer[0] = phase;
 310       phase_buffer[1] = 0;
 311       phase_string = phase_buffer;
 312       break;
 313   }
 314
 315   std::string arg_values_string[3];
 316   for (int i = 0; i < num_args; i++) {
 317     if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
 318       // Temporarily do nothing here. This function consumes 1/3 to 1/2 of
 319       // *total* process CPU time when ETW tracing, and many of the strings
 320       // created exceed WPA's 4094 byte limit and are shown as:
 321       // "Unable to parse data". See crbug.com/488257
 322       // convertable_values[i]->AppendAsTraceFormat(arg_values_string + i);
 323     } else {
 324       TraceEvent::TraceValue trace_event;
 325       trace_event.as_uint = arg_values[i];
 326       TraceEvent::AppendValueAsJSON(arg_types[i], trace_event,
 327                                     arg_values_string + i);
 328     }
 329   }
 330
 331   EventWriteChromeEvent(
 332       name, phase_string, num_args > 0 ? arg_names[0] : "",
 333       arg_values_string[0].c_str(), num_args > 1 ? arg_names[1] : "",
 334       arg_values_string[1].c_str(), num_args > 2 ? arg_names[2] : "",
 335       arg_values_string[2].c_str());
 336 }
 337
 338 // static
 339 void TraceEventETWExport::AddCustomEvent(const char* name,
 340                                          char const* phase,
 341                                          const char* arg_name_1,
 342                                          const char* arg_value_1,
 343                                          const char* arg_name_2,
 344                                          const char* arg_value_2,
 345                                          const char* arg_name_3,
 346                                          const char* arg_value_3) {
 347   auto* instance = GetInstance();
 348   if (!instance || !instance->etw_export_enabled_ || !EventEnabledChromeEvent())
 349     return;
 350
 351   EventWriteChromeEvent(name, phase, arg_name_1, arg_value_1, arg_name_2,
 352                         arg_value_2, arg_name_3, arg_value_3);
 353 }
 354
 355 // static
 356 bool TraceEventETWExport::IsCategoryGroupEnabled(
 357     const char* category_group_name) {
 358   DCHECK(category_group_name);
 359   auto* instance = GetInstance();
 360   if (instance == nullptr)
 361     return false;
 362
 363   if (!instance->IsETWExportEnabled())
 364     return false;
 365
 366   CStringTokenizer category_group_tokens(
 367       category_group_name, category_group_name + strlen(category_group_name),
 368       ",");
 369   while (category_group_tokens.GetNext()) {
 370     std::string category_group_token = category_group_tokens.token();
 371     if (instance->IsCategoryEnabled(category_group_token.c_str())) {
 372       return true;
 373     }
 374   }
 375   return false;
 376 }
 377
 378 bool TraceEventETWExport::UpdateEnabledCategories() {
 379   if (etw_match_any_keyword_ == CHROME_Context.MatchAnyKeyword)
 380     return false;
 381
 382   // If the keyword has changed, update each category.
 383   // Chrome_Context.MatchAnyKeyword is set by UIforETW (or other ETW trace
 384   // recording tools) using the ETW infrastructure. This value will be set in
 385   // all Chrome processes that have registered their ETW provider.
 386   etw_match_any_keyword_ = CHROME_Context.MatchAnyKeyword;
 387   for (int i = 0; i < ARRAYSIZE(kFilteredEventGroupNames); i++) {
 388     if (etw_match_any_keyword_ & (1ULL << i)) {
 389       categories_status_[kFilteredEventGroupNames[i]] = true;
 390     } else {
 391       categories_status_[kFilteredEventGroupNames[i]] = false;
 392     }
 393   }
 394
 395   // Also update the two default categories.
 396   if (etw_match_any_keyword_ & kOtherEventsKeywordBit) {
 397     categories_status_[kOtherEventsGroupName] = true;
 398   } else {
 399     categories_status_[kOtherEventsGroupName] = false;
 400   }
 401   if (etw_match_any_keyword_ & kDisabledOtherEventsKeywordBit) {
 402     categories_status_[kDisabledOtherEventsGroupName] = true;
 403   } else {
 404     categories_status_[kDisabledOtherEventsGroupName] = false;
 405   }
 406
 407   DCHECK_EQ(kNumberOfCategories, categories_status_.size());
 408
 409   // Update the categories in TraceLog.
 410   TraceLog::GetInstance()->UpdateETWCategoryGroupEnabledFlags();
 411
 412   return true;
 413 }
 414
 415 bool TraceEventETWExport::IsCategoryEnabled(const char* category_name) const {
 416   DCHECK_EQ(kNumberOfCategories, categories_status_.size());
 417   // Try to find the category and return its status if found
 418   auto it = categories_status_.find(category_name);
 419   if (it != categories_status_.end())
 420     return it->second;
 421
 422   // Otherwise return the corresponding default status by first checking if the
 423   // category is disabled by default.
 424   if (StringPiece(category_name).starts_with("disabled-by-default")) {
 425     DCHECK(categories_status_.find(kDisabledOtherEventsGroupName) !=
 426            categories_status_.end());
 427     return categories_status_.find(kDisabledOtherEventsGroupName)->second;
 428   } else {
 429     DCHECK(categories_status_.find(kOtherEventsGroupName) !=
 430            categories_status_.end());
 431     return categories_status_.find(kOtherEventsGroupName)->second;
 432   }
 433 }
 434
 435 // static
 436 void TraceEventETWExport::UpdateETWKeyword() {
 437   if (!IsETWExportEnabled())
 438     return;
 439   auto* instance = GetInstance();
 440   DCHECK(instance);
 441   instance->UpdateEnabledCategories();
 442 }
 443 }  // namespace trace_event
 444 }  // namespace base