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

runtime/vm/json_stream.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 "platform/assert.h"
 
 #include "vm/dart_entry.h"
 #include "vm/debugger.h"
 #include "vm/json_stream.h"
 #include "vm/message.h"
@@ skipping 61 matching lines @@
       string_iterator ^= param_values.At(i);
       param_values_native[i] =
           zone->MakeCopyOfString(string_iterator.ToCString());
     }
     SetParams(param_keys_native, param_values_native, param_keys.Length());
   }
   if (FLAG_trace_service) {
     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\":");
 }
 
 
 void JSONStream::SetupError() {
   buffer_.Clear();
   buffer_.Printf("{\"jsonrpc\":\"2.0\", \"error\":");
 }
 
@@ skipping 70 matching lines @@
 void JSONStream::PostNullReply(Dart_Port port) {
   PortMap::PostMessage(new Message(
       port, Object::null(), Message::kNormalPriority));
 }
 
 
 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_);
     PrintProperty("id", str.ToCString());
   } else if (seq_->IsInteger()) {
     const Integer& integer = Integer::Cast(*seq_);
     PrintProperty64("id", integer.AsInt64Value());
   } else if (seq_->IsDouble()) {
     const Double& dbl = Double::Cast(*seq_);
     PrintProperty("id", dbl.value());
@@ skipping 10 matching lines @@
   uint8_t* data = NULL;
   MessageWriter writer(&data, &allocator, false);
   writer.WriteMessage(reply);
   bool result = PortMap::PostMessage(new Message(port, data,
                                                  writer.BytesWritten(),
                                                  Message::kNormalPriority));
   if (FLAG_trace_service) {
     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);
     }
   }
 }
 
 
 const char* JSONStream::LookupParam(const char* key) const {
   for (int i = 0; i < num_params(); i++) {
     if (!strcmp(key, param_keys_[i])) {
       return param_values_[i];
     }
@@ skipping 630 matching lines @@
   ASSERT(len == len2);
   stream_->buffer_.AddChar('"');
   stream_->AddEscapedUTF8String(p);
   stream_->buffer_.AddChar('"');
   free(p);
 }
 
 #endif  // !PRODUCT
 
 }  // namespace dart