[VM/Runtime] Add more shutdown logging to debug occasional delay in shutdown.
TEST=cq
Change-Id: Id663e03c38a8380320982ddd8fd328b38896baf9
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/219125
Commit-Queue: Siva Annamalai <asiva@google.com>
Reviewed-by: Ryan Macnak <rmacnak@google.com>
diff --git a/runtime/vm/dart.cc b/runtime/vm/dart.cc
index ced30ca..00a1877 100644
--- a/runtime/vm/dart.cc
+++ b/runtime/vm/dart.cc
@@ -582,6 +582,14 @@
// This waits until only the VM isolate remains in the list.
void Dart::WaitForIsolateShutdown() {
+ int64_t start_time = 0;
+ if (FLAG_trace_shutdown) {
+ start_time = UptimeMillis();
+ OS::PrintErr("[+%" Pd64
+ "ms] SHUTDOWN: Waiting for service "
+ "and kernel isolates to shutdown\n",
+ start_time);
+ }
ASSERT(!Isolate::creation_enabled_);
MonitorLocker ml(Isolate::isolate_creation_monitor_);
intptr_t num_attempts = 0;
@@ -592,6 +600,25 @@
if (num_attempts > 10) {
DumpAliveIsolates(num_attempts, /*only_application_isolates=*/false);
}
+ if (FLAG_trace_shutdown) {
+ OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: %" Pd
+ " time out waiting for "
+ "service and kernel isolates to shutdown\n",
+ UptimeMillis(), num_attempts);
+ }
+ }
+ }
+ if (FLAG_trace_shutdown) {
+ int64_t stop_time = UptimeMillis();
+ OS::PrintErr("[+%" Pd64
+ "ms] SHUTDOWN: Done waiting for service "
+ "and kernel isolates to shutdown\n",
+ stop_time);
+ if ((stop_time - start_time) > 500) {
+ OS::PrintErr("[+%" Pd64
+ "ms] SHUTDOWN: waited too long for service "
+ "and kernel isolates to shutdown\n",
+ (stop_time - start_time));
}
}
@@ -642,6 +669,10 @@
UptimeMillis());
}
WaitForApplicationIsolateShutdown();
+ if (FLAG_trace_shutdown) {
+ OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Done shutting down app isolates\n",
+ UptimeMillis());
+ }
}
// Shutdown the kernel isolate.
@@ -658,12 +689,8 @@
}
ServiceIsolate::Shutdown();
- // Wait for the remaining isolate (service isolate) to shutdown
+ // Wait for the remaining isolate (service/kernel isolate) to shutdown
// before shutting down the thread pool.
- if (FLAG_trace_shutdown) {
- OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Waiting for isolate shutdown\n",
- UptimeMillis());
- }
WaitForIsolateShutdown();
#if !defined(PRODUCT)
@@ -696,6 +723,10 @@
thread_pool_->Shutdown();
delete thread_pool_;
thread_pool_ = NULL;
+ if (FLAG_trace_shutdown) {
+ OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Done deleting thread pool\n",
+ UptimeMillis());
+ }
Api::Cleanup();
delete predefined_handles_;
diff --git a/runtime/vm/isolate.cc b/runtime/vm/isolate.cc
index c1e6cbe..c546dba 100644
--- a/runtime/vm/isolate.cc
+++ b/runtime/vm/isolate.cc
@@ -62,6 +62,7 @@
DECLARE_FLAG(bool, print_metrics);
DECLARE_FLAG(bool, trace_service);
+DECLARE_FLAG(bool, trace_shutdown);
DECLARE_FLAG(bool, warn_on_pause_with_no_debugger);
// Reload flags.
@@ -488,6 +489,13 @@
}
void IsolateGroup::Shutdown() {
+ char* name;
+
+ if (FLAG_trace_shutdown) {
+ name = Utils::StrDup(source()->name);
+ OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Shutdown starting for group %s\n",
+ Dart::UptimeMillis(), name);
+ }
// Ensure to join all threads before waiting for pending GC tasks (the thread
// pool can trigger idle notification, which can start new GC tasks).
//
@@ -529,11 +537,28 @@
// After this isolate group has died we might need to notify a pending
// `Dart_Cleanup()` call.
{
+ if (FLAG_trace_shutdown) {
+ OS::PrintErr("[+%" Pd64
+ "ms] SHUTDOWN: Notifying "
+ "isolate group shutdown (%s)\n",
+ Dart::UptimeMillis(), name);
+ }
MonitorLocker ml(Isolate::isolate_creation_monitor_);
if (!Isolate::creation_enabled_ &&
!IsolateGroup::HasApplicationIsolateGroups()) {
ml.Notify();
}
+ if (FLAG_trace_shutdown) {
+ OS::PrintErr("[+%" Pd64
+ "ms] SHUTDOWN: Done Notifying "
+ "isolate group shutdown (%s)\n",
+ Dart::UptimeMillis(), name);
+ }
+ }
+ if (FLAG_trace_shutdown) {
+ OS::PrintErr("[+%" Pd64 "ms] SHUTDOWN: Done shutdown for group %s\n",
+ Dart::UptimeMillis(), name);
+ free(name);
}
}
@@ -2635,6 +2660,10 @@
// The current thread is running on the isolate group's thread pool.
// So we cannot safely delete the isolate group (and it's pool).
// Instead we will destroy the isolate group on the VM-global pool.
+ if (FLAG_trace_shutdown) {
+ OS::PrintErr("[+%" Pd64 "ms] : Scheduling shutdown on VM pool %s\n",
+ Dart::UptimeMillis(), isolate_group->source()->name);
+ }
Dart::thread_pool()->Run<ShutdownGroupTask>(isolate_group);
}
} else {
