Adding raw tracing to trace framework.

base/debug/trace_event.h

 // 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.
 
 // This header is designed to give you trace_event macros without specifying
 // how the events actually get collected and stored. If you need to expose trace
 // event to some other universe, you can copy-and-paste this file,
 // implement the TRACE_EVENT_API macros, and do any other necessary fixup for
 // the target platform. The end result is that multiple libraries can funnel
 // events through to a shared trace event collector.
@@ skipping 247 matching lines @@
         category, name, TRACE_EVENT_FLAG_COPY)
 #define TRACE_EVENT_COPY_BEGIN1(category, name, arg1_name, arg1_val) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \
         category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val)
 #define TRACE_EVENT_COPY_BEGIN2(category, name, arg1_name, arg1_val, \
         arg2_name, arg2_val) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \
         category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, \
         arg2_name, arg2_val)
 
+// Similar to TRACE_EVENT_BEGINx but with a custom |at| timestamp provided.
+// - |id| is used to match the _BEGIN event with the _END event.
+//   Events are considered to match if their category, name and id values all
+//   match. |id| must either be a pointer or an integer value up to 64 bits. If
+//   it's a pointer, the bits will be xored with a hash of the process ID so
+//   that the same pointer on two different processes will not collide.
+#define TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(category, \
+        name, id, tid, ts) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
+        TRACE_EVENT_PHASE_ASYNC_BEGIN, category, name, id, tid, ts, \
+        TRACE_EVENT_FLAG_NONE)
+#define TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0( \
+        category, name, id, tid, ts) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
+        TRACE_EVENT_PHASE_ASYNC_BEGIN, category, name, id, tid, ts, \
+        TRACE_EVENT_FLAG_COPY)
+
 // Records a single END event for "name" immediately. If the category
 // is not enabled, then this does nothing.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_EVENT_END0(category, name) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \
         category, name, TRACE_EVENT_FLAG_NONE)
 #define TRACE_EVENT_END1(category, name, arg1_name, arg1_val) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \
         category, name, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val)
 #define TRACE_EVENT_END2(category, name, arg1_name, arg1_val, \
         arg2_name, arg2_val) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \
         category, name, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val, \
         arg2_name, arg2_val)
 #define TRACE_EVENT_COPY_END0(category, name) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \
         category, name, TRACE_EVENT_FLAG_COPY)
 #define TRACE_EVENT_COPY_END1(category, name, arg1_name, arg1_val) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \
         category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val)
 #define TRACE_EVENT_COPY_END2(category, name, arg1_name, arg1_val, \
         arg2_name, arg2_val) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \
         category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, \
         arg2_name, arg2_val)
 
+// Similar to TRACE_EVENT_ENDx but with a custom |at| timestamp provided.
+// - |id| is used to match the _BEGIN event with the _END event.
+//   Events are considered to match if their category, name and id values all
+//   match. |id| must either be a pointer or an integer value up to 64 bits. If
+//   it's a pointer, the bits will be xored with a hash of the process ID so
+//   that the same pointer on two different processes will not collide.
+#define TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(category, \
+        name, id, tid, ts) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
+        TRACE_EVENT_PHASE_ASYNC_END, category, name, id, tid, ts, \
+        TRACE_EVENT_FLAG_NONE)
+#define TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0( \
+        category, name, id, tid, ts) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
+        TRACE_EVENT_PHASE_ASYNC_END, category, name, id, tid, ts, \
+        TRACE_EVENT_FLAG_COPY)
+
 // Records the value of a counter called "name" immediately. Value
 // must be representable as a 32 bit integer.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
 #define TRACE_COUNTER1(category, name, value) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_COUNTER, \
         category, name, TRACE_EVENT_FLAG_NONE, \
         "value", static_cast<int>(value))
 #define TRACE_COPY_COUNTER1(category, name, value) \
     INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_COUNTER, \
@@ skipping 249 matching lines @@
 // unsigned char is non-zero, tracing is enabled. If tracing is enabled,
 // TRACE_EVENT_API_ADD_TRACE_EVENT can be called. It's OK if tracing is disabled
 // between the load of the tracing state and the call to
 // TRACE_EVENT_API_ADD_TRACE_EVENT, because this flag only provides an early out
 // for best performance when tracing is disabled.
 // const unsigned char*
 //     TRACE_EVENT_API_GET_CATEGORY_ENABLED(const char* category_name)
 #define TRACE_EVENT_API_GET_CATEGORY_ENABLED \
     base::debug::TraceLog::GetCategoryEnabled
 
