Home | History | Annotate | Download | only in debug 
      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 
     15 namespace {
     16 
     17 int g_atrace_fd = -1;
     18 const char* kATraceMarkerFile = "/sys/kernel/debug/tracing/trace_marker";
     19 
     20 void 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 
     61 void 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 
     68 void 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 
     77 namespace base {
     78 namespace 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 
     90 void 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 
    104 void 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 
    122 void 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 
    178 void 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