1// Copyright (c) 2012 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/debug/trace_event_impl.h"
6
7#include <fcntl.h>
8
9#include "base/debug/trace_event.h"
10#include "base/format_macros.h"
11#include "base/logging.h"
12#include "base/strings/stringprintf.h"
13#include "base/synchronization/waitable_event.h"
14
15namespace {
16
17int g_atrace_fd = -1;
18const char* kATraceMarkerFile = "/sys/kernel/debug/tracing/trace_marker";
19
20void WriteEvent(
21    char phase,
22    const char* category_group,
23    const char* name,
24    unsigned long long id,
25    const char** arg_names,
26    const unsigned char* arg_types,
27    const base::debug::TraceEvent::TraceValue* arg_values,
28    const scoped_refptr<base::debug::ConvertableToTraceFormat>*
29        convertable_values,
30    unsigned char flags) {
31  std::string out = base::StringPrintf("%c|%d|%s", phase, getpid(), name);
32  if (flags & TRACE_EVENT_FLAG_HAS_ID)
33    base::StringAppendF(&out, "-%" PRIx64, static_cast<uint64>(id));
34  out += '|';
35
36  for (int i = 0; i < base::debug::kTraceMaxNumArgs && arg_names[i]; ++i) {
37    if (i)
38      out += ';';
39    out += arg_names[i];
40    out += '=';
41    std::string::size_type value_start = out.length();
42    if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
43      convertable_values[i]->AppendAsTraceFormat(&out);
44    } else {
45      base::debug::TraceEvent::AppendValueAsJSON(
46          arg_types[i], arg_values[i], &out);
47    }
48    // Remove the quotes which may confuse the atrace script.
49    ReplaceSubstringsAfterOffset(&out, value_start, "\\\"", "'");
50    ReplaceSubstringsAfterOffset(&out, value_start, "\"", "");
51    // Replace chars used for separators with similar chars in the value.
52    std::replace(out.begin() + value_start, out.end(), ';', ',');
53    std::replace(out.begin() + value_start, out.end(), '|', '!');
54  }
55
56  out += '|';
57  out += category_group;
58  write(g_atrace_fd, out.c_str(), out.size());
59}
60
61void NoOpOutputCallback(base::WaitableEvent* complete_event,
62                        const scoped_refptr<base::RefCountedString>&,
63                        bool has_more_events) {
64  if (!has_more_events)
65    complete_event->Signal();
66}
67
68void EndChromeTracing(base::debug::TraceLog* trace_log,
69                      base::WaitableEvent* complete_event) {
70  trace_log->SetDisabled();
71  // Delete the buffered trace events as they have been sent to atrace.
72  trace_log->Flush(base::Bind(&NoOpOutputCallback, complete_event));
73}
74
75}  // namespace
76
77namespace base {
78namespace debug {
79
80// These functions support Android systrace.py when 'webview' category is
81// traced. With the new adb_profile_chrome, we may have two phases:
82// - before WebView is ready for combined tracing, we can use adb_profile_chrome
83//   to trace android categories other than 'webview' and chromium categories.
84//   In this way we can avoid the conflict between StartATrace/StopATrace and
85//   the intents.
86// - TODO(wangxianzhu): after WebView is ready for combined tracing, remove
87//   StartATrace, StopATrace and SendToATrace, and perhaps send Java traces
88//   directly to atrace in trace_event_binding.cc.
89
90void TraceLog::StartATrace() {
91  if (g_atrace_fd != -1)
92    return;
93
94  g_atrace_fd = open(kATraceMarkerFile, O_WRONLY);
95  if (g_atrace_fd == -1) {
96    PLOG(WARNING) << "Couldn't open " << kATraceMarkerFile;
97    return;
98  }
99  SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString),
100             TraceLog::RECORDING_MODE,
101             TraceOptions(RECORD_CONTINUOUSLY));
102}
103
104void TraceLog::StopATrace() {
105  if (g_atrace_fd == -1)
106    return;
107
108  close(g_atrace_fd);
109  g_atrace_fd = -1;
110
111  // TraceLog::Flush() requires the current thread to have a message loop, but
112  // this thread called from Java may not have one, so flush in another thread.
113  Thread end_chrome_tracing_thread("end_chrome_tracing");
114  WaitableEvent complete_event(false, false);
115  end_chrome_tracing_thread.Start();
116  end_chrome_tracing_thread.message_loop()->PostTask(
117      FROM_HERE, base::Bind(&EndChromeTracing, Unretained(this),
118                            Unretained(&complete_event)));
119  complete_event.Wait();
120}
121
122void TraceEvent::SendToATrace() {
123  if (g_atrace_fd == -1)
124    return;
125
126  const char* category_group =
127      TraceLog::GetCategoryGroupName(category_group_enabled_);
128
129  switch (phase_) {
130    case TRACE_EVENT_PHASE_BEGIN:
131      WriteEvent('B', category_group, name_, id_,
132                 arg_names_, arg_types_, arg_values_, convertable_values_,
133                 flags_);
134      break;
135
136    case TRACE_EVENT_PHASE_COMPLETE:
137      WriteEvent(duration_.ToInternalValue() == -1 ? 'B' : 'E',
138                 category_group, name_, id_,
139                 arg_names_, arg_types_, arg_values_, convertable_values_,
140                 flags_);
141      break;
142
143    case TRACE_EVENT_PHASE_END:
144      // Though a single 'E' is enough, here append pid, name and
145      // category_group etc. So that unpaired events can be found easily.
146      WriteEvent('E', category_group, name_, id_,
147                 arg_names_, arg_types_, arg_values_, convertable_values_,
148                 flags_);
149      break;
150
151    case TRACE_EVENT_PHASE_INSTANT:
152      // Simulate an instance event with a pair of begin/end events.
153      WriteEvent('B', category_group, name_, id_,
154                 arg_names_, arg_types_, arg_values_, convertable_values_,
155                 flags_);
156      write(g_atrace_fd, "E", 1);
157      break;
158
159    case TRACE_EVENT_PHASE_COUNTER:
160      for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
161        DCHECK(arg_types_[i] == TRACE_VALUE_TYPE_INT);
162        std::string out = base::StringPrintf(
163            "C|%d|%s-%s", getpid(), name_, arg_names_[i]);
164        if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
165          StringAppendF(&out, "-%" PRIx64, static_cast<uint64>(id_));
166        StringAppendF(&out, "|%d|%s",
167                      static_cast<int>(arg_values_[i].as_int), category_group);
168        write(g_atrace_fd, out.c_str(), out.size());
169      }
170      break;
171
172    default:
173      // Do nothing.
174      break;
175  }
176}
177
178void TraceLog::AddClockSyncMetadataEvent() {
179  int atrace_fd = open(kATraceMarkerFile, O_WRONLY | O_APPEND);
180  if (atrace_fd == -1) {
181    PLOG(WARNING) << "Couldn't open " << kATraceMarkerFile;
182    return;
183  }
184
185  // Android's kernel trace system has a trace_marker feature: this is a file on
186  // debugfs that takes the written data and pushes it onto the trace
187  // buffer. So, to establish clock sync, we write our monotonic clock into that
188  // trace buffer.
189  TimeTicks now = TimeTicks::NowFromSystemTraceTime();
190  double now_in_seconds = now.ToInternalValue() / 1000000.0;
191  std::string marker = StringPrintf(
192      "trace_event_clock_sync: parent_ts=%f\n", now_in_seconds);
193  if (write(atrace_fd, marker.c_str(), marker.size()) == -1)
194    PLOG(WARNING) << "Couldn't write to " << kATraceMarkerFile;
195  close(atrace_fd);
196}
197
198}  // namespace debug
199}  // namespace base
200