Integrate CallbacksMonitor into Java Borg Debugger for the upcoming support of breakpoints canary

vladlf · emrekultursay · commit 5e6ef36456cf · 2016-02-02T15:56:57.000-08:00
FEATURE: borg-debugger RELNOTES: N/A ------------- Created by MOE: https://github.com/google/moe MOE_MIGRATED_REVID=112839765
diff --git a/src/agent/callbacks_monitor.cc b/src/agent/callbacks_monitor.cc
@@ -0,0 +1,106 @@
+/**
+ * Copyright 2016 Google Inc. All Rights Reserved.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "callbacks_monitor.h"
+
+#include <time.h>
+
+namespace devtools {
+namespace cdbg {
+
+static CallbacksMonitor* g_instance = nullptr;
+
+void CallbacksMonitor::InitializeSingleton(int max_interval_ms) {
+  DCHECK(g_instance == nullptr);
+
+  g_instance = new CallbacksMonitor(max_interval_ms);
+}
+
+
+void CallbacksMonitor::CleanupSingleton() {
+  delete g_instance;
+  g_instance = nullptr;
+}
+
+
+CallbacksMonitor* CallbacksMonitor::GetInstance() {
+  DCHECK(g_instance != nullptr);
+  return g_instance;
+}
+
+
+int64 CallbacksMonitor::MonotonicClockMillis() {
+  struct timespec tp;
+  clock_gettime(CLOCK_MONOTONIC, &tp);
+  return tp.tv_sec * 1000L + tp.tv_nsec / 1000000L;
+}
+
+
+CallbacksMonitor::Id CallbacksMonitor::RegisterCall(const char* tag) {
+  OngoingCall ongoing_call { GetCurrentTimeMillis(), tag };
+
+  std::lock_guard<std::mutex> lock(mu_);
+  return ongoing_calls_.insert(ongoing_calls_.begin(), ongoing_call);
+}
+
+
+void CallbacksMonitor::CompleteCall(CallbacksMonitor::Id id) {
+  int64 current_time_ms = GetCurrentTimeMillis();
+
+  std::lock_guard<std::mutex> lock(mu_);
+
+  if (current_time_ms - id->start_time_ms > max_call_duration_ms_) {
+    LOG(INFO) << "Cloud Debugger call \"" << id->tag
+              << "\" completed after " << current_time_ms - id->start_time_ms
+              << " ms";
+    last_unhealthy_time_ms_ = current_time_ms;
+  }
+
+  ongoing_calls_.erase(id);
+}
+
+
+bool CallbacksMonitor::IsHealthy(int64 timestamp) const {
+  bool rc = true;
+  int64 current_time_ms = GetCurrentTimeMillis();
+
+  std::lock_guard<std::mutex> lock(mu_);
+
+  if (last_unhealthy_time_ms_ >= timestamp) {
+    LOG(WARNING) << "Unhealthy callback completed "
+                 << current_time_ms - last_unhealthy_time_ms_ << " ms ago";
+    return false;
+  }
+
+  for (auto it = ongoing_calls_.begin(); it != ongoing_calls_.end(); ++it) {
+    int64 duration_ms = current_time_ms - it->start_time_ms;
+    if (duration_ms > max_call_duration_ms_) {
+      LOG(WARNING) << "Cloud Debugger call \"" << it->tag
+                   << "\" hasn't completed in " << duration_ms
+                   << " ms, possibly stuck";
+      rc = false;
+    }
+  }
+
+  return rc;
+}
+
+}  // namespace cdbg
+}  // namespace devtools
+
+
+
+
diff --git a/src/agent/callbacks_monitor.h b/src/agent/callbacks_monitor.h
@@ -0,0 +1,123 @@
+/**
+ * Copyright 2016 Google Inc. All Rights Reserved.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef DEVTOOLS_CDBG_COMMON_CALLBACKS_MONITOR_H_
+#define DEVTOOLS_CDBG_COMMON_CALLBACKS_MONITOR_H_
+
+#include <functional>
+#include <list>
+#include <mutex>  // NOLINT
+
+#include "common.h"
+
+namespace devtools {
+namespace cdbg {
+
+// Keeps track of all the ongoing and past calls to allow detection of
+// stuck ones or those that just take too much time. Once a stuck callback is
+// detected, the caller should declare the agent as unhealthy.
+//
+// The class is optimized for performance of registering/completing new calls.
+class CallbacksMonitor {
+ public:
+  struct OngoingCall {
+    int64 start_time_ms;
+    const char* tag;
+  };
+
+  typedef std::list<OngoingCall>::iterator Id;
+
+  CallbacksMonitor(
+      int max_call_duration_ms,
+      std::function<int64()> fn_gettime = MonotonicClockMillis)
+      : max_call_duration_ms_(max_call_duration_ms),
+        fn_gettime_(fn_gettime),
+        last_unhealthy_time_ms_(-1) {
+  }
+
+  ~CallbacksMonitor() {
+    DCHECK(ongoing_calls_.empty());
+  }
+
+  // One time initialization of the global instance.
+  static void InitializeSingleton(int max_interval_ms);
+
+  // One time cleanup of the global instance.
+  static void CleanupSingleton();
+
+  // Gets the global instance of this class.
+  static CallbacksMonitor* GetInstance();
+
+  // Gets the current time.
+  int64 GetCurrentTimeMillis() const { return fn_gettime_(); }
+
+  // Notifies start of an operation to monitor. The "tag" is a human readable
+  // name of this callback. It is only used for logging purposes.
+  Id RegisterCall(const char* tag);
+
+  // Notifies completion of an operation started with "RegisterCall".
+  void CompleteCall(Id id);
+
+  // Returns true if there are no ongoing calls that already take more than
+  // "max_interval_ms_" and that no completed call took more than
+  // "max_interval_ms_" after "timestamp" time.
+  bool IsHealthy(int64 timestamp) const;
+
+  // Returns the current time in milliseconds.
+  static int64 MonotonicClockMillis();
+
+ private:
+  // Maximum allowed duration of the healthy callback.
+  const int max_call_duration_ms_;
+
+  // Function to get the current time. Defined explicitly for unit tests.
+  std::function<int64()> fn_gettime_;
+
+  // Protects access to "ongoing_calls_" and "last_unhealthy_timestamp_".
+  mutable std::mutex mu_;
+
+  // Linked list of currently active calls to monitor.
+  std::list<OngoingCall> ongoing_calls_;
+
+  // Timestamp of the completion of last callback that lasted more than
+  // "max_interval_ms_".
+  int64 last_unhealthy_time_ms_;
+
+  DISALLOW_COPY_AND_ASSIGN(CallbacksMonitor);
+};
+
+
+// Automatically calls "RegisterCall", "CompleteCall" on entry and scope exit.
+class ScopedMonitoredCall {
+ public:
+  explicit ScopedMonitoredCall(const char* tag)
+      : id_(CallbacksMonitor::GetInstance()->RegisterCall(tag)) {
+  }
+
+  ~ScopedMonitoredCall() {
+    CallbacksMonitor::GetInstance()->CompleteCall(id_);
+  }
+
+ private:
+  const CallbacksMonitor::Id id_;
+
+  DISALLOW_COPY_AND_ASSIGN(ScopedMonitoredCall);
+};
+
+}  // namespace cdbg
+}  // namespace devtools
+
+#endif  // DEVTOOLS_CDBG_COMMON_CALLBACKS_MONITOR_H_
diff --git a/src/agent/jvm_breakpoints_manager.cc b/src/agent/jvm_breakpoints_manager.cc
@@ -17,6 +17,7 @@
 #include "jvm_breakpoints_manager.h"
 
 #include <algorithm>
+#include "callbacks_monitor.h"
 #include "format_queue.h"
 #include "breakpoint.h"
 #include "jvm_evaluators.h"
@@ -86,6 +87,9 @@ void JvmBreakpointsManager::SetActiveBreakpointsList(
 
   // Identify deleted and new breakpoints.
   {
+    ScopedMonitoredCall monitored_call(
+        "BreakpointsManager:SetActiveBreakpoints:Scan");
+
     MutexLock lock_data(&mu_data_);
 
     for (int i = 0; i < breakpoints.size(); ++i) {
@@ -119,6 +123,9 @@ void JvmBreakpointsManager::SetActiveBreakpointsList(
 
   // Create new breakpoints.
   for (std::unique_ptr<BreakpointModel>& new_breakpoint : new_breakpoints) {
+    ScopedMonitoredCall monitored_call(
+        "BreakpointsManager:SetActiveBreakpoints:SetNewBreakpoint");
+
     LOG(INFO) << "Setting new breakpoint: " << new_breakpoint->id;
 
     std::shared_ptr<Breakpoint> jvm_breakpoint =
@@ -137,6 +144,9 @@ void JvmBreakpointsManager::SetActiveBreakpointsList(
 
   // Remove breakpoints that were not listed.
   for (auto& breakpoint : updated_active_breakpoints) {
+    ScopedMonitoredCall monitored_call(
+        "BreakpointsManager:SetActiveBreakpoints:RemoveCompletedBreakpoint");
+
     if (breakpoint.second != nullptr) {
       LOG(INFO) << "Completing breakpoint " << breakpoint.second->id()
                 << " (removed from active list by backend)";
diff --git a/src/agent/jvm_env.h b/src/agent/jvm_env.h
@@ -20,6 +20,13 @@
 namespace devtools {
 namespace cdbg {
 
+// Maximum time we allow the Cloud Debugger to spend inside a callback. Beyond
+// that we declare the agent as unhealthy. This is used for breakpoints canary.
+// The interval of 5 seconds is way longer than anything that the debugger
+// will ever take, but we need to account for potential GC cycles that
+// may interrupt the debugger operation.
+constexpr int MaxCallbackTimeMs = 5000;
+
 // Gets the global instance of JVMTI interface.
 jvmtiEnv* jvmti();
 
diff --git a/src/agent/jvmti_agent.cc b/src/agent/jvmti_agent.cc
@@ -19,6 +19,7 @@
 #include <atomic>
 #include <sstream>
 
+#include "callbacks_monitor.h"
 #include "auto_reset_event.h"
 #include "bridge.h"
 #include "config_builder.h"
@@ -120,6 +121,9 @@ JvmtiAgent::JvmtiAgent(
 
 
 JvmtiAgent::~JvmtiAgent() {
+  // Assert no unhealthy callbacks occurred throughout the debuglet lifetime.
+  LOG_IF(WARNING, !CallbacksMonitor::GetInstance()->IsHealthy(0))
+      << "Unhealthy callbacks occurred during debuglet lifetime";
 }
 
 
@@ -167,6 +171,8 @@ bool JvmtiAgent::OnLoad() {
 
 
 void JvmtiAgent::JvmtiOnVMInit(jthread thread) {
+  ScopedMonitoredCall monitored_call("JVMTI:VMInit");
+
   Stopwatch stopwatch;
 
   LOG(INFO) << "Java VM started";
@@ -210,10 +216,13 @@ void JvmtiAgent::JvmtiOnVMDeath() {
 // to it. The class provided in JvmtiOnClassLoad doesn't have methods
 // initialized so it not very useful for debugger.
 void JvmtiAgent::JvmtiOnClassLoad(jthread thread, jclass cls) {
+  // ScopedMonitoredCall monitored_call("JVMTI:ClassLoad");
 }
 
 
 void JvmtiAgent::JvmtiOnClassPrepare(jthread thread, jclass cls) {
+  ScopedMonitoredCall monitored_call("JVMTI:ClassPrepare");
+
   std::shared_ptr<Debugger> debugger = debugger_;
 
   if (debugger != nullptr) {
@@ -229,12 +238,15 @@ void JvmtiAgent::JvmtiOnCompiledMethodLoad(
     jint map_length,
     const jvmtiAddrLocationMap* map,
     const void* compile_info) {
+  // ScopedMonitoredCall monitored_call("JVMTI:CompiledMethodLoad");
 }
 
 
 void JvmtiAgent::JvmtiOnCompiledMethodUnload(
     jmethodID method,
     const void* code_addr) {
+  ScopedMonitoredCall monitored_call("JVMTI:CompiledMethodUnload");
+
   std::shared_ptr<Debugger> debugger = debugger_;
 
   if (debugger != nullptr) {
@@ -247,6 +259,8 @@ void JvmtiAgent::JvmtiOnBreakpoint(
     jthread thread,
     jmethodID method,
     jlocation location) {
+  ScopedMonitoredCall monitored_call("JVMTI:Breakpoint");
+
   // Ignore breakpoint events from debugger worker threads. Debugging
   // the debugger may cause deadlock.
   if (JvmtiAgentThread::IsInAgentThread()) {
@@ -340,6 +354,8 @@ bool JvmtiAgent::OnWorkerReady() {
 
 
 void JvmtiAgent::OnIdle() {
+  ScopedMonitoredCall monitored_call("Agent:Idle");
+
   // Invoke scheduled callbacks.
   // The precision of "scheduler_" has the granularity of "OnIdle" calls. This
   // is typically in the order of minutes. This precision is good enough
@@ -361,6 +377,9 @@ void JvmtiAgent::OnBreakpointsUpdated(
 
 
 void JvmtiAgent::EnableDebugger(bool is_enabled) {
+  ScopedMonitoredCall monitored_call(
+      is_enabled ? "Agent:EnableDebugger" : "Agent:DisableDebugger");
+
   if (is_enabled) {
     // Attach debugger if needed
     if (debugger_ == nullptr) {
diff --git a/src/agent/jvmti_globals.cc b/src/agent/jvmti_globals.cc
@@ -18,6 +18,7 @@
 #include <dirent.h>
 #include <memory>
 #include <sstream>
+#include "callbacks_monitor.h"
 #include "common.h"
 #include "jvm_eval_call_stack.h"
 #include "jvm_internals.h"
@@ -294,6 +295,8 @@ static void InitEnvironment(const char* options) {
 #endif  // STANDALONE_BUILD
 
   devtools::cdbg::InitializeStatisticians();
+  devtools::cdbg::CallbacksMonitor::InitializeSingleton(
+      devtools::cdbg::MaxCallbackTimeMs);
 }
 
 
@@ -382,6 +385,7 @@ Agent_OnLoad(JavaVM* vm, char* options, void* reserved) {
 JNIEXPORT void JNICALL Agent_OnUnload(JavaVM* vm) {
   CleanupAgent();
 
+  devtools::cdbg::CallbacksMonitor::CleanupSingleton();
   devtools::cdbg::CleanupStatisticians();
 }
 
