Improve --trace-service to help track down problems in full_coverage_test.

runtime/vm/isolate.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/isolate.h"
 
 #include "include/dart_api.h"
 #include "include/dart_native_api.h"
 #include "platform/assert.h"
 #include "platform/text_buffer.h"
@@ skipping 34 matching lines @@
 #include "vm/timeline_analysis.h"
 #include "vm/timer.h"
 #include "vm/visitor.h"
 
 
 namespace dart {
 
 DECLARE_FLAG(bool, print_metrics);
 DECLARE_FLAG(bool, timing);
 DECLARE_FLAG(bool, trace_service);
+DECLARE_FLAG(bool, trace_service_verbose);
 
 DEFINE_FLAG(bool, trace_isolates, false,
             "Trace isolate creation and shut down.");
 DEFINE_FLAG(bool, pause_isolates_on_start, false,
             "Pause isolates before starting.");
 DEFINE_FLAG(bool, pause_isolates_on_exit, false,
             "Pause isolates exiting.");
 DEFINE_FLAG(bool, pause_isolates_on_unhandled_exceptions, false,
             "Pause isolates on unhandled exceptions.");
 
@@ skipping 1452 matching lines @@
     deferred_interrupts_ = stack_limit_ & deferred_interrupts_mask_;
 
     // Clear deferrable interrupts, if present.
     stack_limit_ &= ~deferred_interrupts_mask_;
 
     if ((stack_limit_ & kInterruptsMask) == 0) {
       // No other pending interrupts.  Restore normal stack limit.
       stack_limit_ = saved_stack_limit_;
     }
   }
+  if (FLAG_trace_service && FLAG_trace_service_verbose) {
+    OS::Print("[+%" Pd64 "ms] Isolate %s deferring OOB interrupts\n",
+              Dart::timestamp(), name());
+  }
 }
 
 
 void Isolate::RestoreOOBMessageInterrupts() {
   MutexLocker ml(mutex_);
   ASSERT(deferred_interrupts_mask_ == kMessageInterrupt);
   deferred_interrupts_mask_ = 0;
   if (deferred_interrupts_ != 0) {
     if (stack_limit_ == saved_stack_limit_) {
       stack_limit_ = (~static_cast<uword>(0)) & ~kInterruptsMask;
     }
     stack_limit_ |= deferred_interrupts_;
     deferred_interrupts_ = 0;
   }
+  if (FLAG_trace_service && FLAG_trace_service_verbose) {
+    OS::Print("[+%" Pd64 "ms] Isolate %s restoring OOB interrupts\n",
+              Dart::timestamp(), name());
+  }
 }
 
 
 RawError* Isolate::HandleInterrupts() {
   uword interrupt_bits = GetAndClearInterrupts();
   if ((interrupt_bits & kVMInterrupt) != 0) {
     if (store_buffer()->Overflowed()) {
       if (FLAG_verbose_gc) {
         OS::PrintErr("Scavenge scheduled by store buffer overflow.\n");
       }
@@ skipping 546 matching lines @@
     return Object::null();
   }
   // Grab run function.
   const Library& developer_lib = Library::Handle(Library::DeveloperLibrary());
   ASSERT(!developer_lib.IsNull());
   const Function& run_extension = Function::Handle(
       developer_lib.LookupLocalFunction(Symbols::_runExtension()));
   ASSERT(!run_extension.IsNull());
 
   const Array& arguments =
-      Array::Handle(Array::New(kPendingEntrySize, Heap::kNew));
+      Array::Handle(Array::New(kPendingEntrySize + 1, Heap::kNew));
   Object& result = Object::Handle();
   String& method_name = String::Handle();
   Instance& closure = Instance::Handle();
   Array& parameter_keys = Array::Handle();
   Array& parameter_values = Array::Handle();
   Instance& reply_port = Instance::Handle();
   Instance& id = Instance::Handle();
   for (intptr_t i = 0; i < calls.Length(); i += kPendingEntrySize) {
     // Grab arguments for call.
     closure ^= calls.At(i + kPendingHandlerIndex);
     ASSERT(!closure.IsNull());
     arguments.SetAt(kPendingHandlerIndex, closure);
     method_name ^= calls.At(i + kPendingMethodNameIndex);
     ASSERT(!method_name.IsNull());
     arguments.SetAt(kPendingMethodNameIndex, method_name);
     parameter_keys ^= calls.At(i + kPendingKeysIndex);
     ASSERT(!parameter_keys.IsNull());
     arguments.SetAt(kPendingKeysIndex, parameter_keys);
     parameter_values ^= calls.At(i + kPendingValuesIndex);
     ASSERT(!parameter_values.IsNull());
     arguments.SetAt(kPendingValuesIndex, parameter_values);
     reply_port ^= calls.At(i + kPendingReplyPortIndex);
     ASSERT(!reply_port.IsNull());
     arguments.SetAt(kPendingReplyPortIndex, reply_port);
     id ^= calls.At(i + kPendingIdIndex);
     arguments.SetAt(kPendingIdIndex, id);
+    arguments.SetAt(kPendingEntrySize, Bool::Get(FLAG_trace_service));
 
+    if (FLAG_trace_service) {
+      OS::Print(
+          "[+%" Pd64 "ms] Isolate %s invoking _runExtension for %s\n",
+          Dart::timestamp(), name(), method_name.ToCString());
+    }
     result = DartEntry::InvokeFunction(run_extension, arguments);
+    if (FLAG_trace_service) {
+      OS::Print(
+          "[+%" Pd64 "ms] Isolate %s : _runExtension complete for %s\n",
+          Dart::timestamp(), name(), method_name.ToCString());
+    }
     if (result.IsError()) {
       if (result.IsUnwindError()) {
         // Propagate the unwind error. Remaining service extension calls
         // are dropped.
         return result.raw();
       } else {
         // Send error back over the protocol.
         Service::PostError(method_name,
                            parameter_keys,
                            parameter_values,
@@ skipping 17 matching lines @@
   return r;
 }
 
 
 void Isolate::AppendServiceExtensionCall(const Instance& closure,
                                          const String& method_name,
                                          const Array& parameter_keys,
                                          const Array& parameter_values,
                                          const Instance& reply_port,
                                          const Instance& id) {
+  if (FLAG_trace_service) {
+    OS::Print(
+        "[+%" Pd64 "ms] Isolate %s ENQUEUING request for extension %s\n",
+        Dart::timestamp(), name(), method_name.ToCString());
+  }
   GrowableObjectArray& calls =
       GrowableObjectArray::Handle(pending_service_extension_calls());
   if (calls.IsNull()) {
     calls ^= GrowableObjectArray::New();
     ASSERT(!calls.IsNull());
     set_pending_service_extension_calls(calls);
   }
   ASSERT(kPendingHandlerIndex == 0);
   calls.Add(closure);
   ASSERT(kPendingMethodNameIndex == 1);
@@ skipping 592 matching lines @@
 void IsolateSpawnState::DecrementSpawnCount() {
   ASSERT(spawn_count_monitor_ != NULL);
   ASSERT(spawn_count_ != NULL);
   MonitorLocker ml(spawn_count_monitor_);
   ASSERT(*spawn_count_ > 0);
   *spawn_count_ = *spawn_count_ - 1;
   ml.Notify();
 }
 
 }  // namespace dart