Add extra tracing to Debug_InterruptIsolate test.

runtime/vm/dart.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/dart.h"
 
 #include "vm/code_observers.h"
 #include "vm/cpu.h"
 #include "vm/dart_api_state.h"
 #include "vm/dart_entry.h"
@@ skipping 24 matching lines @@
 namespace dart {
 
 DECLARE_FLAG(bool, print_class_table);
 DECLARE_FLAG(bool, trace_isolates);
 DECLARE_FLAG(bool, trace_time_all);
 DECLARE_FLAG(bool, pause_isolates_on_start);
 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;
 const uint8_t* Dart::instructions_snapshot_buffer_ = NULL;
 
 // Structure for managing read-only global handles allocation used for
 // creating global read-only handles that are pre created and initialized
 // for use across all isolates. Having these global pre created handles
 // stored in the vm isolate ensures that we don't constantly create and
 // destroy handles for read-only objects referred in the VM code
@@ skipping 69 matching lines @@
     ASSERT(vm_isolate_ == NULL);
     ASSERT(Flags::Initialized());
     const bool is_vm_isolate = true;
     const bool precompiled = instructions_snapshot != NULL;
 
     // Setup default flags for the VM isolate.
     Isolate::Flags vm_flags;
     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());
     ASSERT(vm_isolate_ == Thread::Current()->isolate());
 
     Thread* T = Thread::Current();
     ASSERT(T != NULL);
     StackZone zone(T);
     HandleScope handle_scope(T);
     Object::InitNull(vm_isolate_);
@@ skipping 81 matching lines @@
   ASSERT(Isolate::isolates_list_head_ == Dart::vm_isolate());
 }
 
 
 const char* Dart::Cleanup() {
   ASSERT(Isolate::Current() == NULL);
   if (vm_isolate_ == NULL) {
     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();
   }
 
 
   {
     // 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();
     Thread::ExitIsolate();
   }
 
   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;
 
     // Disable creation of any new OSThread structures which means no more new
     // threads can do an EnterIsolate. This must come after isolate shutdown
     // because new threads may need to be spawned to shutdown the isolates.
     // 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);
 
     ShutdownIsolate();
     vm_isolate_ = NULL;
     ASSERT(Isolate::IsolateListLength() == 0);
 
     TargetCPUFeatures::Cleanup();
     StoreBuffer::ShutDown();
 
     // Delete the current thread's TLS and set it's TLS to null.
     // If it is the last thread then the destructor would call
     // OSThread::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;
 }
 
 
 Isolate* Dart::CreateIsolate(const char* name_prefix,
                              const Dart_IsolateFlags& api_flags) {
   // Create a new isolate.
   Isolate* isolate = Isolate::Init(name_prefix, api_flags);
   return isolate;
@@ skipping 142 matching lines @@
 }
 
 
 void Dart::ShutdownIsolate() {
   Isolate* isolate = Isolate::Current();
   isolate->Shutdown();
   delete isolate;
 }
 
 
+int64_t Dart::timestamp() {
+  return ((OS::GetCurrentTimeMicros() - Dart::start_time_) /
+          kMillisecondsPerSecond);
+}
+
+
 uword Dart::AllocateReadOnlyHandle() {
   ASSERT(Isolate::Current() == Dart::vm_isolate());
   ASSERT(predefined_handles_ != NULL);
   return predefined_handles_->handles_.AllocateScopedHandle();
 }
 
 
 LocalHandle* Dart::AllocateReadOnlyApiHandle() {
   ASSERT(Isolate::Current() == Dart::vm_isolate());
   ASSERT(predefined_handles_ != NULL);
   return predefined_handles_->api_handles_.AllocateHandle();
 }
 
 
 bool Dart::IsReadOnlyHandle(uword address) {
   ASSERT(predefined_handles_ != NULL);
   return predefined_handles_->handles_.IsValidScopedHandle(address);
 }
 
 
 bool Dart::IsReadOnlyApiHandle(Dart_Handle handle) {
   ASSERT(predefined_handles_ != NULL);
   return predefined_handles_->api_handles_.IsValidHandle(handle);
 }
 
 }  // namespace dart