summaryrefslogtreecommitdiffstats
path: root/third_party/libwebrtc/rtc_base/event_tracer.cc
blob: 992a2b5e089b00c9fd596f415000a096ed6f4338 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
/*
 *  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 "rtc_base/event_tracer.h"

#include <inttypes.h>
#include <stdint.h>
#include <stdio.h>
#include <string.h>

#include <atomic>
#include <string>
#include <vector>

#include "absl/strings/string_view.h"
#include "api/sequence_checker.h"
#include "rtc_base/checks.h"
#include "rtc_base/event.h"
#include "rtc_base/logging.h"
#include "rtc_base/platform_thread.h"
#include "rtc_base/platform_thread_types.h"
#include "rtc_base/synchronization/mutex.h"
#include "rtc_base/thread_annotations.h"
#include "rtc_base/time_utils.h"
#include "rtc_base/trace_event.h"

// This is a guesstimate that should be enough in most cases.
static const size_t kEventLoggerArgsStrBufferInitialSize = 256;
static const size_t 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,
                      AddTraceEventPtr add_trace_event_ptr) {
  g_get_category_enabled_ptr = get_category_enabled_ptr;
  g_add_trace_event_ptr = add_trace_event_ptr;
}

const unsigned char* EventTracer::GetCategoryEnabled(const char* name) {
  if (g_get_category_enabled_ptr)
    return g_get_category_enabled_ptr(name);

  // A string with null terminator means category is disabled.
  return reinterpret_cast<const unsigned char*>("\0");
}

// Arguments to this function (phase, etc.) are as defined in
// webrtc/rtc_base/trace_event.h.
void EventTracer::AddTraceEvent(char phase,
                                const unsigned char* category_enabled,
                                const char* name,
                                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) {
  if (g_add_trace_event_ptr) {
    g_add_trace_event_ptr(phase, category_enabled, name, id, num_args,
                          arg_names, arg_types, arg_values, flags);
  }
}

}  // namespace webrtc

namespace rtc {
namespace tracing {
namespace {

// Atomic-int fast path for avoiding logging when disabled.
static std::atomic<int> g_event_logging_active(0);

// TODO(pbos): Log metadata for all threads, etc.
class EventLogger final {
 public:
  ~EventLogger() { RTC_DCHECK(thread_checker_.IsCurrent()); }

  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) {
      TraceArg& arg = args[i];
      arg.name = arg_names[i];
      arg.type = arg_types[i];
      arg.value.as_uint = arg_values[i];

      // 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.
        size_t str_length = strlen(arg.value.as_string) + 1;
        char* str_copy = new char[str_length];
        memcpy(str_copy, arg.value.as_string, str_length);
        arg.value.as_string = str_copy;
      }
    }
    webrtc::MutexLock lock(&mutex_);
    trace_events_.push_back(
        {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 constexpr webrtc::TimeDelta kLoggingInterval =
        webrtc::TimeDelta::Millis(100);
    fprintf(output_file_, "{ \"traceEvents\": [\n");
    bool has_logged_event = false;
    while (true) {
      bool shutting_down = shutdown_event_.Wait(kLoggingInterval);
      std::vector<TraceEvent> events;
      {
        webrtc::MutexLock lock(&mutex_);
        trace_events_.swap(events);
      }
      std::string args_str;
      args_str.reserve(kEventLoggerArgsStrBufferInitialSize);
      for (TraceEvent& e : events) {
        args_str.clear();
        if (!e.args.empty()) {
          args_str += ", \"args\": {";
          bool is_first_argument = true;
          for (TraceArg& arg : e.args) {
            if (!is_first_argument)
              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, 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;
  }

  void Start(FILE* file, bool owned) {
    RTC_DCHECK(thread_checker_.IsCurrent());
    RTC_DCHECK(file);
    RTC_DCHECK(!output_file_);
    output_file_ = file;
    output_file_owned_ = owned;
    {
      webrtc::MutexLock lock(&mutex_);
      // Since the atomic fast-path for adding events to the queue can be
      // bypassed while the logging thread is shutting down there may be some
      // stale events in the queue, hence the vector needs to be cleared to not
      // log events from a previous logging session (which may be days old).
      trace_events_.clear();
    }
    // Enable event logging (fast-path). This should be disabled since starting
    // shouldn't be done twice.
    int zero = 0;
    RTC_CHECK(g_event_logging_active.compare_exchange_strong(zero, 1));

    // Finally start, everything should be set up now.
    logging_thread_ =
        PlatformThread::SpawnJoinable([this] { Log(); }, "EventTracingThread");
    TRACE_EVENT_INSTANT0("webrtc", "EventLogger::Start");
  }

  void Stop() {
    RTC_DCHECK(thread_checker_.IsCurrent());
    TRACE_EVENT_INSTANT0("webrtc", "EventLogger::Stop");
    // Try to stop. Abort if we're not currently logging.
    int one = 1;
    if (g_event_logging_active.compare_exchange_strong(one, 0))
      return;

    // Wake up logging thread to finish writing.
    shutdown_event_.Set();
    // Join the logging thread.
    logging_thread_.Finalize();
  }

 private:
  struct TraceArg {
    const char* name;
    unsigned char type;
    // Copied from webrtc/rtc_base/trace_event.h TraceValueUnion.
    union TraceArgValue {
      bool as_bool;
      unsigned long long as_uint;
      long long as_int;
      double as_double;
      const void* as_pointer;
      const char* as_string;
    } value;

    // Assert that the size of the union is equal to the size of the as_uint
    // field since we are assigning to arbitrary types using it.
    static_assert(sizeof(TraceArgValue) == sizeof(unsigned long long),
                  "Size of TraceArg value union is not equal to the size of "
                  "the uint field of that union.");
  };

  struct TraceEvent {
    const char* name;
    const unsigned char* category_enabled;
    char phase;
    std::vector<TraceArg> args;
    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 += '\"';
      const char* c = arg.value.as_string;
      do {
        if (*c == '"' || *c == '\\') {
          output += '\\';
          output += *c;
        } else {
          output += *c;
        }
      } while (*++c);
      output += '\"';
    } else {
      output.resize(kTraceArgBufferLength);
      size_t print_length = 0;
      switch (arg.type) {
        case TRACE_VALUE_TYPE_BOOL:
          if (arg.value.as_bool) {
            strcpy(&output[0], "true");
            print_length = 4;
          } else {
            strcpy(&output[0], "false");
            print_length = 5;
          }
          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;
      }
      size_t output_length = print_length < kTraceArgBufferLength
                                 ? print_length
                                 : kTraceArgBufferLength - 1;
      // This will hopefully be very close to nop. On most implementations, it
      // just writes null byte and sets the length field of the string.
      output.resize(output_length);
    }

    return output;
  }

  webrtc::Mutex mutex_;
  std::vector<TraceEvent> trace_events_ RTC_GUARDED_BY(mutex_);
  rtc::PlatformThread logging_thread_;
  rtc::Event shutdown_event_;
  webrtc::SequenceChecker thread_checker_;
  FILE* output_file_ = nullptr;
  bool output_file_owned_ = false;
};

static std::atomic<EventLogger*> g_event_logger(nullptr);
static const char* const kDisabledTracePrefix = TRACE_DISABLED_BY_DEFAULT("");
const unsigned char* InternalGetCategoryEnabled(const char* name) {
  const char* prefix_ptr = &kDisabledTracePrefix[0];
  const char* name_ptr = name;
  // Check whether name contains the default-disabled prefix.
  while (*prefix_ptr == *name_ptr && *prefix_ptr != '\0') {
    ++prefix_ptr;
    ++name_ptr;
  }
  return reinterpret_cast<const unsigned char*>(*prefix_ptr == '\0' ? ""
                                                                    : name);
}

const unsigned char* InternalEnableAllCategories(const char* name) {
  return reinterpret_cast<const unsigned char*>(name);
}

void InternalAddTraceEvent(char phase,
                           const unsigned char* category_enabled,
                           const char* name,
                           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 (g_event_logging_active.load() == 0)
    return;

  g_event_logger.load()->AddTraceEvent(
      name, category_enabled, phase, num_args, arg_names, arg_types, arg_values,
      rtc::TimeMicros(), 1, rtc::CurrentThreadId());
}

}  // namespace

void SetupInternalTracer(bool enable_all_categories) {
  EventLogger* null_logger = nullptr;
  RTC_CHECK(
      g_event_logger.compare_exchange_strong(null_logger, new EventLogger()));
  webrtc::SetupEventTracer(enable_all_categories ? InternalEnableAllCategories
                                                 : InternalGetCategoryEnabled,
                           InternalAddTraceEvent);
}

void StartInternalCaptureToFile(FILE* file) {
  EventLogger* event_logger = g_event_logger.load();
  if (event_logger) {
    event_logger->Start(file, false);
  }
}

bool StartInternalCapture(absl::string_view filename) {
  EventLogger* event_logger = g_event_logger.load();
  if (!event_logger)
    return false;

  FILE* file = fopen(std::string(filename).c_str(), "w");
  if (!file) {
    RTC_LOG(LS_ERROR) << "Failed to open trace file '" << filename
                      << "' for writing.";
    return false;
  }
  event_logger->Start(file, true);
  return true;
}

void StopInternalCapture() {
  EventLogger* event_logger = g_event_logger.load();
  if (event_logger) {
    event_logger->Stop();
  }
}

void ShutdownInternalTracer() {
  StopInternalCapture();
  EventLogger* old_logger = g_event_logger.load(std::memory_order_acquire);
  RTC_DCHECK(old_logger);
  RTC_CHECK(g_event_logger.compare_exchange_strong(old_logger, nullptr));
  delete old_logger;
  webrtc::SetupEventTracer(nullptr, nullptr);
}

}  // namespace tracing
}  // namespace rtc