Add extra tracing to Debug_InterruptIsolate test.

runtime/vm/dart.cc

Index: runtime/vm/dart.cc
diff --git a/runtime/vm/dart.cc b/runtime/vm/dart.cc
index bace9af3c1dc0cd73342a5721d1c45dcc35751e1..d2cc5a8097139417f087c145b4e55a398df8e609 100644
--- a/runtime/vm/dart.cc
+++ b/runtime/vm/dart.cc
@@ -42,8 +42,10 @@ DECLARE_FLAG(bool, pause_isolates_on_exit);
 DEFINE_FLAG(bool, keep_code, false,
             "Keep deoptimized code for profiling.");
 DEFINE_FLAG(bool, shutdown, true, "Do a clean shutdown of the VM");
+DEFINE_FLAG(bool, trace_shutdown, false, "Trace VM shutdown on stderr");
 
 Isolate* Dart::vm_isolate_ = NULL;
+int64_t Dart::start_time_ = 0;
 ThreadPool* Dart::thread_pool_ = NULL;
 DebugInfo* Dart::pprof_symbol_generator_ = NULL;
 ReadOnlyHandles* Dart::predefined_handles_ = NULL;
@@ -133,6 +135,7 @@ const char* Dart::InitOnce(const uint8_t* vm_isolate_snapshot,
     Dart_IsolateFlags api_flags;
     vm_flags.CopyTo(&api_flags);
     vm_isolate_ = Isolate::Init("vm-isolate", api_flags, is_vm_isolate);
+    start_time_ = vm_isolate_->start_time();
     vm_isolate_->set_compilation_allowed(!precompiled);
     // Verify assumptions about executing in the VM isolate.
     ASSERT(vm_isolate_ == Isolate::Current());
@@ -234,8 +237,17 @@ const char* Dart::Cleanup() {
     return "VM already terminated.";
   }
 
+  if (FLAG_trace_shutdown) {
+    OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Starting shutdown\n",
+                 timestamp());
+  }
+
   if (FLAG_profiler) {
     // Shut down profiling.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Shutting down profiling\n",
+                   timestamp());
+    }
     Profiler::Shutdown();
   }
 
@@ -243,6 +255,10 @@ const char* Dart::Cleanup() {
   {
     // Set the VM isolate as current isolate when shutting down
     // Metrics so that we can use a StackZone.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Entering vm isolate\n",
+                   timestamp());
+    }
     bool result = Thread::EnterIsolate(vm_isolate_);
     ASSERT(result);
     Metric::Cleanup();
@@ -251,19 +267,39 @@ const char* Dart::Cleanup() {
 
   if (FLAG_shutdown) {
     // Disable the creation of new isolates.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Disabling isolate creation\n",
+                   timestamp());
+    }
     Isolate::DisableIsolateCreation();
 
     // Send the OOB Kill message to all remaining application isolates.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Killing all app isolates\n",
+                   timestamp());
+    }
     Isolate::KillAllIsolates(Isolate::kInternalKillMsg);
 
     // Shutdown the service isolate.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Shutting down service isolate\n",
+                   timestamp());
+    }
     ServiceIsolate::Shutdown();
 
     // Wait for all application isolates and the service isolate to shutdown
     // before shutting down the thread pool.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Waiting for isolate shutdown\n",
+                   timestamp());
+    }
     WaitForIsolateShutdown();
 
     // Shutdown the thread pool. On return, all thread pool threads have exited.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Deleting thread pool\n",
+                   timestamp());
+    }
     delete thread_pool_;
     thread_pool_ = NULL;
 
@@ -273,9 +309,17 @@ const char* Dart::Cleanup() {
     // This must come after deletion of the thread pool to avoid a race in which
     // a thread spawned by the thread pool does not exit through the thread
     // pool, messing up its bookkeeping.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Disabling OS Thread creation\n",
+                   timestamp());
+    }
     OSThread::DisableOSThreadCreation();
 
     // Set the VM isolate as current isolate.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Cleaning up vm isolate\n",
+                   timestamp());
+    }
     bool result = Thread::EnterIsolate(vm_isolate_);
     ASSERT(result);
 
@@ -292,18 +336,41 @@ const char* Dart::Cleanup() {
     OSThread* os_thread = OSThread::Current();
     OSThread::SetCurrent(NULL);
     delete os_thread;
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Deleted os_thread\n",
+                   timestamp());
+    }
   } else {
     // Shutdown the service isolate.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Shutting down service isolate\n",
+                   timestamp());
+    }
     ServiceIsolate::Shutdown();
 
     // Disable thread creation.
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Disabling OS Thread creation\n",
+                   timestamp());
+    }
     OSThread::DisableOSThreadCreation();
   }
 
+  if (FLAG_trace_shutdown) {
+    OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Deleting code observers\n",
+                 timestamp());
+  }
   CodeObservers::DeleteAll();
   if (FLAG_support_timeline) {
+    if (FLAG_trace_shutdown) {
+      OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Shutting down timeline\n",
+                   timestamp());
+    }
     Timeline::Shutdown();
   }
+  if (FLAG_trace_shutdown) {
+    OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Done\n", timestamp());
+  }
 
   return NULL;
 }
@@ -466,6 +533,12 @@ void Dart::ShutdownIsolate() {
 }
 
 
+int64_t Dart::timestamp() {
+  return ((OS::GetCurrentTimeMicros() - Dart::start_time_) /
+          kMillisecondsPerSecond);
+}
+
+
 uword Dart::AllocateReadOnlyHandle() {
   ASSERT(Isolate::Current() == Dart::vm_isolate());
   ASSERT(predefined_handles_ != NULL);