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