Add argument support for stand-alone WebRTC tracing.

webrtc/base/event_tracer.cc

 /*
  *  Copyright (c) 2012 The WebRTC project authors. All Rights Reserved.
  *
  *  Use of this source code is governed by a BSD-style license
  *  that can be found in the LICENSE file in the root of the source
  *  tree. An additional intellectual property rights grant can be found
  *  in the file PATENTS.  All contributing project authors may
  *  be found in the AUTHORS file in the root of the source tree.
  */
 #include "webrtc/base/event_tracer.h"
 
 #include <inttypes.h>
 
+#include <string>
 #include <vector>
 
 #include "webrtc/base/checks.h"
 #include "webrtc/base/criticalsection.h"
 #include "webrtc/base/event.h"
 #include "webrtc/base/logging.h"
 #include "webrtc/base/platform_thread.h"
 #include "webrtc/base/timeutils.h"
 #include "webrtc/base/trace_event.h"
 
+static const int kTraceArgBufferLength = 32;
+
 namespace webrtc {
 
 namespace {
 
 GetCategoryEnabledPtr g_get_category_enabled_ptr = nullptr;
 AddTraceEventPtr g_add_trace_event_ptr = nullptr;
 
 }  // namespace
 
 void SetupEventTracer(GetCategoryEnabledPtr get_category_enabled_ptr,
@@ skipping 49 matching lines @@
 class EventLogger final {
  public:
   EventLogger()
       : logging_thread_(EventTracingThreadFunc, this, "EventTracingThread"),
         shutdown_event_(false, false) {}
   ~EventLogger() { RTC_DCHECK(thread_checker_.CalledOnValidThread()); }
 
   void AddTraceEvent(const char* name,
                      const unsigned char* category_enabled,
                      char phase,
+                     int num_args,
+                     const char** arg_names,
+                     const unsigned char* arg_types,
+                     const unsigned long long* arg_values,
                      uint64_t timestamp,
                      int pid,
                      rtc::PlatformThreadId thread_id) {
+    std::vector<TraceArg> args(num_args);
+    for (int i = 0; i < num_args; i++) {

[tommi, 2016/08/05 10:58:42]

++i

[sakal, 2016/08/05 12:21:07]

Done.

+      TraceArg& arg = args[i];
+      arg.name = arg_names[i];
+      arg.type = arg_types[i];
+      arg.value.as_uint = arg_values[i];

[tommi, 2016/08/05 10:58:41]

At first I wasn't sure if this would always copy all the bits since uint can be
32bit.  I see that this is not a problem after seeing that as_uint, isn't
necessarily the same as a uint.  So I think a better name might be in order. 
intptr?

[sakal, 2016/08/05 12:21:07]

I copied the union from webrtc/base/trace_event.h TraceValueUnion. I would like
to keep it identical to that one.

[tommi, 2016/08/05 12:50:15]

Acknowledged.

+
+      // Value is a pointer to a temporary string, so we have to make a copy.
+      if (arg.type == TRACE_VALUE_TYPE_COPY_STRING) {
+        // Space for the string and for the terminating null character.
+        char* str_copy = new char[strlen(arg.value.as_string) + 1];
+        strcpy(str_copy, arg.value.as_string);

[tommi, 2016/08/05 10:58:41]

nit: since you call strlen above, you could use that return value and call
strncpy here.

[sakal, 2016/08/05 12:21:06]

Changed this to memcpy. Should be safe and even more efficient.

+        arg.value.as_string = str_copy;
+      }
+    }
     rtc::CritScope lock(&crit_);
     trace_events_.push_back(
-        {name, category_enabled, phase, timestamp, 1, thread_id});
+        {name, category_enabled, phase, args, timestamp, 1, thread_id});
   }
 
 // The TraceEvent format is documented here:
 // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
   void Log() {
     RTC_DCHECK(output_file_);
     static const int kLoggingIntervalMs = 100;
     fprintf(output_file_, "{ \"traceEvents\": [\n");
     bool has_logged_event = false;
     while (true) {
       bool shutting_down = shutdown_event_.Wait(kLoggingIntervalMs);
       std::vector<TraceEvent> events;
       {
         rtc::CritScope lock(&crit_);
         trace_events_.swap(events);
       }
-      for (const TraceEvent& e : events) {
+      for (TraceEvent& e : events) {
+        std::string args_str;
+        if (!e.args.empty()) {
+          args_str += ", \"args\": {";

[tommi, 2016/08/05 10:58:41]

nit: since we know that args_str will always be at least of a certain size, we
could start by reserving a few bytes to handle common cases.

[sakal, 2016/08/05 12:21:07]

I moved args_str to the outside of the loop and made it be initialized to 256
bytes.

+          bool is_first_argument = true;
+          for (TraceArg& arg : e.args) {
+            if (!is_first_argument) {

[tommi, 2016/08/05 10:58:42]

no {} (see rest of code)

[sakal, 2016/08/05 12:21:06]

Done.

+              args_str += ",";
+            }
+            is_first_argument = false;
+            args_str += " \"";
+            args_str += arg.name;
+            args_str += "\": ";
+            args_str += TraceArgValueAsString(arg);
+
+            // Delete our copy of the string.
+            if (arg.type == TRACE_VALUE_TYPE_COPY_STRING) {
+              delete[] arg.value.as_string;
+              arg.value.as_string = nullptr;
+            }
+          }
+          args_str += " }";
+        }
         fprintf(output_file_,
                 "%s{ \"name\": \"%s\""
                 ", \"cat\": \"%s\""
                 ", \"ph\": \"%c\""
                 ", \"ts\": %" PRIu64
                 ", \"pid\": %d"
 #if defined(WEBRTC_WIN)
                 ", \"tid\": %lu"
 #else
                 ", \"tid\": %d"
 #endif  // defined(WEBRTC_WIN)
+                "%s"
                 "}\n",
                 has_logged_event ? "," : " ", e.name, e.category_enabled,
-                e.phase, e.timestamp, e.pid, e.tid);
+                e.phase, e.timestamp, e.pid, e.tid, args_str.c_str());
         has_logged_event = true;
       }
       if (shutting_down)
         break;
     }
     fprintf(output_file_, "]}\n");
     if (output_file_owned_)
       fclose(output_file_);
     output_file_ = nullptr;
   }
@@ skipping 30 matching lines @@
     if (rtc::AtomicOps::CompareAndSwap(&g_event_logging_active, 1, 0) == 0)
       return;
 
     // Wake up logging thread to finish writing.
     shutdown_event_.Set();
     // Join the logging thread.
     logging_thread_.Stop();
   }
 
  private:
+  struct TraceArg {
+    const char* name;
+    unsigned char type;
+    union {
+      bool as_bool;
+      unsigned long long as_uint;

[tommi, 2016/08/05 10:58:42]

'as_uint' is a bit misleading.  uint can be 32 bits, but this can never be that.
 I think it might actually be a good thing too to have a static_assert() that
the size of this union member, equals the size of the union, since you use it to
assign arbitrary types to the union.

[sakal, 2016/08/05 12:21:07]

I copied this union from webrtc/base/trace_event.h TraceValueUnion. I would like
to keep it identical to that one. I added the static assert.

[tommi, 2016/08/05 12:50:15]

Acknowledged.  Thanks for the static_assert.

+      long long as_int;
+      double as_double;
+      const void* as_pointer;
+      const char* as_string;
+    } value;
+  };
+
   struct TraceEvent {
     const char* name;
     const unsigned char* category_enabled;
     char phase;
+    std::vector<TraceArg> args;

[tommi, 2016/08/05 10:58:42]

is there a way for us to avoid allocating a vector for every TraceEvent?  As is,
it seems like all the other members are pod.

[sakal, 2016/08/05 12:21:06]

Discussed this offline.

     uint64_t timestamp;
     int pid;
     rtc::PlatformThreadId tid;
   };
 
+  static std::string TraceArgValueAsString(TraceArg arg) {
+    std::string output;
+
+    if (arg.type == TRACE_VALUE_TYPE_STRING ||
+        arg.type == TRACE_VALUE_TYPE_COPY_STRING) {
+      // Space for every character to be an espaced character + two for
+      // quatation marks.
+      output.reserve(strlen(arg.value.as_string) * 2 + 2);
+      output += "\"";

[tommi, 2016/08/05 10:58:42]

nit: this does a "string append" and not a "char append".  The difference is
that a strlen() call will be made.  Instead, you can avoid that strlen call +
the extra terminating \0 by doing:

output += '"';

[sakal, 2016/08/05 12:21:07]

Done.

+      const char* c = arg.value.as_string;
+      do {
+        if (*c == '"' || *c == '\\') {
+          output += '\\';
+          output += *c;
+        } else {
+          output += *c;
+        }
+      } while (*++c);
+      output += "\"";

[tommi, 2016/08/05 10:58:42]

same here.

[sakal, 2016/08/05 12:21:07]

Done.

+    } else {
+      output.resize(kTraceArgBufferLength);
+      int print_length;
+      switch (arg.type) {
+        case TRACE_VALUE_TYPE_BOOL:
+          print_length = snprintf(&output[0], kTraceArgBufferLength, "%s",

[tommi, 2016/08/05 10:58:41]

you don't need snprintf here, just use strcpy()

[sakal, 2016/08/05 12:21:06]

Done.

+                                  arg.value.as_bool ? "true" : "false");
+          break;
+        case TRACE_VALUE_TYPE_UINT:
+          print_length = snprintf(&output[0], kTraceArgBufferLength, "%llu",
+                                  arg.value.as_uint);
+          break;
+        case TRACE_VALUE_TYPE_INT:
+          print_length = snprintf(&output[0], kTraceArgBufferLength, "%lld",
+                                  arg.value.as_int);
+          break;
+        case TRACE_VALUE_TYPE_DOUBLE:
+          print_length = snprintf(&output[0], kTraceArgBufferLength, "%f",
+                                  arg.value.as_double);
+          break;
+        case TRACE_VALUE_TYPE_POINTER:
+          print_length = snprintf(&output[0], kTraceArgBufferLength, "\"%p\"",
+                                  arg.value.as_pointer);
+          break;
+      }
+      int output_length = print_length < kTraceArgBufferLength
+                              ? print_length
+                              : kTraceArgBufferLength - 1;
+      output.resize(output_length);
+    }
+
+    return output;
+  }
+
   rtc::CriticalSection crit_;
   std::vector<TraceEvent> trace_events_ GUARDED_BY(crit_);
   rtc::PlatformThread logging_thread_;
   rtc::Event shutdown_event_;
   rtc::ThreadChecker thread_checker_;
   FILE* output_file_ = nullptr;
   bool output_file_owned_ = false;
 };
 
 static bool EventTracingThreadFunc(void* params) {
@@ skipping 23 matching lines @@
                            unsigned long long id,
                            int num_args,
                            const char** arg_names,
                            const unsigned char* arg_types,
                            const unsigned long long* arg_values,
                            unsigned char flags) {
   // Fast path for when event tracing is inactive.
   if (rtc::AtomicOps::AcquireLoad(&g_event_logging_active) == 0)
     return;
 
-  g_event_logger->AddTraceEvent(name, category_enabled, phase,
+  g_event_logger->AddTraceEvent(name, category_enabled, phase, num_args,
+                                arg_names, arg_types, arg_values,
                                 rtc::TimeMicros(), 1, rtc::CurrentThreadId());
 }
 
 }  // namespace
 
 void SetupInternalTracer() {
   RTC_CHECK(rtc::AtomicOps::CompareAndSwapPtr(
                 &g_event_logger, static_cast<EventLogger*>(nullptr),
                 new EventLogger()) == nullptr);
   webrtc::SetupEventTracer(InternalGetCategoryEnabled, InternalAddTraceEvent);
@@ skipping 24 matching lines @@
   RTC_DCHECK(old_logger);
   RTC_CHECK(rtc::AtomicOps::CompareAndSwapPtr(
                 &g_event_logger, old_logger,
                 static_cast<EventLogger*>(nullptr)) == old_logger);
   delete old_logger;
   webrtc::SetupEventTracer(nullptr, nullptr);
 }
 
 }  // namespace tracing
 }  // namespace rtc