-// Add a trace event to the platform tracing system.
-// void TRACE_EVENT_API_ADD_TRACE_EVENT(
+// Add a trace event to the platform tracing system. Returns thresholdBeginId
+// for use in a corresponding end TRACE_EVENT_API_ADD_TRACE_EVENT call.
+// int TRACE_EVENT_API_ADD_TRACE_EVENT(
 //                    char phase,
 //                    const unsigned char* category_enabled,
 //                    const char* name,
 //                    unsigned long long id,
+//                    int thread_id,
+//                    int64 timestamp,
 //                    int num_args,
 //                    const char** arg_names,
 //                    const unsigned char* arg_types,
 //                    const unsigned long long* arg_values,
 //                    unsigned char flags)
 #define TRACE_EVENT_API_ADD_TRACE_EVENT \
     base::debug::TraceLog::GetInstance()->AddTraceEvent
 
 ////////////////////////////////////////////////////////////////////////////////
 
@@ skipping 63 matching lines @@
         unsigned char trace_event_flags = flags | TRACE_EVENT_FLAG_HAS_ID; \
         trace_event_internal::TraceID trace_event_trace_id( \
             id, &trace_event_flags); \
         trace_event_internal::AddTraceEvent( \
             phase, INTERNAL_TRACE_EVENT_UID(catstatic), \
             name, trace_event_trace_id.data(), trace_event_flags, \
             ##__VA_ARGS__); \
       } \
     } while (0)
 
+// Implementation detail: internal macro to create static category and add
+// event if the category is enabled.
+#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(phase, category, \
+        name, id, tid, ts, flags, ...) \
+    do { \
+      INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
+      if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \
+        unsigned char trace_event_flags = flags | TRACE_EVENT_FLAG_HAS_ID; \
+        trace_event_internal::TraceID trace_event_trace_id( \
+            id, &trace_event_flags); \
+        trace_event_internal::AddTraceEvent( \
+            phase, INTERNAL_TRACE_EVENT_UID(catstatic), \
+            name, trace_event_trace_id.data(), tid, ts, \
+            trace_event_flags, ##__VA_ARGS__); \
+      } \
+    } while (0)
+
 // Notes regarding the following definitions:
 // New values can be added and propagated to third party libraries, but existing
 // definitions must never be changed, because third party libraries may use old
 // definitions.
 
 // Phase indicates the nature of an event entry. E.g. part of a begin/end pair.
 #define TRACE_EVENT_PHASE_BEGIN    ('B')
 #define TRACE_EVENT_PHASE_END      ('E')
 #define TRACE_EVENT_PHASE_INSTANT  ('I')
 #define TRACE_EVENT_PHASE_ASYNC_BEGIN ('S')
@@ skipping 166 matching lines @@
   *value = type_value.as_uint;
 }
 
 // These AddTraceEvent template functions are defined here instead of in the
 // macro, because the arg_values could be temporary objects, such as
 // std::string. In order to store pointers to the internal c_str and pass
 // through to the tracing API, the arg_values must live throughout
 // these procedures.
 
 static inline void AddTraceEvent(char phase,
-                                const unsigned char* category_enabled,
-                                const char* name,
-                                unsigned long long id,
-                                unsigned char flags) {
+                                 const unsigned char* category_enabled,
+                                 const char* name,
+                                 unsigned long long id,
+                                 int thread_id,
+                                 int64 timestamp,
+                                 unsigned char flags) {
   TRACE_EVENT_API_ADD_TRACE_EVENT(
-      phase, category_enabled, name, id,
+      phase, category_enabled, name, id, thread_id, timestamp,
       kZeroNumArgs, NULL, NULL, NULL,
       flags);
 }
 
