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 PlatformThread::Delegate {
 137  public:
 138   ETWKeywordUpdateThread() {}
 139   ~ETWKeywordUpdateThread() override {}
 140
 141   // Implementation of PlatformThread::Delegate:
 142   void ThreadMain() override {
 143     PlatformThread::SetName("ETW Keyword Update Thread");
 144     TimeDelta sleep_time = TimeDelta::FromMilliseconds(kUpdateTimerDelayMs);
 145     while (1) {
 146       PlatformThread::Sleep(sleep_time);
 147       trace_event::TraceEventETWExport::UpdateETWKeyword();
 148     }
 149   }
 150
 151  private:
 152   // Time between checks for ETW keyword changes (in milliseconds).
 153   unsigned int kUpdateTimerDelayMs = 1000;
 154 };
 155
 156
 157 TraceEventETWExport::TraceEventETWExport()
 158     : etw_export_enabled_(false), etw_match_any_keyword_(0ULL) {
 159   // Find Advapi32.dll. This should always succeed.
 160   HMODULE AdvapiDLL = ::LoadLibraryW(L"Advapi32.dll");
 161   if (AdvapiDLL) {
 162     // Try to find the ETW functions. This will fail on XP.
 163     EventRegisterProc = reinterpret_cast<tEventRegister>(
 164         ::GetProcAddress(AdvapiDLL, "EventRegister"));
 165     EventWriteProc = reinterpret_cast<tEventWrite>(
 166         ::GetProcAddress(AdvapiDLL, "EventWrite"));
 167     EventUnregisterProc = reinterpret_cast<tEventUnregister>(
 168         ::GetProcAddress(AdvapiDLL, "EventUnregister"));
 169
 170     // Register the ETW provider. If registration fails then the event logging
 171     // calls will fail (on XP this call will do nothing).
 172     EventRegisterChrome();
 173   }
 174
 175   // Make sure to initialize the map with all the group names. Subsequent
 176   // modifications will be made by the background thread and only affect the
 177   // values of the keys (no key addition/deletion). Therefore, the map does not
 178   // require a lock for access.
 179   for (int i = 0; i < ARRAYSIZE(kFilteredEventGroupNames); i++)
 180     categories_status_[kFilteredEventGroupNames[i]] = false;
 181   categories_status_[kOtherEventsGroupName] = false;
 182   categories_status_[kDisabledOtherEventsGroupName] = false;
 183   DCHECK_EQ(kNumberOfCategories, categories_status_.size());
 184 }
 185
 186 TraceEventETWExport::~TraceEventETWExport() {
 187   EventUnregisterChrome();
 188 }
 189
 190 // static
 191 TraceEventETWExport* TraceEventETWExport::GetInstance() {
 192   return Singleton<TraceEventETWExport,
 193                    StaticMemorySingletonTraits<TraceEventETWExport>>::get();
 194 }
 195
 196 // static
 197 void TraceEventETWExport::EnableETWExport() {
 198   auto* instance = GetInstance();
 199   if (instance && !instance->etw_export_enabled_) {
 200     instance->etw_export_enabled_ = true;
 201     // Sync the enabled categories with ETW by calling UpdateEnabledCategories()
 202     // that checks the keyword. Then create a thread that will call that same
 203     // function periodically, to make sure we stay in sync.
 204     instance->UpdateEnabledCategories();
 205     if (instance->keyword_update_thread_handle_.is_null()) {
 206       instance->keyword_update_thread_.reset(new ETWKeywordUpdateThread);
 207       PlatformThread::CreateWithPriority(
 208           0, instance->keyword_update_thread_.get(),
 209           &instance->keyword_update_thread_handle_, ThreadPriority::BACKGROUND);
 210     }
 211   }
 212 }
 213
 214 // static
 215 void TraceEventETWExport::DisableETWExport() {
 216   auto* instance = GetInstance();
 217   if (instance && instance->etw_export_enabled_)
 218     instance->etw_export_enabled_ = false;
 219 }
 220
 221 // static
 222 bool TraceEventETWExport::IsETWExportEnabled() {
 223   auto* instance = GetInstance();
 224   return (instance && instance->etw_export_enabled_);
 225 }
 226
 227 // static
 228 void TraceEventETWExport::AddEvent(
 229     char phase,
 230     const unsigned char* category_group_enabled,
 231     const char* name,
 232     unsigned long long id,
 233     int num_args,
 234     const char** arg_names,
 235     const unsigned char* arg_types,
 236     const unsigned long long* arg_values,
 237     const scoped_refptr<ConvertableToTraceFormat>* convertable_values) {
 238   // We bail early in case exporting is disabled or no consumer is listening.
 239   auto* instance = GetInstance();
 240   if (!instance || !instance->etw_export_enabled_ || !EventEnabledChromeEvent())
 241     return;
 242
 243   const char* phase_string = nullptr;
 244   // Space to store the phase identifier and null-terminator, when needed.
 245   char phase_buffer[2];
 246   switch (phase) {
 247     case TRACE_EVENT_PHASE_BEGIN:
 248       phase_string = "Begin";
 249       break;
 250     case TRACE_EVENT_PHASE_END:
 251       phase_string = "End";
 252       break;
 253     case TRACE_EVENT_PHASE_COMPLETE:
 254       phase_string = "Complete";
 255       break;
 256     case TRACE_EVENT_PHASE_INSTANT:
 257       phase_string = "Instant";
 258       break;
 259     case TRACE_EVENT_PHASE_ASYNC_BEGIN:
 260       phase_string = "Async Begin";
 261       break;
 262     case TRACE_EVENT_PHASE_ASYNC_STEP_INTO:
 263       phase_string = "Async Step Into";
 264       break;
 265     case TRACE_EVENT_PHASE_ASYNC_STEP_PAST:
 266       phase_string = "Async Step Past";
 267       break;
 268     case TRACE_EVENT_PHASE_ASYNC_END:
 269       phase_string = "Async End";
 270       break;
 271     case TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN:
 272       phase_string = "Nestable Async Begin";
 273       break;
 274     case TRACE_EVENT_PHASE_NESTABLE_ASYNC_END:
 275       phase_string = "Nestable Async End";
 276       break;
 277     case TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT:
 278       phase_string = "Nestable Async Instant";
 279       break;
 280     case TRACE_EVENT_PHASE_FLOW_BEGIN:
 281       phase_string = "Phase Flow Begin";
 282       break;
 283     case TRACE_EVENT_PHASE_FLOW_STEP:
 284       phase_string = "Phase Flow Step";
 285       break;
 286     case TRACE_EVENT_PHASE_FLOW_END:
 287       phase_string = "Phase Flow End";
 288       break;
 289     case TRACE_EVENT_PHASE_METADATA:
 290       phase_string = "Phase Metadata";
 291       break;
 292     case TRACE_EVENT_PHASE_COUNTER:
 293       phase_string = "Phase Counter";
 294       break;
 295     case TRACE_EVENT_PHASE_SAMPLE:
 296       phase_string = "Phase Sample";
 297       break;
 298     case TRACE_EVENT_PHASE_CREATE_OBJECT:
 299       phase_string = "Phase Create Object";
 300       break;
 301     case TRACE_EVENT_PHASE_SNAPSHOT_OBJECT:
 302       phase_string = "Phase Snapshot Object";
 303       break;
 304     case TRACE_EVENT_PHASE_DELETE_OBJECT:
 305       phase_string = "Phase Delete Object";
 306       break;
 307     default:
 308       phase_buffer[0] = phase;
 309       phase_buffer[1] = 0;
 310       phase_string = phase_buffer;
 311       break;
 312   }
 313
 314   std::string arg_values_string[3];
 315   for (int i = 0; i < num_args; i++) {
 316     if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
 317       // Temporarily do nothing here. This function consumes 1/3 to 1/2 of
 318       // *total* process CPU time when ETW tracing, and many of the strings
 319       // created exceed WPA's 4094 byte limit and are shown as:
 320       // "Unable to parse data". See crbug.com/488257
 321       // convertable_values[i]->AppendAsTraceFormat(arg_values_string + i);
 322     } else {
 323       TraceEvent::TraceValue trace_event;
 324       trace_event.as_uint = arg_values[i];
 325       TraceEvent::AppendValueAsJSON(arg_types[i], trace_event,
 326                                     arg_values_string + i);
 327     }
 328   }
 329
 330   EventWriteChromeEvent(
 331       name, phase_string, num_args > 0 ? arg_names[0] : "",
 332       arg_values_string[0].c_str(), num_args > 1 ? arg_names[1] : "",
 333       arg_values_string[1].c_str(), num_args > 2 ? arg_names[2] : "",
 334       arg_values_string[2].c_str());
 335 }
 336
 337 // static
 338 void TraceEventETWExport::AddCustomEvent(const char* name,
 339                                          char const* phase,
 340                                          const char* arg_name_1,
 341                                          const char* arg_value_1,
 342                                          const char* arg_name_2,
 343                                          const char* arg_value_2,
 344                                          const char* arg_name_3,
 345                                          const char* arg_value_3) {
 346   auto* instance = GetInstance();
 347   if (!instance || !instance->etw_export_enabled_ || !EventEnabledChromeEvent())
 348     return;
 349
 350   EventWriteChromeEvent(name, phase, arg_name_1, arg_value_1, arg_name_2,
 351                         arg_value_2, arg_name_3, arg_value_3);
 352 }
 353
 354 // static
 355 bool TraceEventETWExport::IsCategoryGroupEnabled(
 356     const char* category_group_name) {
 357   DCHECK(category_group_name);
 358   auto* instance = GetInstance();
 359   if (instance == nullptr)
 360     return false;
 361
 362   if (!instance->IsETWExportEnabled())
 363     return false;
 364
 365   CStringTokenizer category_group_tokens(
 366       category_group_name, category_group_name + strlen(category_group_name),
 367       ",");
 368   while (category_group_tokens.GetNext()) {
 369     std::string category_group_token = category_group_tokens.token();
 370     if (instance->IsCategoryEnabled(category_group_token.c_str())) {
 371       return true;
 372     }
 373   }
 374   return false;
 375 }
 376
 377 bool TraceEventETWExport::UpdateEnabledCategories() {
 378   if (etw_match_any_keyword_ == CHROME_Context.MatchAnyKeyword)
 379     return false;
 380
 381   // If the keyword has changed, update each category.
 382   // Chrome_Context.MatchAnyKeyword is set by UIforETW (or other ETW trace
 383   // recording tools) using the ETW infrastructure. This value will be set in
 384   // all Chrome processes that have registered their ETW provider.
 385   etw_match_any_keyword_ = CHROME_Context.MatchAnyKeyword;
 386   for (int i = 0; i < ARRAYSIZE(kFilteredEventGroupNames); i++) {
 387     if (etw_match_any_keyword_ & (1ULL << i)) {
 388       categories_status_[kFilteredEventGroupNames[i]] = true;
 389     } else {
 390       categories_status_[kFilteredEventGroupNames[i]] = false;
 391     }
 392   }
 393
 394   // Also update the two default categories.
 395   if (etw_match_any_keyword_ & kOtherEventsKeywordBit) {
 396     categories_status_[kOtherEventsGroupName] = true;
 397   } else {
 398     categories_status_[kOtherEventsGroupName] = false;
 399   }
 400   if (etw_match_any_keyword_ & kDisabledOtherEventsKeywordBit) {
 401     categories_status_[kDisabledOtherEventsGroupName] = true;
 402   } else {
 403     categories_status_[kDisabledOtherEventsGroupName] = false;
 404   }
 405
 406   DCHECK_EQ(kNumberOfCategories, categories_status_.size());
 407
 408   // Update the categories in TraceLog.
 409   TraceLog::GetInstance()->UpdateETWCategoryGroupEnabledFlags();
 410
 411   return true;
 412 }
 413
 414 bool TraceEventETWExport::IsCategoryEnabled(const char* category_name) const {
 415   DCHECK_EQ(kNumberOfCategories, categories_status_.size());
 416   // Try to find the category and return its status if found
 417   auto it = categories_status_.find(category_name);
 418   if (it != categories_status_.end())
 419     return it->second;
 420
 421   // Otherwise return the corresponding default status by first checking if the
 422   // category is disabled by default.
 423   if (StringPiece(category_name).starts_with("disabled-by-default")) {
 424     DCHECK(categories_status_.find(kDisabledOtherEventsGroupName) !=
 425            categories_status_.end());
 426     return categories_status_.find(kDisabledOtherEventsGroupName)->second;
 427   } else {
 428     DCHECK(categories_status_.find(kOtherEventsGroupName) !=
 429            categories_status_.end());
 430     return categories_status_.find(kOtherEventsGroupName)->second;
 431   }
 432 }
 433
 434 // static
 435 void TraceEventETWExport::UpdateETWKeyword() {
 436   if (!IsETWExportEnabled())
 437     return;
 438   auto* instance = GetInstance();
 439   DCHECK(instance);
 440   instance->UpdateEnabledCategories();
 441 }
 442 }  // namespace trace_event
 443 }  // namespace base