Add events with custom timestamps and thread id to PPAPI dev tracing interface.

This exposes the AddTraceEventWithThreadIdAndTimestamp function, which may be
helpful for in-module profiling of NaCl applications.

BUG=none
NOTRY=true

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

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

9 files changed, 273 insertions, 25 deletions

diff --git a/ppapi/api/dev/ppb_trace_event_dev.idl b/ppapi/api/dev/ppb_trace_event_dev.idl
index ff01dea..8e483cd 100644
--- a/ppapi/api/dev/ppb_trace_event_dev.idl
+++ b/ppapi/api/dev/ppb_trace_event_dev.idl
@@ -9,9 +9,15 @@
  */
 
 label Chrome {
-  M25 = 0.1
+  M25 = 0.1,
+  M29 = 0.2
 };
 
+/**
+ * A trace event timestamp.
+ */
+typedef int64_t PP_TraceEventTime;
+
 interface PPB_Trace_Event_Dev {
   /**
    * Gets a pointer to a character for identifying a category name in the
@@ -43,6 +49,34 @@ interface PPB_Trace_Event_Dev {
       [in] uint8_t flags);
 
   /**
+   * Version of the above interface that allows specifying a custom thread id
+   * and timestamp. This is useful for when tracing data cannot be registered
+   * in real time. For example, this could be used by storing timestamps
+   * internally and then registering the events retroactively.
+   */
+  [version=0.2]
+  void AddTraceEventWithThreadIdAndTimestamp(
+      [in] int8_t phase,
+      [in] mem_t category_enabled,
+      [in] cstr_t name,
+      [in] uint64_t id,
+      [in] int32_t thread_id,
+      [in] PP_TraceEventTime timestamp,
+      [in] uint32_t num_args,
+      [in, size_as=num_args] str_t[] arg_names,
+      [in, size_as=num_args] uint8_t[] arg_types,
+      [in, size_as=num_args] uint64_t[] arg_values,
+      [in] uint8_t flags);
+
+  /**
+   * Get the current clock value. Since this uses the same function as the trace
+   * events use internally, it can be used to create events with explicit time
+   * stamps.
+   */
+  [version=0.2]
+  PP_TraceEventTime Now();
+
+  /**
    * Sets the thread name of the calling thread in the tracing system so it will
    * show up properly in chrome://tracing.
    */
diff --git a/ppapi/c/dev/ppb_trace_event_dev.h b/ppapi/c/dev/ppb_trace_event_dev.h
index 153fca8..0fb8cc5 100644
--- a/ppapi/c/dev/ppb_trace_event_dev.h
+++ b/ppapi/c/dev/ppb_trace_event_dev.h
@@ -3,7 +3,7 @@
  * found in the LICENSE file.
  */
 
-/* From dev/ppb_trace_event_dev.idl modified Wed Jan  2 16:11:35 2013. */
+/* From dev/ppb_trace_event_dev.idl modified Tue Jun 25 16:12:08 2013. */
 
 #ifndef PPAPI_C_DEV_PPB_TRACE_EVENT_DEV_H_
 #define PPAPI_C_DEV_PPB_TRACE_EVENT_DEV_H_
@@ -12,7 +12,8 @@
 #include "ppapi/c/pp_stdint.h"
 
 #define PPB_TRACE_EVENT_DEV_INTERFACE_0_1 "PPB_Trace_Event(Dev);0.1"
-#define PPB_TRACE_EVENT_DEV_INTERFACE PPB_TRACE_EVENT_DEV_INTERFACE_0_1
+#define PPB_TRACE_EVENT_DEV_INTERFACE_0_2 "PPB_Trace_Event(Dev);0.2"
+#define PPB_TRACE_EVENT_DEV_INTERFACE PPB_TRACE_EVENT_DEV_INTERFACE_0_2
 
 /**
  * @file
@@ -22,10 +23,22 @@
 
 
 /**
+ * @addtogroup Typedefs
+ * @{
+ */
+/**
+ * A trace event timestamp.
+ */
+typedef int64_t PP_TraceEventTime;
+/**
+ * @}
+ */
+
+/**
  * @addtogroup Interfaces
  * @{
  */
-struct PPB_Trace_Event_Dev_0_1 {
+struct PPB_Trace_Event_Dev_0_2 {
   /**
    * Gets a pointer to a character for identifying a category name in the
    * tracing system as well as for being able to early exit in client-side
@@ -53,13 +66,50 @@ struct PPB_Trace_Event_Dev_0_1 {
                         const uint64_t arg_values[],
                         uint8_t flags);
   /**
+   * Version of the above interface that allows specifying a custom thread id
+   * and timestamp. This is useful for when tracing data cannot be registered
+   * in real time. For example, this could be used by storing timestamps
+   * internally and then registering the events retroactively.
+   */
+  void (*AddTraceEventWithThreadIdAndTimestamp)(int8_t phase,
+                                                const void* category_enabled,
+                                                const char* name,
+                                                uint64_t id,
+                                                int32_t thread_id,
+                                                PP_TraceEventTime timestamp,
+                                                uint32_t num_args,
+                                                const char* arg_names[],
+                                                const uint8_t arg_types[],
+                                                const uint64_t arg_values[],
+                                                uint8_t flags);
+  /**
+   * Get the current clock value. Since this uses the same function as the trace
+   * events use internally, it can be used to create events with explicit time
+   * stamps.
+   */
+  PP_TraceEventTime (*Now)(void);
+  /**
    * Sets the thread name of the calling thread in the tracing system so it will
    * show up properly in chrome://tracing.
    */
   void (*SetThreadName)(const char* thread_name);
 };
 
-typedef struct PPB_Trace_Event_Dev_0_1 PPB_Trace_Event_Dev;
+typedef struct PPB_Trace_Event_Dev_0_2 PPB_Trace_Event_Dev;
+
+struct PPB_Trace_Event_Dev_0_1 {
+  void* (*GetCategoryEnabled)(const char* category_name);
+  void (*AddTraceEvent)(int8_t phase,
+                        const void* category_enabled,
+                        const char* name,
+                        uint64_t id,
+                        uint32_t num_args,
+                        const char* arg_names[],
+                        const uint8_t arg_types[],
+                        const uint64_t arg_values[],
+                        uint8_t flags);
+  void (*SetThreadName)(const char* thread_name);
+};
 /**
  * @}
  */
diff --git a/ppapi/native_client/src/untrusted/pnacl_irt_shim/pnacl_shim.c b/ppapi/native_client/src/untrusted/pnacl_irt_shim/pnacl_shim.c
index 844cd56..1e488ea 100644
--- a/ppapi/native_client/src/untrusted/pnacl_irt_shim/pnacl_shim.c
+++ b/ppapi/native_client/src/untrusted/pnacl_irt_shim/pnacl_shim.c
@@ -1864,6 +1864,8 @@ static void Pnacl_M28_PPB_Testing_Dev_SetMinimumArrayBufferSizeForShmem(PP_Insta
 
 /* Not generating wrapper methods for PPB_Trace_Event_Dev_0_1 */
 
+/* Not generating wrapper methods for PPB_Trace_Event_Dev_0_2 */
+
 /* Begin wrapper methods for PPB_TrueTypeFont_Dev_0_1 */
 
 static int32_t Pnacl_M26_PPB_TrueTypeFont_Dev_GetFontFamilies(PP_Instance instance, struct PP_ArrayOutput* output, struct PP_CompletionCallback* callback) {
@@ -4256,6 +4258,8 @@ struct PPB_Testing_Dev_0_92 Pnacl_Wrappers_PPB_Testing_Dev_0_92 = {
 
 /* Not generating wrapper interface for PPB_Trace_Event_Dev_0_1 */
 
+/* Not generating wrapper interface for PPB_Trace_Event_Dev_0_2 */
+
 struct PPB_TrueTypeFont_Dev_0_1 Pnacl_Wrappers_PPB_TrueTypeFont_Dev_0_1 = {
     .GetFontFamilies = (int32_t (*)(PP_Instance instance, struct PP_ArrayOutput output, struct PP_CompletionCallback callback))&Pnacl_M26_PPB_TrueTypeFont_Dev_GetFontFamilies,
     .GetFontsInFamily = (int32_t (*)(PP_Instance instance, struct PP_Var family, struct PP_ArrayOutput output, struct PP_CompletionCallback callback))&Pnacl_M26_PPB_TrueTypeFont_Dev_GetFontsInFamily,
diff --git a/ppapi/ppapi_sources.gypi b/ppapi/ppapi_sources.gypi
index 4394435d..9183de2 100644
--- a/ppapi/ppapi_sources.gypi
+++ b/ppapi/ppapi_sources.gypi
@@ -462,6 +462,8 @@
       'tests/test_tcp_socket.h',
       'tests/test_tcp_socket_private.cc',
       'tests/test_tcp_socket_private.h',
+      'tests/test_trace_event.cc',
+      'tests/test_trace_event.h',
       'tests/test_truetype_font.cc',
       'tests/test_truetype_font.h',
       'tests/test_udp_socket.cc',
diff --git a/ppapi/shared_impl/ppb_trace_event_impl.cc b/ppapi/shared_impl/ppb_trace_event_impl.cc
index 6803fc6..1433d4a 100644
--- a/ppapi/shared_impl/ppb_trace_event_impl.cc
+++ b/ppapi/shared_impl/ppb_trace_event_impl.cc
@@ -4,6 +4,7 @@
 
 #include "ppapi/shared_impl/ppb_trace_event_impl.h"
 
+#include "base/basictypes.h"
 #include "base/debug/trace_event.h"
 #include "ppapi/thunk/thunk.h"
 
@@ -28,15 +29,19 @@ void* TraceEventImpl::GetCategoryEnabled(const char* category_name) {
 }
 
 // static
-void TraceEventImpl::AddTraceEvent(int8_t phase,
-                                      const void* category_enabled,
-                                      const char* name,
-                                      uint64_t id,
-                                      uint32_t num_args,
-                                      const char* arg_names[],
-                                      const uint8_t arg_types[],
-                                      const uint64_t arg_values[],
-                                      uint8_t flags) {
+void TraceEventImpl::AddTraceEvent(
+    int8_t phase,
+    const void* category_enabled,
+    const char* name,
+    uint64_t id,
+    uint32_t num_args,
+    const char* arg_names[],
+    const uint8_t arg_types[],
+    const uint64_t arg_values[],
+    uint8_t flags) {
+
+  COMPILE_ASSERT(sizeof(unsigned long long) == sizeof(uint64_t), msg);
+
   base::debug::TraceLog::GetInstance()->AddTraceEvent(phase,
       static_cast<const unsigned char*>(category_enabled), name, id, num_args,
       arg_names, arg_types,
@@ -48,15 +53,54 @@ void TraceEventImpl::AddTraceEvent(int8_t phase,
 }
 
 // static
+void TraceEventImpl::AddTraceEventWithThreadIdAndTimestamp(
+    int8_t phase,
+    const void* category_enabled,
+    const char* name,
+    uint64_t id,
+    int32_t thread_id,
+    int64_t timestamp,
+    uint32_t num_args,
+    const char* arg_names[],
+    const uint8_t arg_types[],
+    const uint64_t arg_values[],
+    uint8_t flags) {
+  base::debug::TraceLog::GetInstance()->AddTraceEventWithThreadIdAndTimestamp(
+      phase,
+      static_cast<const unsigned char*>(category_enabled), name, id,
+      thread_id,
+      base::TimeTicks::FromInternalValue(timestamp),
+      num_args, arg_names, arg_types,
+      // This cast is necessary for LP64 systems, where uint64_t is defined as
+      // an unsigned long int, but trace_event internals are hermetic and
+      // accepts an |unsigned long long*|.  The pointer types are compatible but
+      // the compiler throws an error without an explicit cast.
+      reinterpret_cast<const unsigned long long*>(arg_values), NULL, flags);
+}
+
+// static
+int64_t TraceEventImpl::Now() {
+  return base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
+}
+
+// static
 void TraceEventImpl::SetThreadName(const char* thread_name) {
   base::PlatformThread::SetName(thread_name);
 }
 
 namespace {
 
-const PPB_Trace_Event_Dev g_ppb_trace_event_thunk = {
+const PPB_Trace_Event_Dev_0_1 g_ppb_trace_event_thunk_0_1 = {
+  &TraceEventImpl::GetCategoryEnabled,
+  &TraceEventImpl::AddTraceEvent,
+  &TraceEventImpl::SetThreadName,
+};
+
+const PPB_Trace_Event_Dev_0_2 g_ppb_trace_event_thunk_0_2 = {
   &TraceEventImpl::GetCategoryEnabled,
   &TraceEventImpl::AddTraceEvent,
+  &TraceEventImpl::AddTraceEventWithThreadIdAndTimestamp,
+  &TraceEventImpl::Now,
   &TraceEventImpl::SetThreadName,
 };
 
@@ -68,7 +112,11 @@ namespace ppapi {
 namespace thunk {
 
 const PPB_Trace_Event_Dev_0_1* GetPPB_Trace_Event_Dev_0_1_Thunk() {
-  return &g_ppb_trace_event_thunk;
+  return &g_ppb_trace_event_thunk_0_1;
+}
+
+const PPB_Trace_Event_Dev_0_2* GetPPB_Trace_Event_Dev_0_2_Thunk() {
+  return &g_ppb_trace_event_thunk_0_2;
 }
 
 }  // namespace thunk
diff --git a/ppapi/shared_impl/ppb_trace_event_impl.h b/ppapi/shared_impl/ppb_trace_event_impl.h
index 21a77ac..6df7cc8 100644
--- a/ppapi/shared_impl/ppb_trace_event_impl.h
+++ b/ppapi/shared_impl/ppb_trace_event_impl.h
@@ -18,15 +18,29 @@ namespace ppapi {
 class PPAPI_SHARED_EXPORT TraceEventImpl {
  public:
   static void* GetCategoryEnabled(const char* category_name);
-  static void AddTraceEvent(int8_t phase,
-                               const void* category_enabled,
-                               const char* name,
-                               uint64_t id,
-                               uint32_t num_args,
-                               const char* arg_names[],
-                               const uint8_t arg_types[],
-                               const uint64_t arg_values[],
-                               uint8_t flags);
+  static void AddTraceEvent(
+      int8_t phase,
+      const void* category_enabled,
+      const char* name,
+      uint64_t id,
+      uint32_t num_args,
+      const char* arg_names[],
+      const uint8_t arg_types[],
+      const uint64_t arg_values[],
+      uint8_t flags);
+  static void AddTraceEventWithThreadIdAndTimestamp(
+      int8_t phase,
+      const void* category_enabled,
+      const char* name,
+      uint64_t id,
+      int32_t thread_id,
+      int64_t timestamp,
+      uint32_t num_args,
+      const char* arg_names[],
+      const uint8_t arg_types[],
+      const uint64_t arg_values[],
+      uint8_t flags);
+  static int64_t Now();
   static void SetThreadName(const char* thread_name);
 };
 
diff --git a/ppapi/tests/test_trace_event.cc b/ppapi/tests/test_trace_event.cc
new file mode 100644
index 0000000..b58bf9b
--- /dev/null
+++ b/ppapi/tests/test_trace_event.cc
@@ -0,0 +1,65 @@
+// Copyright 2013 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 "ppapi/tests/test_trace_event.h"
+
+#include "ppapi/cpp/module.h"
+#include "ppapi/tests/testing_instance.h"
+
+REGISTER_TEST_CASE(TraceEvent);
+
+TestTraceEvent::TestTraceEvent(TestingInstance* instance)
+    : TestCase(instance),
+      interface_(NULL) {
+}
+
+bool TestTraceEvent::Init() {
+  interface_ = static_cast<const PPB_Trace_Event_Dev*>(
+      pp::Module::Get()->GetBrowserInterface(PPB_TRACE_EVENT_DEV_INTERFACE));
+  return !!interface_;
+}
+
+void TestTraceEvent::RunTests(const std::string& filter) {
+  RUN_TEST(Smoke, filter);
+  RUN_TEST(SmokeWithTimestamps, filter);
+  RUN_TEST(Clock, filter);
+}
+
+std::string TestTraceEvent::TestSmoke() {
+  // This test does not verify the log message actually reaches dev tracing, but
+  // it does test that the interface exists and that it can be called without
+  // crashing.
+  const void* cat_enabled = interface_->GetCategoryEnabled("bar");
+  interface_->AddTraceEvent('B', cat_enabled, "foo", 0, 0, NULL, NULL, NULL, 0);
+  interface_->AddTraceEvent('E', cat_enabled, "foo", 0, 0, NULL, NULL, NULL, 0);
+  PASS();
+}
+
+std::string TestTraceEvent::TestSmokeWithTimestamps() {
+  // This test does not verify the log message actually reaches dev tracing, but
+  // it does test that the interface exists and that it can be called without
+  // crashing.
+  const void* cat_enabled = interface_->GetCategoryEnabled("bar");
+  interface_->AddTraceEventWithThreadIdAndTimestamp(
+    'B', cat_enabled, "foo", 0, 0, 42, 0, NULL, NULL, NULL, 0);
+  interface_->AddTraceEventWithThreadIdAndTimestamp(
+    'B', cat_enabled, "foo", 0, 1, 43, 0, NULL, NULL, NULL, 0);
+  interface_->AddTraceEventWithThreadIdAndTimestamp(
+    'E', cat_enabled, "foo", 0, 0, 44, 0, NULL, NULL, NULL, 0);
+  interface_->AddTraceEventWithThreadIdAndTimestamp(
+    'E', cat_enabled, "foo", 0, 1, 45, 0, NULL, NULL, NULL, 0);
+  PASS();
+}
+
+std::string TestTraceEvent::TestClock() {
+  int64_t last = interface_->Now();
+
+  for(int i=0; i<5; ++i){
+    int64_t next = interface_->Now();
+    ASSERT_LE(last, next);
+    last = next;
+  }
+
+  PASS();
+}
\ No newline at end of file
diff --git a/ppapi/tests/test_trace_event.h b/ppapi/tests/test_trace_event.h
new file mode 100644
index 0000000..c3278a3
--- /dev/null
+++ b/ppapi/tests/test_trace_event.h
@@ -0,0 +1,29 @@
+// Copyright 2013 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.
+
+#ifndef PPAPI_TESTS_TEST_TRACE_EVENT_H_
+#define PPAPI_TESTS_TEST_TRACE_EVENT_H_
+
+#include <string>
+
+#include "ppapi/c/dev/ppb_trace_event_dev.h"
+#include "ppapi/tests/test_case.h"
+
+class TestTraceEvent : public TestCase {
+ public:
+  explicit TestTraceEvent(TestingInstance* instance);
+
+ private:
+  // TestCase implementation.
+  virtual bool Init();
+  virtual void RunTests(const std::string& filter);
+
+  std::string TestSmoke();
+  std::string TestSmokeWithTimestamps();
+  std::string TestClock();
+
+  const PPB_Trace_Event_Dev* interface_;
+};
+
+#endif  // PPAPI_TESTS_TEST_TRACE_EVENT_H_
diff --git a/ppapi/thunk/interfaces_ppb_public_dev.h b/ppapi/thunk/interfaces_ppb_public_dev.h
index 23a6039..8fa7a93 100644
--- a/ppapi/thunk/interfaces_ppb_public_dev.h
+++ b/ppapi/thunk/interfaces_ppb_public_dev.h
@@ -41,6 +41,8 @@ PROXIED_IFACE(NoAPIName, PPB_VIEW_DEV_INTERFACE_0_1,
 UNPROXIED_IFACE(PPB_Instance, PPB_ZOOM_DEV_INTERFACE_0_2, PPB_Zoom_Dev_0_2)
 PROXIED_IFACE(PPB_Instance, PPB_TRACE_EVENT_DEV_INTERFACE_0_1,
               PPB_Trace_Event_Dev_0_1)
+PROXIED_IFACE(PPB_Instance, PPB_TRACE_EVENT_DEV_INTERFACE_0_2,
+              PPB_Trace_Event_Dev_0_2)
 
 #if !defined(OS_NACL)
 PROXIED_API(PPB_Buffer)