Add timestamps to --trace-service output to help debug test timeouts.

runtime/vm/json_stream.cc

Index: runtime/vm/json_stream.cc
diff --git a/runtime/vm/json_stream.cc b/runtime/vm/json_stream.cc
index b64d6e64fc87c6c8f68a03d6b5bba2f0fee2fd61..a16217055d964a42fd9a4d63ed533dd43115cf82 100644
--- a/runtime/vm/json_stream.cc
+++ b/runtime/vm/json_stream.cc
@@ -79,9 +79,10 @@ void JSONStream::Setup(Zone* zone,
     Isolate* isolate = Isolate::Current();
     ASSERT(isolate != NULL);
     const char* isolate_name = isolate->name();
-    OS::Print("Isolate %s processing service request %s\n",
-              isolate_name, method_);
     setup_time_micros_ = OS::GetCurrentTimeMicros();
+    int64_t timestamp = setup_time_micros_ - Dart::vm_isolate()->start_time();
+    OS::Print("[@%" Pd64 "] Isolate %s processing service request %s\n",
+              timestamp, isolate_name, method_);
   }
   buffer_.Printf("{\"jsonrpc\":\"2.0\", \"result\":");
 }
@@ -172,10 +173,6 @@ void JSONStream::PostReply() {
   Dart_Port port = reply_port();
   ASSERT(port != ILLEGAL_PORT);
   set_reply_port(ILLEGAL_PORT);  // Prevent double replies.
-  int64_t process_delta_micros = 0;
-  if (FLAG_trace_service) {
-    process_delta_micros = OS::GetCurrentTimeMicros() - setup_time_micros_;
-  }
   ASSERT(seq_ != NULL);
   if (seq_->IsString()) {
     const String& str = String::Cast(*seq_);
@@ -206,12 +203,17 @@ void JSONStream::PostReply() {
     Isolate* isolate = Isolate::Current();
     ASSERT(isolate != NULL);
     const char* isolate_name = isolate->name();
+    int64_t current_time = OS::GetCurrentTimeMicros();
+    int64_t process_delta_micros = current_time - setup_time_micros_;
+    int64_t timestamp = current_time - Dart::vm_isolate()->start_time();
     if (result) {
-      OS::Print("Isolate %s processed service request %s in %" Pd64" us.\n",
-                isolate_name, method_, process_delta_micros);
+      OS::Print("[@%" Pd64 "] Isolate %s processed service request %s "
+                "(%" Pd64 "us)\n",
+                timestamp, isolate_name, method_, process_delta_micros);
     } else {
-      OS::Print("Isolate %s FAILED to post response for service request %s.\n",
-                isolate_name, method_);
+      OS::Print("[@%" Pd64 "] Isolate %s processed service request %s "
+                "(%" Pd64 "us) FAILED\n",
+                timestamp, isolate_name, method_, process_delta_micros);
     }
   }
 }