gltrace: Trace thread time and wall clock time.

For each gl function, trace both the thread and wall clock
times.

Change-Id: I32b6caa67fa50bf915dab89b3c5021ee82e28d55

opengl/libs/GLES_trace/TODO.txt

@@ -1,14 +0,0 @@
-TODO:
-    - Context - Currently, we don't do anything regarding the contexts that are created.
-    Need to maintain more state regarding contexts, and figure out what happens in the
-    presence of multiple contexts.
-
-    - Transport: Each GLMessage is sent via a socket as soon as the message is received.
-    i.e., there is no buffering of messages. Buffering should improve performance.
-
-    - Initialization: On first connection, send some basic information that includes:
-        1. version of the trace library
-        2. implementation dependent GL state variables such as # of vertex arrays etc.
-
-    - eglSwapBuffers: The images are lzf compressed, but there is no mode that transfers
-    only the differences from the previous images.

opengl/libs/GLES_trace/gltrace.proto

@@ -543,11 +543,13 @@ message GLMessage {
 
     required int32      context_id = 1;                     // GL context ID
     required int64      start_time = 2;                     // time when call was invoked
-    required int32      duration = 3;                       // duration of the call
+    required int32      duration = 3;                       // duration of the call (MONOTONIC TIME)
 
     required Function   function = 4 [default = invalid];   // GL function called
     repeated DataType   args = 5;                           // GL function's arguments
     optional DataType   returnValue = 6;                    // GL function's return value
 
     optional FrameBuffer fb = 7;                            // contents of the framebuffer
+
+    optional int32      threadtime = 8;                     // duration of the call (THREAD TIME)
 };

opengl/libs/GLES_trace/src/gltrace.pb.cpp

@@ -1663,6 +1663,7 @@ const int GLMessage::kFunctionFieldNumber;
 const int GLMessage::kArgsFieldNumber;
 const int GLMessage::kReturnValueFieldNumber;
 const int GLMessage::kFbFieldNumber;
+const int GLMessage::kThreadtimeFieldNumber;
 #endif  // !_MSC_VER
 
 GLMessage::GLMessage()
@@ -1689,6 +1690,7 @@ void GLMessage::SharedCtor() {
   function_ = 3000;
   returnvalue_ = NULL;
   fb_ = NULL;
+  threadtime_ = 0;
   ::memset(_has_bits_, 0, sizeof(_has_bits_));
 }
 
@@ -1730,6 +1732,7 @@ void GLMessage::Clear() {
     if (_has_bit(6)) {
       if (fb_ != NULL) fb_->::android::gltrace::GLMessage_FrameBuffer::Clear();
     }
+    threadtime_ = 0;
   }
   args_.Clear();
   ::memset(_has_bits_, 0, sizeof(_has_bits_));
@@ -1846,6 +1849,22 @@ bool GLMessage::MergePartialFromCodedStream(
         } else {
           goto handle_uninterpreted;
         }
+        if (input->ExpectTag(64)) goto parse_threadtime;
+        break;
+      }
+      
+      // optional int32 threadtime = 8;
+      case 8: {
+        if (::google::protobuf::internal::WireFormatLite::GetTagWireType(tag) ==
+            ::google::protobuf::internal::WireFormatLite::WIRETYPE_VARINT) {
+         parse_threadtime:
+          DO_((::google::protobuf::internal::WireFormatLite::ReadPrimitive<
+                   ::google::protobuf::int32, ::google::protobuf::internal::WireFormatLite::TYPE_INT32>(
+                 input, &threadtime_)));
+          _set_bit(7);
+        } else {
+          goto handle_uninterpreted;
+        }
         if (input->ExpectAtEnd()) return true;
         break;
       }
@@ -1906,6 +1925,11 @@ void GLMessage::SerializeWithCachedSizes(
       7, this->fb(), output);
   }
   
+  // optional int32 threadtime = 8;
+  if (_has_bit(7)) {
+    ::google::protobuf::internal::WireFormatLite::WriteInt32(8, this->threadtime(), output);
+  }
+  
 }
 
 int GLMessage::ByteSize() const {
@@ -1953,6 +1977,13 @@ int GLMessage::ByteSize() const {
           this->fb());
     }
     
+    // optional int32 threadtime = 8;
+    if (has_threadtime()) {
+      total_size += 1 +
+        ::google::protobuf::internal::WireFormatLite::Int32Size(
+          this->threadtime());
+    }
+    
   }
   // repeated .android.gltrace.GLMessage.DataType args = 5;
   total_size += 1 * this->args_size();
@@ -1995,6 +2026,9 @@ void GLMessage::MergeFrom(const GLMessage& from) {
     if (from._has_bit(6)) {
       mutable_fb()->::android::gltrace::GLMessage_FrameBuffer::MergeFrom(from.fb());
     }
+    if (from._has_bit(7)) {
+      set_threadtime(from.threadtime());
+    }
   }
 }
 
@@ -2028,6 +2062,7 @@ void GLMessage::Swap(GLMessage* other) {
     args_.Swap(&other->args_);
     std::swap(returnvalue_, other->returnvalue_);
     std::swap(fb_, other->fb_);
+    std::swap(threadtime_, other->threadtime_);
     std::swap(_has_bits_[0], other->_has_bits_[0]);
     std::swap(_cached_size_, other->_cached_size_);
   }

opengl/libs/GLES_trace/src/gltrace.pb.h