+static inline void AddTraceEvent(char phase,
+                                 const unsigned char* category_enabled,
+                                 const char* name,
+                                 unsigned long long id,
+                                 unsigned char flags) {
+  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime() -

[nduca, 2012/12/20 20:19:27]

Can we take off the TimeOffset inside the TraceLog implementation? I'd rather we
didn't expose that as part of the public api.

[dsinclair, 2013/01/28 16:45:07]

Done.

+      base::debug::TraceLog::GetInstance()->GetTimeOffset();
+  AddTraceEvent(phase, category_enabled, name, id, thread_id,
+                now.ToInternalValue(), flags);
+}
+
+template<class ARG1_TYPE>
+static inline void AddTraceEvent(char phase,
+                                 const unsigned char* category_enabled,
+                                 const char* name,
+                                 unsigned long long id,
+                                 int thread_id,
+                                 int64 timestamp,
+                                 unsigned char flags,
+                                 const char* arg1_name,
+                                 const ARG1_TYPE& arg1_val) {
+  const int num_args = 1;
+  unsigned char arg_types[1];
+  unsigned long long arg_values[1];
+  SetTraceValue(arg1_val, &arg_types[0], &arg_values[0]);
+  TRACE_EVENT_API_ADD_TRACE_EVENT(
+      phase, category_enabled, name, id, thread_id, timestamp,
+      num_args, &arg1_name, arg_types, arg_values,
+      flags);
+}
+
 template<class ARG1_TYPE>
 static inline void AddTraceEvent(char phase,
-                                const unsigned char* category_enabled,
-                                const char* name,
-                                unsigned long long id,
-                                unsigned char flags,
-                                const char* arg1_name,
-                                const ARG1_TYPE& arg1_val) {
-  const int num_args = 1;
-  unsigned char arg_types[1];
-  unsigned long long arg_values[1];
-  SetTraceValue(arg1_val, &arg_types[0], &arg_values[0]);
-  TRACE_EVENT_API_ADD_TRACE_EVENT(
-      phase, category_enabled, name, id,
-      num_args, &arg1_name, arg_types, arg_values,
-      flags);
+                                 const unsigned char* category_enabled,
+                                 const char* name,
+                                 unsigned long long id,
+                                 unsigned char flags,
+                                 const char* arg1_name,
+                                 const ARG1_TYPE& arg1_val) {
+  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime() -
+      base::debug::TraceLog::GetInstance()->GetTimeOffset();
+  AddTraceEvent(phase, category_enabled, name, id, thread_id,
+                now.ToInternalValue(), flags,
+                arg1_name, arg1_val);
 }
 
 template<class ARG1_TYPE, class ARG2_TYPE>
 static inline void AddTraceEvent(char phase,
-                                const unsigned char* category_enabled,
-                                const char* name,
-                                unsigned long long id,
-                                unsigned char flags,
-                                const char* arg1_name,
-                                const ARG1_TYPE& arg1_val,
-                                const char* arg2_name,
-                                const ARG2_TYPE& arg2_val) {
+                                 const unsigned char* category_enabled,
+                                 const char* name,
+                                 unsigned long long id,
+                                 int thread_id,
+                                 int64 timestamp,
+                                 unsigned char flags,
+                                 const char* arg1_name,
+                                 const ARG1_TYPE& arg1_val,
+                                 const char* arg2_name,
+                                 const ARG2_TYPE& arg2_val) {
   const int num_args = 2;
   const char* arg_names[2] = { arg1_name, arg2_name };
   unsigned char arg_types[2];
   unsigned long long arg_values[2];
   SetTraceValue(arg1_val, &arg_types[0], &arg_values[0]);
   SetTraceValue(arg2_val, &arg_types[1], &arg_values[1]);
   TRACE_EVENT_API_ADD_TRACE_EVENT(
-      phase, category_enabled, name, id,
+      phase, category_enabled, name, id, thread_id, timestamp,
       num_args, arg_names, arg_types, arg_values,
       flags);
 }
 
+template<class ARG1_TYPE, class ARG2_TYPE>
+static inline void AddTraceEvent(char phase,
+                                const unsigned char* category_enabled,
+                                const char* name,
+                                unsigned long long id,
+                                unsigned char flags,
+                                const char* arg1_name,
+                                const ARG1_TYPE& arg1_val,
+                                const char* arg2_name,
+                                const ARG2_TYPE& arg2_val) {
+  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime() -
+      base::debug::TraceLog::GetInstance()->GetTimeOffset();
+  AddTraceEvent(phase, category_enabled, name, id, thread_id,
+                now.ToInternalValue(), flags,
+                arg1_name, arg1_val, arg2_name, arg2_val);
+}
+
 // Used by TRACE_EVENTx macro. Do not use directly.
 class BASE_EXPORT TraceEndOnScopeClose {
  public:
   // Note: members of data_ intentionally left uninitialized. See Initialize.
   TraceEndOnScopeClose() : p_data_(NULL) {}
   ~TraceEndOnScopeClose() {
     if (p_data_)
       AddEventIfEnabled();
   }
 
@@ skipping 14 matching lines @@
     const char* name;
   };
   Data* p_data_;
   Data data_;
 };
 
 
 }  // namespace trace_event_internal
 
 #endif  // BASE_DEBUG_TRACE_EVENT_H_