Make Chrome Trace work with Android ATrace.

It uses "view" tag in the ATrace to enable tracing Chrome events.

Steps to grab a trace:

1. Enable trace of "view" in the Developer options.

2. adb shell stop; adb shell start
  or if the system itself supports changing trace settings without restart:
   adb shell am force-stop com.android.chrome (for stable version)
   adb shell am force-stop com.google.android.apps.chrome (for beta/dev version)

3. Start Chrome

4. // grab a 5-seconds trace, the result is in trace.html
   third_party/android_tools/sdk/tools/systrace/systrace.py -t 5 -f -w

Note: the intent triggered Chrome trace still works with this patch.

BUG=

Review URL: https://chromiumcodereview.appspot.com/11345019

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@165507 0039d316-1c4b-4281-b951-d872f2087c98

6 files changed, 232 insertions, 90 deletions

diff --git a/base/base.gypi b/base/base.gypi
index 905dd4c..b8b5fa0 100644
--- a/base/base.gypi
+++ b/base/base.gypi
@@ -114,6 +114,7 @@
           'debug/stack_trace_win.cc',
           'debug/trace_event.cc',
           'debug/trace_event.h',
+          'debug/trace_event_android.cc',
           'debug/trace_event_impl.cc',
           'debug/trace_event_impl.h',
           'debug/trace_event_win.cc',
diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc
index be77d5a..4298bba 100644
--- a/base/debug/trace_event.cc
+++ b/base/debug/trace_event.cc
@@ -15,7 +15,7 @@ void TraceEndOnScopeClose::Initialize(const unsigned char* category_enabled,
 
 void TraceEndOnScopeClose::AddEventIfEnabled() {
   // Only called when p_data_ is non-null.
-  if (*p_data_->category_enabled) {
+  if (TRACE_EVENT_API_IS_ATRACE_ENABLED() || *p_data_->category_enabled) {
     TRACE_EVENT_API_ADD_TRACE_EVENT(
         TRACE_EVENT_PHASE_END,
         p_data_->category_enabled,
@@ -39,7 +39,7 @@ void TraceEndOnScopeCloseThreshold::Initialize(
 
 void TraceEndOnScopeCloseThreshold::AddEventIfEnabled() {
   // Only called when p_data_ is non-null.
-  if (*p_data_->category_enabled) {
+  if (TRACE_EVENT_API_IS_ATRACE_ENABLED() || *p_data_->category_enabled) {
     TRACE_EVENT_API_ADD_TRACE_EVENT(
         TRACE_EVENT_PHASE_END,
         p_data_->category_enabled,
diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index 07863ad..f78bb3c 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -597,6 +597,14 @@
 #define TRACE_EVENT_API_ADD_TRACE_EVENT \
     base::debug::TraceLog::GetInstance()->AddTraceEvent
 
+// Checks if Android ATrace is enabled.
+#if defined(OS_ANDROID)
+#define TRACE_EVENT_API_IS_ATRACE_ENABLED() \
+    base::debug::TraceLog::IsATraceEnabled()
+#else
+#define TRACE_EVENT_API_IS_ATRACE_ENABLED() false
+#endif
+
 ////////////////////////////////////////////////////////////////////////////////
 
 // Implementation detail: trace event macros create temporary variables
@@ -626,12 +634,17 @@
               INTERNAL_TRACE_EVENT_UID(catstatic))); \
     }
 
+// Implementation detail: internal macro to check if Android ATrace or the
+// current category (using the current static category variable) is enabled.
+#define INTERNAL_TRACE_EVENT_IS_ATRACE_OR_CATEGORY_ENABLED() \
+    TRACE_EVENT_API_IS_ATRACE_ENABLED() || *INTERNAL_TRACE_EVENT_UID(catstatic)
+
 // Implementation detail: internal macro to create static category and add
 // event if the category is enabled.
 #define INTERNAL_TRACE_EVENT_ADD(phase, category, name, flags, ...) \
     do { \
       INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
-      if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \
+      if (INTERNAL_TRACE_EVENT_IS_ATRACE_OR_CATEGORY_ENABLED()) { \
         trace_event_internal::AddTraceEvent( \
             phase, INTERNAL_TRACE_EVENT_UID(catstatic), name, \
             trace_event_internal::kNoEventId, flags, ##__VA_ARGS__); \
@@ -645,7 +658,7 @@
     INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
     trace_event_internal::TraceEndOnScopeClose \
         INTERNAL_TRACE_EVENT_UID(profileScope); \
-    if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \
+    if (INTERNAL_TRACE_EVENT_IS_ATRACE_OR_CATEGORY_ENABLED()) { \
       trace_event_internal::AddTraceEvent( \
           TRACE_EVENT_PHASE_BEGIN, \
           INTERNAL_TRACE_EVENT_UID(catstatic), \
@@ -663,7 +676,7 @@
     INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
     trace_event_internal::TraceEndOnScopeCloseThreshold \
         INTERNAL_TRACE_EVENT_UID(profileScope); \
-    if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \
+    if (INTERNAL_TRACE_EVENT_IS_ATRACE_OR_CATEGORY_ENABLED()) { \
       int INTERNAL_TRACE_EVENT_UID(begin_event_id) = \
         trace_event_internal::AddTraceEvent( \
             TRACE_EVENT_PHASE_BEGIN, \
@@ -681,7 +694,7 @@
                                          ...) \
     do { \
       INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
-      if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \
+      if (INTERNAL_TRACE_EVENT_IS_ATRACE_OR_CATEGORY_ENABLED()) { \
         unsigned char trace_event_flags = flags | TRACE_EVENT_FLAG_HAS_ID; \
         trace_event_internal::TraceID trace_event_trace_id( \
             id, &trace_event_flags); \
diff --git a/base/debug/trace_event_android.cc b/base/debug/trace_event_android.cc
new file mode 100644
index 0000000..0cfa622
--- /dev/null
+++ b/base/debug/trace_event_android.cc
@@ -0,0 +1,140 @@
+// 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_impl.h"
+
+#include <fcntl.h>
+
+#include "base/debug/trace_event.h"
+#include "base/file_util.h"
+#include "base/format_macros.h"
+#include "base/logging.h"
+#include "base/stringprintf.h"
+
+namespace {
+
+int g_atrace_fd = -1;
+const char* kATraceMarkerFile = "/sys/kernel/debug/tracing/trace_marker";
+
+}  // namespace
+
+namespace base {
+namespace debug {
+
+// static
+void TraceLog::InitATrace() {
+  DCHECK(g_atrace_fd == -1);
+  g_atrace_fd = open(kATraceMarkerFile, O_WRONLY | O_APPEND);
+  if (g_atrace_fd == -1)
+    LOG(WARNING) << "Couldn't open " << kATraceMarkerFile;
+}
+
+// static
+bool TraceLog::IsATraceEnabled() {
+  return g_atrace_fd != -1;
+}
+
+void TraceLog::SendToATrace(char phase,
+                            const char* category,
+                            const char* name,
+                            int num_args,
+                            const char** arg_names,
+                            const unsigned char* arg_types,
+                            const unsigned long long* arg_values) {
+  if (!IsATraceEnabled())
+    return;
+
+  switch (phase) {
+    case TRACE_EVENT_PHASE_BEGIN:
+    case TRACE_EVENT_PHASE_INSTANT: {
+      std::string out = StringPrintf("B|%d|%s-%s", getpid(), category, name);
+      for (int i = 0; i < num_args; ++i) {
+        out += '|';
+        out += arg_names[i];
+        out += '=';
+        TraceEvent::TraceValue value;
+        value.as_uint = arg_values[i];
+        std::string::size_type value_start = out.length();
+        TraceEvent::AppendValueAsJSON(arg_types[i], value, &out);
+        // Remove the quotes which may confuse the atrace script.
+        ReplaceSubstringsAfterOffset(&out, value_start, "\\\"", "'");
+        ReplaceSubstringsAfterOffset(&out, value_start, "\"", "");
+      }
+      write(g_atrace_fd, out.c_str(), out.size());
+
+      if (phase != TRACE_EVENT_PHASE_INSTANT)
+        break;
+      // Fall through. Simulate an instance event with a pair of begin/end.
+    }
+    case TRACE_EVENT_PHASE_END: {
+      // Though a single 'E' is enough, here append pid and name so that
+      // unpaired events can be found easily.
+      std::string out = StringPrintf("E|%d|%s-%s", getpid(), category, name);
+      write(g_atrace_fd, out.c_str(), out.size());
+      break;
+    }
+    case TRACE_EVENT_PHASE_COUNTER:
+      for (int i = 0; i < num_args; ++i) {
+        DCHECK(arg_types[i] == TRACE_VALUE_TYPE_INT);
+        std::string out = StringPrintf(
+            "C|%d|%s-%s-%s|%d",
+            getpid(), category, name,
+            arg_names[i], static_cast<int>(arg_values[i]));
+        write(g_atrace_fd, out.c_str(), out.size());
+      }
+      break;
+
+    default:
+      // Do nothing.
+      break;
+  }
+}
+
+void TraceLog::AddClockSyncMetadataEvents() {
+  // Since Android does not support sched_setaffinity, we cannot establish clock
+  // sync unless the scheduler clock is set to global. If the trace_clock file
+  // can't be read, we will assume the kernel doesn't support tracing and do
+  // nothing.
+  std::string clock_mode;
+  if (!file_util::ReadFileToString(
+      FilePath("/sys/kernel/debug/tracing/trace_clock"), &clock_mode))
+    return;
+
+  if (clock_mode != "local [global]\n") {
+    DLOG(WARNING) <<
+        "The kernel's tracing clock must be set to global in order for " <<
+        "trace_event to be synchronized with . Do this by\n" <<
+        "  echo global > /sys/kerel/debug/tracing/trace_clock";
+    return;
+  }
+
+  int atrace_fd = g_atrace_fd;
+  if (atrace_fd == -1) {
+    // This function may be called when atrace is not enabled.
+    atrace_fd = open(kATraceMarkerFile, O_WRONLY | O_APPEND);
+    if (atrace_fd == -1) {
+      LOG(WARNING) << "Couldn't open " << kATraceMarkerFile;
+      return;
+    }
+  }
+
+  // Android's kernel trace system has a trace_marker feature: this is a file on
+  // debugfs that takes the written data and pushes it onto the trace
+  // buffer. So, to establish clock sync, we write our monotonic clock into that
+  // trace buffer.
+  TimeTicks now = TimeTicks::NowFromSystemTraceTime();
+  double now_in_seconds = now.ToInternalValue() / 1000000.0;
+  std::string marker = StringPrintf(
+      "trace_event_clock_sync: parent_ts=%f\n", now_in_seconds);
+  if (write(atrace_fd, marker.c_str(), marker.size()) != 0) {
+    DLOG(WARNING) << "Couldn't write to " << kATraceMarkerFile << ": "
+                  << strerror(errno);
+  }
+
+  if (g_atrace_fd == -1)
+    close(atrace_fd);
+}
+
+}  // namespace debug
+}  // namespace base
diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc
index 13b6a97..fa23def 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -9,7 +9,6 @@
 #include "base/bind.h"
 #include "base/debug/leak_annotations.h"
 #include "base/debug/trace_event.h"
-#include "base/file_util.h"
 #include "base/format_macros.h"
 #include "base/lazy_instance.h"
 #include "base/memory/singleton.h"
@@ -70,50 +69,6 @@ int g_category_index = 3; // skip initial 3 categories
 LazyInstance<ThreadLocalPointer<const char> >::Leaky
     g_current_thread_name = LAZY_INSTANCE_INITIALIZER;
 
-void AppendValueAsJSON(unsigned char type,
-                       TraceEvent::TraceValue value,
-                       std::string* out) {
-  std::string::size_type start_pos;
-  switch (type) {
-    case TRACE_VALUE_TYPE_BOOL:
-      *out += value.as_bool ? "true" : "false";
-      break;
-    case TRACE_VALUE_TYPE_UINT:
-      StringAppendF(out, "%" PRIu64, static_cast<uint64>(value.as_uint));
-      break;
-    case TRACE_VALUE_TYPE_INT:
-      StringAppendF(out, "%" PRId64, static_cast<int64>(value.as_int));
-      break;
-    case TRACE_VALUE_TYPE_DOUBLE:
-      StringAppendF(out, "%f", value.as_double);
-      break;
-    case TRACE_VALUE_TYPE_POINTER:
-      // JSON only supports double and int numbers.
-      // So as not to lose bits from a 64-bit pointer, output as a hex string.
-      StringAppendF(out, "\"%" PRIx64 "\"", static_cast<uint64>(
-                                     reinterpret_cast<intptr_t>(
-                                     value.as_pointer)));
-      break;
-    case TRACE_VALUE_TYPE_STRING:
-    case TRACE_VALUE_TYPE_COPY_STRING:
-      *out += "\"";
-      start_pos = out->size();
-      *out += value.as_string ? value.as_string : "NULL";
-      // insert backslash before special characters for proper json format.
-      while ((start_pos = out->find_first_of("\\\"", start_pos)) !=
-             std::string::npos) {
-        out->insert(start_pos, 1, '\\');
-        // skip inserted escape character and following character.
-        start_pos += 2;
-      }
-      *out += "\"";
-      break;
-    default:
-      NOTREACHED() << "Don't know how to print this value";
-      break;
-  }
-}
-
 }  // namespace
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -225,6 +180,51 @@ TraceEvent::TraceEvent(int thread_id,
 TraceEvent::~TraceEvent() {
 }
 
+// static
+void TraceEvent::AppendValueAsJSON(unsigned char type,
+                                   TraceEvent::TraceValue value,
+                                   std::string* out) {
+  std::string::size_type start_pos;
+  switch (type) {
+    case TRACE_VALUE_TYPE_BOOL:
+      *out += value.as_bool ? "true" : "false";
+      break;
+    case TRACE_VALUE_TYPE_UINT:
+      StringAppendF(out, "%" PRIu64, static_cast<uint64>(value.as_uint));
+      break;
+    case TRACE_VALUE_TYPE_INT:
+      StringAppendF(out, "%" PRId64, static_cast<int64>(value.as_int));
+      break;
+    case TRACE_VALUE_TYPE_DOUBLE:
+      StringAppendF(out, "%f", value.as_double);
+      break;
+    case TRACE_VALUE_TYPE_POINTER:
+      // JSON only supports double and int numbers.
+      // So as not to lose bits from a 64-bit pointer, output as a hex string.
+      StringAppendF(out, "\"%" PRIx64 "\"", static_cast<uint64>(
+                                     reinterpret_cast<intptr_t>(
+                                     value.as_pointer)));
+      break;
+    case TRACE_VALUE_TYPE_STRING:
+    case TRACE_VALUE_TYPE_COPY_STRING:
+      *out += "\"";
+      start_pos = out->size();
+      *out += value.as_string ? value.as_string : "NULL";
+      // insert backslash before special characters for proper json format.
+      while ((start_pos = out->find_first_of("\\\"", start_pos)) !=
+             std::string::npos) {
+        out->insert(start_pos, 1, '\\');
+        // skip inserted escape character and following character.
+        start_pos += 2;
+      }
+      *out += "\"";
+      break;
+    default:
+      NOTREACHED() << "Don't know how to print this value";
+      break;
+  }
+}
+
 void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events,
                                     size_t start,
                                     size_t count,
@@ -543,7 +543,9 @@ void TraceLog::SetDisabled() {
   for (int i = 0; i < g_category_index; i++)
     g_category_enabled[i] = 0;
   AddThreadNameMetadataEvents();
+#if defined(OS_ANDROID)
   AddClockSyncMetadataEvents();
+#endif
 }
 
 void TraceLog::SetEnabled(bool enabled) {
@@ -604,6 +606,12 @@ int TraceLog::AddTraceEvent(char phase,
                             long long threshold,
                             unsigned char flags) {
   DCHECK(name);
+
+#if defined(OS_ANDROID)
+  SendToATrace(phase, GetCategoryName(category_enabled), name,
+               num_args, arg_names, arg_types, arg_values);
+#endif
+
   TimeTicks now = TimeTicks::NowFromSystemTraceTime();
   NotificationHelper notifier(this);
   int ret_begin_id = -1;
@@ -741,45 +749,6 @@ void TraceLog::CancelWatchEvent() {
   watch_event_name_ = "";
 }
 
-void TraceLog::AddClockSyncMetadataEvents() {
-#if defined(OS_ANDROID)
-  // Since Android does not support sched_setaffinity, we cannot establish clock
-  // sync unless the scheduler clock is set to global. If the trace_clock file
-  // can't be read, we will assume the kernel doesn't support tracing and do
-  // nothing.
-  std::string clock_mode;
-  if (!file_util::ReadFileToString(
-          FilePath("/sys/kernel/debug/tracing/trace_clock"),
-          &clock_mode))
-    return;
-
-  if (clock_mode != "local [global]\n") {
-    DLOG(WARNING) <<
-        "The kernel's tracing clock must be set to global in order for " <<
-        "trace_event to be synchronized with . Do this by\n" <<
-        "  echo global > /sys/kerel/debug/tracing/trace_clock";
-    return;
-  }
-
-  // Android's kernel trace system has a trace_marker feature: this is a file on
-  // debugfs that takes the written data and pushes it onto the trace
-  // buffer. So, to establish clock sync, we write our monotonic clock into that
-  // trace buffer.
-  TimeTicks now = TimeTicks::NowFromSystemTraceTime();
-
-  double now_in_seconds = now.ToInternalValue() / 1000000.0;
-  std::string marker =
-      StringPrintf("trace_event_clock_sync: parent_ts=%f\n",
-                   now_in_seconds);
-  if (file_util::WriteFile(
-          FilePath("/sys/kernel/debug/tracing/trace_marker"),
-          marker.c_str(), marker.size()) == -1) {
-    DLOG(WARNING) << "Couldn't write to /sys/kernel/debug/tracing/trace_marker";
-    return;
-  }
-#endif
-}
-
 void TraceLog::AddThreadNameMetadataEvents() {
   lock_.AssertAcquired();
   for(base::hash_map<int, std::string>::iterator it = thread_names_.begin();
diff --git a/base/debug/trace_event_impl.h b/base/debug/trace_event_impl.h
index 62a81d8..c186373 100644
--- a/base/debug/trace_event_impl.h
+++ b/base/debug/trace_event_impl.h
@@ -82,6 +82,10 @@ class BASE_EXPORT TraceEvent {
                                  std::string* out);
   void AppendAsJSON(std::string* out) const;
 
+  static void AppendValueAsJSON(unsigned char type,
+                                TraceValue value,
+                                std::string* out);
+
   TimeTicks timestamp() const { return timestamp_; }
 
   // Exposed for unittesting:
@@ -204,6 +208,11 @@ class BASE_EXPORT TraceLog {
   void SetEnabled(bool enabled);
   bool IsEnabled() { return enabled_; }
 
+#if defined(OS_ANDROID)
+  static void InitATrace();
+  static bool IsATraceEnabled();
+#endif
+
   // Enabled state listeners give a callback when tracing is enabled or
   // disabled. This can be used to tie into other library's tracing systems
   // on-demand.
@@ -334,7 +343,17 @@ class BASE_EXPORT TraceLog {
   ~TraceLog();
   const unsigned char* GetCategoryEnabledInternal(const char* name);
   void AddThreadNameMetadataEvents();
+
+#if defined(OS_ANDROID)
+  void SendToATrace(char phase,
+                    const char* category,
+                    const char* name,
+                    int num_args,
+                    const char** arg_names,
+                    const unsigned char* arg_types,
+                    const unsigned long long* arg_values);
   void AddClockSyncMetadataEvents();
+#endif
 
   // TODO(nduca): switch to per-thread trace buffers to reduce thread
   // synchronization.