@@ -1418,6 +1418,13 @@ class GLMessage : public ::google::protobuf::MessageLite {
   inline const ::android::gltrace::GLMessage_FrameBuffer& fb() const;
   inline ::android::gltrace::GLMessage_FrameBuffer* mutable_fb();
   
+  // optional int32 threadtime = 8;
+  inline bool has_threadtime() const;
+  inline void clear_threadtime();
+  static const int kThreadtimeFieldNumber = 8;
+  inline ::google::protobuf::int32 threadtime() const;
+  inline void set_threadtime(::google::protobuf::int32 value);
+  
   // @@protoc_insertion_point(class_scope:android.gltrace.GLMessage)
  private:
   mutable int _cached_size_;
@@ -1429,11 +1436,12 @@ class GLMessage : public ::google::protobuf::MessageLite {
   ::google::protobuf::RepeatedPtrField< ::android::gltrace::GLMessage_DataType > args_;
   ::android::gltrace::GLMessage_DataType* returnvalue_;
   ::android::gltrace::GLMessage_FrameBuffer* fb_;
+  ::google::protobuf::int32 threadtime_;
   friend void  protobuf_AddDesc_gltrace_2eproto();
   friend void protobuf_AssignDesc_gltrace_2eproto();
   friend void protobuf_ShutdownFile_gltrace_2eproto();
   
-  ::google::protobuf::uint32 _has_bits_[(7 + 31) / 32];
+  ::google::protobuf::uint32 _has_bits_[(8 + 31) / 32];
   
   // WHY DOES & HAVE LOWER PRECEDENCE THAN != !?
   inline bool _has_bit(int index) const {
@@ -1860,6 +1868,22 @@ inline ::android::gltrace::GLMessage_FrameBuffer* GLMessage::mutable_fb() {
   return fb_;
 }
 
+// optional int32 threadtime = 8;
+inline bool GLMessage::has_threadtime() const {
+  return _has_bit(7);
+}
+inline void GLMessage::clear_threadtime() {
+  threadtime_ = 0;
+  _clear_bit(7);
+}
+inline ::google::protobuf::int32 GLMessage::threadtime() const {
+  return threadtime_;
+}
+inline void GLMessage::set_threadtime(::google::protobuf::int32 value) {
+  _set_bit(7);
+  threadtime_ = value;
+}
+
 
 // @@protoc_insertion_point(namespace_scope)
 

opengl/libs/GLES_trace/src/gltrace_fixup.cpp

@@ -379,13 +379,16 @@ void fixup_glGetActiveAttribOrUniform(GLMessage *glmsg, int location) {
     arg_location->add_intvalue(location);
 }
 
-void fixupGLMessage(GLTraceContext *context, nsecs_t start, nsecs_t end, GLMessage *glmsg) {
+void fixupGLMessage(GLTraceContext *context, nsecs_t wallStart, nsecs_t wallEnd,
+                                             nsecs_t threadStart, nsecs_t threadEnd,
+                                             GLMessage *glmsg) {
     // for all messages, set the current context id
     glmsg->set_context_id(context->getId());
 
     // set start time and duration
-    glmsg->set_start_time(start);
-    glmsg->set_duration((unsigned)(end - start));
+    glmsg->set_start_time(wallStart);
+    glmsg->set_duration((unsigned)(wallEnd - wallStart));
+    glmsg->set_threadtime((unsigned)(threadEnd - threadStart));
 
     // do any custom message dependent processing
     switch (glmsg->function()) {

opengl/libs/GLES_trace/src/gltrace_fixup.h

@@ -25,7 +25,9 @@
 namespace android {
 namespace gltrace {
 
-void fixupGLMessage(GLTraceContext *curContext, nsecs_t start, nsecs_t end, GLMessage *message);
+void fixupGLMessage(GLTraceContext *curContext, nsecs_t wallStart, nsecs_t wallEnd,
+                                                nsecs_t threadStart, nsecs_t threadEnd,
+                                                GLMessage *message);
 void fixup_addFBContents(GLTraceContext *curContext, GLMessage *message, FBBinding fbToRead);
 
 };

opengl/libs/GLES_trace/tools/genapi.py

@@ -162,13 +162,15 @@ TRACE_CALL_TEMPLATE = pyratemp.Template(
 <!--(end)-->
 
     // call function
-    nsecs_t start_time = systemTime();
+    nsecs_t wallStartTime = systemTime(SYSTEM_TIME_MONOTONIC);
+    nsecs_t threadStartTime = systemTime(SYSTEM_TIME_THREAD);
 <!--(if retType != "void")-->
     $!retType!$ retValue = glContext->hooks->gl.$!callsite!$;
 <!--(else)-->
     glContext->hooks->gl.$!callsite!$;
 <!--(end)-->
-    nsecs_t end_time = systemTime();
+    nsecs_t threadEndTime = systemTime(SYSTEM_TIME_THREAD);
+    nsecs_t wallEndTime = systemTime(SYSTEM_TIME_MONOTONIC);
 <!--(if retType != "void")-->
 
     // set return value
@@ -178,7 +180,9 @@ TRACE_CALL_TEMPLATE = pyratemp.Template(
     rt->$!retDataType.getProtobufCall()!$retValue);
 <!--(end)-->
 
-    fixupGLMessage(glContext, start_time, end_time, &glmsg);
+    fixupGLMessage(glContext, wallStartTime, wallEndTime,
+                              threadStartTime, threadEndTime,
+                              &glmsg);
     glContext->traceGLMessage(&glmsg);
 <!--(if retType != "void")-->