Trace VM service requests

runtime/vm/service.cc

 // Copyright (c) 2013, the Dart project authors.  Please see the AUTHORS file
 // for details. All rights reserved. Use of this source code is governed by a
 // BSD-style license that can be found in the LICENSE file.
 
 #include "vm/service.h"
 
 #include "include/dart_api.h"
 
 #include "vm/compiler.h"
 #include "vm/coverage.h"
@@ skipping 10 matching lines @@
 #include "vm/object_id_ring.h"
 #include "vm/object_store.h"
 #include "vm/port.h"
 #include "vm/profiler.h"
 #include "vm/stack_frame.h"
 #include "vm/symbols.h"
 
 
 namespace dart {
 
+DEFINE_FLAG(bool, trace_service, false, "Trace VM service requests.");
+
 struct ResourcesEntry {
   const char* path_;
   const char* resource_;
   int length_;
 };
 
 extern ResourcesEntry __service_resources_[];
 
 class Resources {
  public:
@@ skipping 525 matching lines @@
     path ^= message.At(1);
     option_keys ^= message.At(2);
     option_values ^= message.At(3);
 
     ASSERT(!path.IsNull());
     ASSERT(!option_keys.IsNull());
     ASSERT(!option_values.IsNull());
     // 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);
+          }
         }
       }
     }
   }
 }
 
 
 static bool HandleIsolate(Isolate* isolate, JSONStream* js) {
   isolate->PrintToJSONStream(js);
   return true;
@@ skipping 537 matching lines @@
     option_values ^= message.At(3);
 
     ASSERT(!path.IsNull());
     ASSERT(!option_keys.IsNull());
     ASSERT(!option_values.IsNull());
     // Path always has at least one entry in it.
     ASSERT(path.Length() > 0);
     // 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(path_segment_c);
 
-    RootMessageHandler handler =
-        FindRootMessageHandler(pathSegment.ToCString());
+    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(),
                       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(&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);
+          }
         }
       }
     }
   }
 }
 
 
 static bool HandleRootEcho(JSONStream* js) {
   JSONObject jsobj(js);
   jsobj.AddProperty("type", "message");
@@ skipping 22 matching lines @@
   for (intptr_t i = 0; i < num_message_handlers; i++) {
     const RootMessageHandlerEntry& entry = root_handlers[i];
     if (!strcmp(command, entry.command)) {
       return entry.handler;
     }
   }
   return NULL;
 }
 
 }  // namespace dart