Trace VM service requests

runtime/vm/service.cc

Index: runtime/vm/service.cc
diff --git a/runtime/vm/service.cc b/runtime/vm/service.cc
index 34675b208a337037f29c6a5008048aa31c0a7c39..726a502a517e4bf6c7db77e0f09347238add9c0c 100644
--- a/runtime/vm/service.cc
+++ b/runtime/vm/service.cc
@@ -28,6 +28,8 @@
 
 namespace dart {
 
+DEFINE_FLAG(bool, trace_service, false, "Trace VM service requests.");
+
 struct ResourcesEntry {
   const char* path_;
   const char* resource_;
@@ -573,27 +575,57 @@ void Service::HandleIsolateMessage(Isolate* isolate, const Instance& msg) {
     // Same number of option keys as values.
     ASSERT(option_keys.Length() == option_values.Length());
 
-    String& pathSegment = String::Handle();
+    String& path_segment = String::Handle();
     if (path.Length() > 0) {
-      pathSegment ^= path.At(0);
+      path_segment ^= path.At(0);
     } else {
-      pathSegment ^= Symbols::Empty().raw();
+      path_segment ^= Symbols::Empty().raw();
     }
-    ASSERT(!pathSegment.IsNull());
+    ASSERT(!path_segment.IsNull());
+    const char* path_segment_c = path_segment.ToCString();
 
     IsolateMessageHandler handler =
-        FindIsolateMessageHandler(pathSegment.ToCString());
+        FindIsolateMessageHandler(path_segment_c);
+    if (FLAG_trace_service) {
+      const char* handler_text =
+          handler == NULL ? "No handler found." : "Handler found.";
+      OS::Print("Service request <%s> to %s - %s\n",
+                path_segment_c,
+                isolate->name(),
+                handler_text);
+    }
     {
       JSONStream js;
       SetupJSONStream(&js, zone.GetZone(),
                       reply_port, path, option_keys, option_values);
+
       if (handler == NULL) {
         PrintError(&js, "Unrecognized path");
         PostReply(&js);
       } else {
+        int64_t start_handler_micros = OS::GetCurrentTimeMicros();
+        int64_t delta_micros = 0;
+        bool posted = false;
         if (handler(isolate, &js)) {
+          delta_micros = OS::GetCurrentTimeMicros() - start_handler_micros;
           // Handler returns true if the reply is ready to be posted.
           PostReply(&js);

[turnidge, 2014/02/13 20:49:51]

I suggest moving the initial timer code and tracing output into SetupJSONStream
and moving the final timer and tracing code into PostReply.  This will make the
tracing/timing work even in the case where the handler returns false.  Also, it
will get rid of the duplicate code here and in HandleRootMessage.

+          posted = true;
+        } else {
+          delta_micros = OS::GetCurrentTimeMicros() - start_handler_micros;
+        }
+        if (FLAG_trace_service) {
+          if (posted) {
+            OS::Print("Service request <%s> to %s handled in %" Pd64 " us.\n",
+                      path_segment_c,
+                      isolate->name(),
+                      delta_micros);
+          } else {
+            OS::Print("Service request <%s> to %s deferred in %" Pd64 " us.\n",
+                      path_segment_c,
+                      isolate->name(),
+                      delta_micros);
+          }
         }
       }
     }
@@ -1151,12 +1183,20 @@ void Service::HandleRootMessage(const Instance& msg) {
     // Same number of option keys as values.
     ASSERT(option_keys.Length() == option_values.Length());
 
-    String& pathSegment = String::Handle();
-    pathSegment ^= path.At(0);
-    ASSERT(!pathSegment.IsNull());
-
+    String& path_segment = String::Handle();
+    path_segment ^= path.At(0);
+    ASSERT(!path_segment.IsNull());
+    const char* path_segment_c = path_segment.ToCString();
     RootMessageHandler handler =
-        FindRootMessageHandler(pathSegment.ToCString());
+        FindRootMessageHandler(path_segment_c);
+
+    if (FLAG_trace_service) {
+      const char* handler_text =
+          handler == NULL ? "No handler found." : "Handler found.";
+      OS::Print("Service request <%s> - %s\n",
+                path_segment_c,
+                handler_text);
+    }
     {
       JSONStream js;
       SetupJSONStream(&js, zone.GetZone(),
@@ -1165,9 +1205,27 @@ void Service::HandleRootMessage(const Instance& msg) {
         PrintError(&js, "Unrecognized path");
         PostReply(&js);
       } else {
+        int64_t start_handler_micros = OS::GetCurrentTimeMicros();
+        int64_t delta_micros = 0;
+        bool posted = false;
         if (handler(&js)) {
+          delta_micros = OS::GetCurrentTimeMicros() - start_handler_micros;
           // Handler returns true if the reply is ready to be posted.
           PostReply(&js);
+          posted = true;
+        } else {
+          delta_micros = OS::GetCurrentTimeMicros() - start_handler_micros;
+        }
+        if (FLAG_trace_service) {
+          if (posted) {
+            OS::Print("Service request <%s> handled in %" Pd64 " us.\n",
+                      path_segment_c,
+                      delta_micros);
+          } else {
+            OS::Print("Service request <%s> deferred in %" Pd64 " us.\n",
+                      path_segment_c,
+                      delta_micros);
+          }
         }
       }
     }