Have all trace points emit to ETW.

base/debug/trace_event_win.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 #include "base/debug/trace_event_win.h"
 
 #include "base/logging.h"
 #include "base/memory/singleton.h"
 #include <initguid.h>  // NOLINT
 
 namespace base {
 namespace debug {
 
 using base::win::EtwEventType;
 using base::win::EtwMofEvent;
 
 // {3DADA31D-19EF-4dc1-B345-037927193422}
 const GUID kChromeTraceProviderName = {
     0x3dada31d, 0x19ef, 0x4dc1, 0xb3, 0x45, 0x3, 0x79, 0x27, 0x19, 0x34, 0x22 };
 
 // {B967AE67-BB22-49d7-9406-55D91EE1D560}
 const GUID kTraceEventClass32 = {
     0xb967ae67, 0xbb22, 0x49d7, 0x94, 0x6, 0x55, 0xd9, 0x1e, 0xe1, 0xd5, 0x60 };

[Sigurður Ásgeirsson, 2013/09/10 21:15:54]

If you're changing the message format, you should change this GUID to avoid
breaking existing tools that parse the old message format (Sawbuck).

[fdoray, 2013/09/16 00:51:03]

Done.

 
 // {97BE602D-2930-4ac3-8046-B6763B631DFE}
 const GUID kTraceEventClass64 = {
     0x97be602d, 0x2930, 0x4ac3, 0x80, 0x46, 0xb6, 0x76, 0x3b, 0x63, 0x1d, 0xfe};
 
+// Number of fields associated with traced events.
+// See the comment above the declaration of TraceEventETWProvider::TraceEvent()
+// for the list of fields.
+const int kTraceNumFields = 6 + 2 * kTraceMaxNumArgs;

[Sigurður Ásgeirsson, 2013/09/10 21:15:54]

The templated, fixed-size MofEvent is a performance hack for logging events with
a fixed number of fields.
It seems like it would be more appropriate here to use a vector of fields or
some mode of dynamic allocation, as this code looks like it'll be allocating a
fair amount of memory anyway.

[fdoray, 2013/09/16 00:51:03]

The difficulty is that the MOF fields must immediately follow the header in
memory. A std::vector is not suitable for that. Did you have in mind something
like below? I don't like to have this new class in addition to EtwMOFEvent
(which will still be used by logging_win.cc and event_trace_provider.cc) to
avoid 6 unused void* on the stack (2*(kTraceMaxNumArgs=2) + 2 pointers for stack
trace). These extra pointers don't change the size of the resulting ETW event.
What do you think? If you prefer dynamic memory, I can make it.

class EtwDynamicMOFEvent {
 public:
  EtwDynamicMOFEvent(const EtwEventClass& event_class, EtwEventType type,
                     EtwEventLevel level, size_t nb_fields)
      : current_field_index_(0), nb_fields_(nb_fields) {
    size_t event_size =
        sizeof(EVENT_TRACE_HEADER) + nb_fields_ * sizeof(MOF_FIELD);
    header_ = static_cast<EVENT_TRACE_HEADER*>(malloc(event_size));
    memset(header_, 0, event_size);
    header_->Size = event_size;
    header_->Guid = event_class;
    header_->Class.Type = type;
    header_->Class.Level = level;
    header_->Flags = WNODE_FLAG_TRACED_GUID | WNODE_FLAG_USE_MOF_PTR;

    fields_ = nb_fields_ ? header_ + sizeof(EVENT_TRACE_HEADER) : NULL;
  }

  ~EtwDynamicMOFEvent() {
    free(header_);
  }

  void AddField(size_t size, const void *data) {
    DCHECK(current_field_index_ < nb_fields_);
    fields_[current_field_index_].DataPtr = reinterpret_cast<ULONG64>(data);
    fields_[current_field_index_].Length = static_cast<ULONG>(size);
    ++current_field_index;
  }

  ETW_TRACE_HEADER* get() { return header_; }

 private:
  EVENT_TRACE_HEADER* header_;
  MOF_FIELD_* fields_;
  size_t current_field_index_;
  size_t nb_fields_;

  DISALLOW_COPY_AND_ASSIGN(EtwDynamicMOFEvent);
};

On 2013/09/10 21:15:54, Sigurður Ásgeirsson wrote:

 
 TraceEventETWProvider::TraceEventETWProvider() :
     EtwTraceProvider(kChromeTraceProviderName) {
   Register();
 }
 
 TraceEventETWProvider* TraceEventETWProvider::GetInstance() {
   return Singleton<TraceEventETWProvider,
       StaticMemorySingletonTraits<TraceEventETWProvider> >::get();
 }
 
 bool TraceEventETWProvider::StartTracing() {
   return true;
 }
 
-void TraceEventETWProvider::TraceEvent(const char* name,
-                                       size_t name_len,
+void TraceEventETWProvider::TraceEvent(const char* category_group,
+                                       const char* name,
                                        char type,
-                                       const void* id,
-                                       const char* extra,
-                                       size_t extra_len) {
+                                       unsigned long long id,
+                                       const std::string& thread_name,
+                                       int num_args,
+                                       const char** arg_names,
+                                       std::string* arg_values) {
   // Make sure we don't touch NULL.
   if (name == NULL)
     name = "";
-  if (extra == NULL)
-    extra = "";
+  if (category_group == NULL)
+    category_group = "";
 
   EtwEventType etw_type = 0;
   switch (type) {
     case TRACE_EVENT_PHASE_BEGIN:
+    case TRACE_EVENT_PHASE_ASYNC_BEGIN:
+    case TRACE_EVENT_PHASE_FLOW_BEGIN:
+    case TRACE_EVENT_PHASE_CREATE_OBJECT:
       etw_type = kTraceEventTypeBegin;
       break;
     case TRACE_EVENT_PHASE_END:
+    case TRACE_EVENT_PHASE_ASYNC_END:
+    case TRACE_EVENT_PHASE_FLOW_END:
+    case TRACE_EVENT_PHASE_DELETE_OBJECT:
       etw_type = kTraceEventTypeEnd;
       break;
 
     case TRACE_EVENT_PHASE_INSTANT:
+    case TRACE_EVENT_PHASE_INSTANT_OLD:
+    case TRACE_EVENT_PHASE_ASYNC_STEP:
+    case TRACE_EVENT_PHASE_FLOW_STEP:
+    case TRACE_EVENT_PHASE_METADATA:
+    case TRACE_EVENT_PHASE_COUNTER:
+    case TRACE_EVENT_PHASE_SAMPLE:
+    case TRACE_EVENT_PHASE_SNAPSHOT_OBJECT:
       etw_type = kTraceEventTypeInstant;
       break;
 
     default:
       NOTREACHED() << "Unknown event type";
       etw_type = kTraceEventTypeInstant;
       break;
   }
 
-  EtwMofEvent<5> event(kTraceEventClass32,
-                       etw_type,
-                       TRACE_LEVEL_INFORMATION);
-  event.SetField(0, name_len + 1, name);
-  event.SetField(1, sizeof(id), &id);
-  event.SetField(2, extra_len + 1, extra);
+  EtwMofEvent<kTraceNumFields> event(kTraceEventClass32,
+                                     etw_type,
+                                     TRACE_LEVEL_INFORMATION);
+  int field_index = 0;
+  event.SetField(field_index++, strlen(name) + 1, name);

[Sigurður Ásgeirsson, 2013/09/10 21:15:54]

I'd be very interested to know what Sawbuck does with these strung out,
multi-field events :). Do you use Sawbuck, have you seen how it treats these?

[fdoray, 2013/09/16 00:51:03]

Sawbuck doesn't parse these messages correctly. With the old GUID, the
"category" was used as the "extra" string and other fields were ignored (no
crash). With the new GUIDs, Sawbuck doesn't show the new events.

On 2013/09/10 21:15:54, Sigurður Ásgeirsson wrote:

+  event.SetField(field_index++, sizeof(id), &id);
+  event.SetField(field_index++, strlen(category_group) + 1, category_group);
+  event.SetField(field_index++, thread_name.size() + 1, thread_name.c_str());

[Sigurður Ásgeirsson, 2013/09/10 21:15:54]

Is it really necessary to stuff the thread name into every event?
The event already contains the process & thread IDs, and if thread names are to
be found in the trace (e.g. perhaps add thread name tracing), you'd be able to
find the names by correlating the traces.

[fdoray, 2013/09/16 00:51:03]

Done. I've started a distinct CL for this:
https://codereview.chromium.org/23510008/

+
+  for (int i = 0; i < kTraceMaxNumArgs; ++i) {
+    if (i < num_args) {
+      event.SetField(field_index++, strlen(arg_names[i]) + 1, arg_names[i]);
+      event.SetField(field_index++,
+                     arg_values[i].size() + 1,
+                     arg_values[i].c_str());
+    } else {
+      event.SetField(field_index++, 1, "");
+      event.SetField(field_index++, 1, "");
+    }
+  }
+  DCHECK(num_args <= kTraceMaxNumArgs)
+      << "Maximum number of custom fields exceeded in ETW event. Extra custom "
+         "fields were ignored.";
 
   // See whether we're to capture a backtrace.
   void* backtrace[32];
   if (enable_flags() & CAPTURE_STACK_TRACE) {
     DWORD hash = 0;
     DWORD depth = CaptureStackBackTrace(0,
                                         arraysize(backtrace),
                                         backtrace,
                                         &hash);
-    event.SetField(3, sizeof(depth), &depth);
-    event.SetField(4, sizeof(backtrace[0]) * depth, backtrace);
+    event.SetField(field_index++, sizeof(depth), &depth);
+    event.SetField(field_index++, sizeof(backtrace[0]) * depth, backtrace);
   }
+  DCHECK(field_index <= kTraceNumFields)
+      << "Maxium number of fields exceeded in ETW event.";
 
   // Trace the event.
   Log(event.get());
 }
 
 void TraceEventETWProvider::Trace(const char* name,
-                                  size_t name_len,
                                   char type,
                                   const void* id,
-                                  const char* extra,
-                                  size_t extra_len) {
+                                  const char* extra) {
   TraceEventETWProvider* provider = TraceEventETWProvider::GetInstance();
   if (provider && provider->IsTracing()) {
-    // Compute the name & extra lengths if not supplied already.
-    if (name_len == -1)
-      name_len = (name == NULL) ? 0 : strlen(name);
-    if (extra_len == -1)
-      extra_len = (extra == NULL) ? 0 : strlen(extra);
+    int num_args = 0;
+    const char* arg_names[1];
+    std::string arg_values[1];
+    if (extra) {
+      num_args = 1;
+      arg_names[0] = "extra";
+      arg_values[0] = extra;
+    }
 
-    provider->TraceEvent(name, name_len, type, id, extra, extra_len);
+    provider->TraceEvent("ETW Macro", name, type,
+                         reinterpret_cast<unsigned long long>(id),
+                         std::string(), num_args, arg_names, arg_values);
   }
 }
 
+void TraceEventETWProvider::TraceWithArgs(

[Sigurður Ásgeirsson, 2013/09/10 21:15:54]

I'd argue for the following:
- Leave the existing trace format as-is for the simpler events already traced,
unless no one is tracing those anymore. 
  In that case, I'd argue for removing the Trace() function and all the code
that goes with it.
- Allocate a new set of trace event class/IDs for these more complicated events.
- Make plans to break the category_groups out to different ETW facilities.
- Make plans to allow ETW-driven runtime control of per-facility/category
tracing, and/or implement that off the bat.
- Add tracing on thread creation to trace the thread ID->name association.

You can also use ETW enable bits to control the level of logging - it might not
be crazy, as a case in point, to elide tracing arguments, unless when explicitly
directed to capture them by an enable bit.

[fdoray, 2013/09/16 00:51:03]

- OK, I kept the existing trace format as-is for events that use the
TRACE_EVENT_*_ETW macros. These macros are not used a lot, so I plan to make
distinct CLs to replace them with the more generic macros from trace_event.h and
then to remove everything related to the old format.
- New GUIDs: done.
- Categories: It would be nice, but it's complex to achieve. See the message
associated with the publication of these comments.
- Thread name event: OK, will be done in a distinct CL
(https://codereview.chromium.org/23510008/)

On 2013/09/10 21:15:54, Sigurður Ásgeirsson wrote:

+    const char* category_group,
+    const char* name,
+    char type,
+    unsigned long long id,
+    const std::string& thread_name,
+    int num_args,
+    const char** arg_names,
+    const unsigned char* arg_types,
+    const unsigned long long* arg_values,
+    scoped_ptr<ConvertableToTraceFormat> convertable_values[]) {
+  TraceEventETWProvider* provider = TraceEventETWProvider::GetInstance();
+  if (provider && provider->IsTracing()) {
+    // Convert argument values to strings.
+    std::string arg_str_values[kTraceMaxNumArgs];
+    for (int i = 0; i < num_args; ++i) {
+      if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
+        convertable_values[i]->AppendAsTraceFormat(&arg_str_values[i]);

[dsinclair, 2013/09/09 19:57:46]

If I'm reading this correctly this is a potential performance issue.  Is this
doing the conversion of the convertables as soon as the trace event is added?

The convertables are designed to do the conversion as late as possible. The
reason for this is that they  can be quite large (i.e. full layer tree dumps,
skp files, gpu pixel dumps, etc).  We don't want to do this while we're tracing
as it will add overhead that can skew the trace results.

[Sigurður Ásgeirsson, 2013/09/10 21:15:54]

ETW provides a binary transport, so everything will need to be serialized for
logging, unfortunately.
This should only happen when ETW logging has been turned on for the facility,
e.g. the conversion won't take place unless someone's listening on the facility.
Lines 167-168 should take care of gating this.

That being said, there's a size limit to what can be stashed in a single ETW
message, on the order of 8K or so IIRC.
I'm not familiar with the various event types passing through here, but perhaps
there's reason to filter the handled events down to some subset initially, or to
skip large messages, or to skip convertible values?

[fdoray, 2013/09/16 00:51:03]

According to
http://msdn.microsoft.com/en-us/library/windows/desktop/aa363668(v=vs.85).aspx,
I think the size limit is 64K. I've added a way to skip convertible values.

On 2013/09/10 21:15:54, Sigurður Ásgeirsson wrote:

+      } else {
+        base::debug::TraceEvent::TraceValue value;
+        value.as_uint = arg_values[i];
+        base::debug::TraceEvent::AppendValueAsJSON(arg_types[i],
+                                                   value,
+                                                   &arg_str_values[i]);
+      }
+    }
+
+    provider->TraceEvent(category_group, name, type, id,
+                         thread_name, num_args, arg_names, arg_str_values);
+  }
+}
+
 void TraceEventETWProvider::Resurrect() {
   StaticMemorySingletonTraits<TraceEventETWProvider>::Resurrect();
 }
 
 }  // namespace debug
 }  // namespace base