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
  95 }  // namespace
  96
  97 // Redirector function for EventRegister. Called by macros in
  98 // chrome_events_win.h
  99 ULONG EVNTAPI EventRegister(LPCGUID ProviderId,
 100                             PENABLECALLBACK EnableCallback,
 101                             PVOID CallbackContext,
 102                             PREGHANDLE RegHandle) {
 103   if (EventRegisterProc)
 104     return EventRegisterProc(ProviderId, EnableCallback, CallbackContext,
 105                              RegHandle);
 106   *RegHandle = 0;
 107   return 0;
 108 }
 109
 110 // Redirector function for EventWrite. Called by macros in
 111 // chrome_events_win.h
 112 ULONG EVNTAPI EventWrite(REGHANDLE RegHandle,
 113                          PCEVENT_DESCRIPTOR EventDescriptor,
 114                          ULONG UserDataCount,
 115                          PEVENT_DATA_DESCRIPTOR UserData) {
 116   if (EventWriteProc)
 117     return EventWriteProc(RegHandle, EventDescriptor, UserDataCount, UserData);
 118   return 0;
 119 }
 120
 121 // Redirector function for EventUnregister. Called by macros in
 122 // chrome_events_win.h
 123 ULONG EVNTAPI EventUnregister(REGHANDLE RegHandle) {
 124   if (EventUnregisterProc)
 125     return EventUnregisterProc(RegHandle);
 126   return 0;
 127 }
 128
 129 namespace base {
 130 namespace trace_event {
 131
 132 // This object will be created by each process. It's a background (low-priority)
 133 // thread that will monitor the ETW keyword for any changes.
 134 class TraceEventETWExport::ETWKeywordUpdateThread
 135     : public base::PlatformThread::Delegate {
 136  public:
 137   ETWKeywordUpdateThread() {}
 138   ~ETWKeywordUpdateThread() override {}
 139
 140   // Implementation of PlatformThread::Delegate:
 141   void ThreadMain() override {
 142     base::PlatformThread::SetName("ETW Keyword Update Thread");
 143     base::TimeDelta sleep_time =
 144         base::TimeDelta::FromMilliseconds(kUpdateTimerDelayMs);
 145     while (1) {
 146       base::PlatformThread::Sleep(sleep_time);
 147       base::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
 176 TraceEventETWExport::~TraceEventETWExport() {
 177   EventUnregisterChrome();
 178 }
 179
 180 // static
 181 TraceEventETWExport* TraceEventETWExport::GetInstance() {
 182   return Singleton<TraceEventETWExport,
 183                    StaticMemorySingletonTraits<TraceEventETWExport>>::get();
 184 }
 185
 186 // static
 187 void TraceEventETWExport::EnableETWExport() {
 188   auto* instance = GetInstance();
 189   if (instance && !instance->etw_export_enabled_) {
 190     instance->etw_export_enabled_ = true;
 191     // Sync the enabled categories with ETW by calling UpdateEnabledCategories()
 192     // that checks the keyword. Then create a thread that will call that same
 193     // function periodically, to make sure we stay in sync.
 194     instance->UpdateEnabledCategories();
 195     if (instance->keyword_update_thread_handle_.is_null()) {
 196       instance->keyword_update_thread_.reset(new ETWKeywordUpdateThread);
 197       PlatformThread::CreateWithPriority(
 198           0, instance->keyword_update_thread_.get(),
 199           &instance->keyword_update_thread_handle_, ThreadPriority::BACKGROUND);
 200     }
 201   }
 202 }
 203
 204 // static
 205 void TraceEventETWExport::DisableETWExport() {
 206   auto* instance = GetInstance();
 207   if (instance && instance->etw_export_enabled_)
 208     instance->etw_export_enabled_ = false;
 209 }
 210
 211 // static
 212 bool TraceEventETWExport::IsETWExportEnabled() {
 213   auto* instance = GetInstance();
 214   return (instance && instance->etw_export_enabled_);
 215 }
 216
 217 // static
 218 void TraceEventETWExport::AddEvent(
 219     char phase,
 220     const unsigned char* category_group_enabled,
 221     const char* name,
 222     unsigned long long id,
 223     int num_args,
 224     const char** arg_names,
 225     const unsigned char* arg_types,
 226     const unsigned long long* arg_values,
 227     const scoped_refptr<ConvertableToTraceFormat>* convertable_values) {
 228   // We bail early in case exporting is disabled or no consumer is listening.
 229   auto* instance = GetInstance();
 230   if (!instance || !instance->etw_export_enabled_ || !EventEnabledChromeEvent())
 231     return;
 232
 233   const char* phase_string = nullptr;
 234   // Space to store the phase identifier and null-terminator, when needed.
 235   char phase_buffer[2];
 236   switch (phase) {
 237     case TRACE_EVENT_PHASE_BEGIN:
 238       phase_string = "Begin";
 239       break;
 240     case TRACE_EVENT_PHASE_END:
 241       phase_string = "End";
 242       break;
 243     case TRACE_EVENT_PHASE_COMPLETE:
 244       phase_string = "Complete";
 245       break;
 246     case TRACE_EVENT_PHASE_INSTANT:
 247       phase_string = "Instant";
 248       break;
 249     case TRACE_EVENT_PHASE_ASYNC_BEGIN:
 250       phase_string = "Async Begin";
 251       break;
 252     case TRACE_EVENT_PHASE_ASYNC_STEP_INTO:
 253       phase_string = "Async Step Into";
 254       break;
 255     case TRACE_EVENT_PHASE_ASYNC_STEP_PAST:
 256       phase_string = "Async Step Past";
 257       break;
 258     case TRACE_EVENT_PHASE_ASYNC_END:
 259       phase_string = "Async End";
 260       break;
 261     case TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN:
 262       phase_string = "Nestable Async Begin";
 263       break;
 264     case TRACE_EVENT_PHASE_NESTABLE_ASYNC_END:
 265       phase_string = "Nestable Async End";
 266       break;
 267     case TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT:
 268       phase_string = "Nestable Async Instant";
 269       break;
 270     case TRACE_EVENT_PHASE_FLOW_BEGIN:
 271       phase_string = "Phase Flow Begin";
 272       break;
 273     case TRACE_EVENT_PHASE_FLOW_STEP:
 274       phase_string = "Phase Flow Step";
 275       break;
 276     case TRACE_EVENT_PHASE_FLOW_END:
 277       phase_string = "Phase Flow End";
 278       break;
 279     case TRACE_EVENT_PHASE_METADATA:
 280       phase_string = "Phase Metadata";
 281       break;
 282     case TRACE_EVENT_PHASE_COUNTER:
 283       phase_string = "Phase Counter";
 284       break;
 285     case TRACE_EVENT_PHASE_SAMPLE:
 286       phase_string = "Phase Sample";
 287       break;
 288     case TRACE_EVENT_PHASE_CREATE_OBJECT:
 289       phase_string = "Phase Create Object";
 290       break;
 291     case TRACE_EVENT_PHASE_SNAPSHOT_OBJECT:
 292       phase_string = "Phase Snapshot Object";
 293       break;
 294     case TRACE_EVENT_PHASE_DELETE_OBJECT:
 295       phase_string = "Phase Delete Object";
 296       break;
 297     default:
 298       phase_buffer[0] = phase;
 299       phase_buffer[1] = 0;
 300       phase_string = phase_buffer;
 301       break;
 302   }
 303
 304   std::string arg_values_string[3];
 305   for (int i = 0; i < num_args; i++) {
 306     if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
 307       // Temporarily do nothing here. This function consumes 1/3 to 1/2 of
 308       // *total* process CPU time when ETW tracing, and many of the strings
 309       // created exceed WPA's 4094 byte limit and are shown as:
 310       // "Unable to parse data". See crbug.com/488257
 311       // convertable_values[i]->AppendAsTraceFormat(arg_values_string + i);
 312     } else {
 313       TraceEvent::TraceValue trace_event;
 314       trace_event.as_uint = arg_values[i];
 315       TraceEvent::AppendValueAsJSON(arg_types[i], trace_event,
 316                                     arg_values_string + i);
 317     }
 318   }
 319
 320   EventWriteChromeEvent(
 321       name, phase_string, num_args > 0 ? arg_names[0] : "",
 322       arg_values_string[0].c_str(), num_args > 1 ? arg_names[1] : "",
 323       arg_values_string[1].c_str(), num_args > 2 ? arg_names[2] : "",
 324       arg_values_string[2].c_str());
 325 }
 326
 327 // static
 328 void TraceEventETWExport::AddCustomEvent(const char* name,
 329                                          char const* phase,
 330                                          const char* arg_name_1,
 331                                          const char* arg_value_1,
 332                                          const char* arg_name_2,
 333                                          const char* arg_value_2,
 334                                          const char* arg_name_3,
 335                                          const char* arg_value_3) {
 336   auto* instance = GetInstance();
 337   if (!instance || !instance->etw_export_enabled_ || !EventEnabledChromeEvent())
 338     return;
 339
 340   EventWriteChromeEvent(name, phase, arg_name_1, arg_value_1, arg_name_2,
 341                         arg_value_2, arg_name_3, arg_value_3);
 342 }
 343
 344 // static
 345 bool TraceEventETWExport::IsCategoryGroupEnabled(
 346     const char* category_group_name) {
 347   DCHECK(category_group_name);
 348   auto* instance = GetInstance();
 349   if (instance == nullptr)
 350     return false;
 351
 352   if (!instance->IsETWExportEnabled())
 353     return false;
 354
 355   CStringTokenizer category_group_tokens(
 356       category_group_name, category_group_name + strlen(category_group_name),
 357       ",");
 358   while (category_group_tokens.GetNext()) {
 359     std::string category_group_token = category_group_tokens.token();
 360     if (instance->IsCategoryEnabled(category_group_token.c_str())) {
 361       return true;
 362     }
 363   }
 364   return false;
 365 }
 366
 367 bool TraceEventETWExport::UpdateEnabledCategories() {
 368   if (etw_match_any_keyword_ == CHROME_Context.MatchAnyKeyword)
 369     return false;
 370
 371   // If the keyword has changed, update each category.
 372   // Chrome_Context.MatchAnyKeyword is set by UIforETW (or other ETW trace
 373   // recording tools) using the ETW infrastructure. This value will be set in
 374   // all Chrome processes that have registered their ETW provider.
 375   etw_match_any_keyword_ = CHROME_Context.MatchAnyKeyword;
 376   for (int i = 0; i < ARRAYSIZE(kFilteredEventGroupNames); i++) {
 377     if (etw_match_any_keyword_ & (1ULL << i)) {
 378       categories_status_[kFilteredEventGroupNames[i]] = true;
 379     } else {
 380       categories_status_[kFilteredEventGroupNames[i]] = false;
 381     }
 382   }
 383
 384   // Also update the two default categories.
 385   if (etw_match_any_keyword_ & kOtherEventsKeywordBit) {
 386     categories_status_[kOtherEventsGroupName] = true;
 387   } else {
 388     categories_status_[kOtherEventsGroupName] = false;
 389   }
 390   if (etw_match_any_keyword_ & kDisabledOtherEventsKeywordBit) {
 391     categories_status_[kDisabledOtherEventsGroupName] = true;
 392   } else {
 393     categories_status_[kDisabledOtherEventsGroupName] = false;
 394   }
 395
 396   // Update the categories in TraceLog.
 397   TraceLog::GetInstance()->UpdateETWCategoryGroupEnabledFlags();
 398
 399   return true;
 400 }
 401
 402 bool TraceEventETWExport::IsCategoryEnabled(const char* category_name) const {
 403   // Try to find the category and return its status if found
 404   auto it = categories_status_.find(category_name);
 405   if (it != categories_status_.end())
 406     return it->second;
 407
 408   // Otherwise return the corresponding default status by first checking if the
 409   // category is disabled by default.
 410   if (StringPiece(category_name).starts_with("disabled-by-default")) {
 411     DCHECK(categories_status_.find(kDisabledOtherEventsGroupName) !=
 412            categories_status_.end());
 413     return categories_status_.find(kDisabledOtherEventsGroupName)->second;
 414   } else {
 415     DCHECK(categories_status_.find(kOtherEventsGroupName) !=
 416            categories_status_.end());
 417     return categories_status_.find(kOtherEventsGroupName)->second;
 418   }
 419 }
 420
 421 // static
 422 void TraceEventETWExport::UpdateETWKeyword() {
 423   if (!IsETWExportEnabled())
 424     return;
 425   auto* instance = GetInstance();
 426   DCHECK(instance);
 427   instance->UpdateEnabledCategories();
 428 }
 429 }  // namespace trace_event
 430 }  // namespace base