Merge pull request #17457 from muxi/alternate-debug-counters

Add more counters to debug the timer crash on iOS

3 files changed, 115 insertions, 4 deletions

diff --git a/src/core/lib/gpr/sync_posix.cc b/src/core/lib/gpr/sync_posix.cc
index 69bd609485..c09a7598ac 100644
--- a/src/core/lib/gpr/sync_posix.cc
+++ b/src/core/lib/gpr/sync_posix.cc
@@ -30,11 +30,18 @@
 // For debug of the timer manager crash only.
 // TODO (mxyan): remove after bug is fixed.
 #ifdef GRPC_DEBUG_TIMER_MANAGER
+#include <string.h>
 void (*g_grpc_debug_timer_manager_stats)(
     int64_t timer_manager_init_count, int64_t timer_manager_shutdown_count,
     int64_t fork_count, int64_t timer_wait_err, int64_t timer_cv_value,
     int64_t timer_mu_value, int64_t abstime_sec_value,
-    int64_t abstime_nsec_value) = nullptr;
+    int64_t abstime_nsec_value, int64_t abs_deadline_sec_value,
+    int64_t abs_deadline_nsec_value, int64_t now1_sec_value,
+    int64_t now1_nsec_value, int64_t now2_sec_value, int64_t now2_nsec_value,
+    int64_t add_result_sec_value, int64_t add_result_nsec_value,
+    int64_t sub_result_sec_value, int64_t sub_result_nsec_value,
+    int64_t next_value, int64_t start_time_sec,
+    int64_t start_time_nsec) = nullptr;
 int64_t g_timer_manager_init_count = 0;
 int64_t g_timer_manager_shutdown_count = 0;
 int64_t g_fork_count = 0;
@@ -43,6 +50,19 @@ int64_t g_timer_cv_value = 0;
 int64_t g_timer_mu_value = 0;
 int64_t g_abstime_sec_value = -1;
 int64_t g_abstime_nsec_value = -1;
+int64_t g_abs_deadline_sec_value = -1;
+int64_t g_abs_deadline_nsec_value = -1;
+int64_t g_now1_sec_value = -1;
+int64_t g_now1_nsec_value = -1;
+int64_t g_now2_sec_value = -1;
+int64_t g_now2_nsec_value = -1;
+int64_t g_add_result_sec_value = -1;
+int64_t g_add_result_nsec_value = -1;
+int64_t g_sub_result_sec_value = -1;
+int64_t g_sub_result_nsec_value = -1;
+int64_t g_next_value = -1;
+int64_t g_start_time_sec = -1;
+int64_t g_start_time_nsec = -1;
 #endif  // GRPC_DEBUG_TIMER_MANAGER
 
 #ifdef GPR_LOW_LEVEL_COUNTERS
@@ -90,17 +110,74 @@ void gpr_cv_init(gpr_cv* cv) {
 
 void gpr_cv_destroy(gpr_cv* cv) { GPR_ASSERT(pthread_cond_destroy(cv) == 0); }
 
+// For debug of the timer manager crash only.
+// TODO (mxyan): remove after bug is fixed.
+#ifdef GRPC_DEBUG_TIMER_MANAGER
+static gpr_timespec gpr_convert_clock_type_debug_timespec(
+    gpr_timespec t, gpr_clock_type clock_type, gpr_timespec& now1,
+    gpr_timespec& now2, gpr_timespec& add_result, gpr_timespec& sub_result) {
+  if (t.clock_type == clock_type) {
+    return t;
+  }
+
+  if (t.tv_sec == INT64_MAX || t.tv_sec == INT64_MIN) {
+    t.clock_type = clock_type;
+    return t;
+  }
+
+  if (clock_type == GPR_TIMESPAN) {
+    return gpr_time_sub(t, gpr_now(t.clock_type));
+  }
+
+  if (t.clock_type == GPR_TIMESPAN) {
+    return gpr_time_add(gpr_now(clock_type), t);
+  }
+
+  now1 = gpr_now(t.clock_type);
+  sub_result = gpr_time_sub(t, now1);
+  now2 = gpr_now(clock_type);
+  add_result = gpr_time_add(now2, sub_result);
+  return add_result;
+}
+
+#define gpr_convert_clock_type_debug(t, clock_type, now1, now2, add_result, \
+                                     sub_result)                            \
+  gpr_convert_clock_type_debug_timespec((t), (clock_type), (now1), (now2),  \
+                                        (add_result), (sub_result))
+#else
+#define gpr_convert_clock_type_debug(t, clock_type, now1, now2, add_result, \
+                                     sub_result)                            \
+  gpr_convert_clock_type((t), (clock_type))
+#endif
+
 int gpr_cv_wait(gpr_cv* cv, gpr_mu* mu, gpr_timespec abs_deadline) {
   int err = 0;
+#ifdef GRPC_DEBUG_TIMER_MANAGER
+  // For debug of the timer manager crash only.
+  // TODO (mxyan): remove after bug is fixed.
+  gpr_timespec abs_deadline_copy;
+  abs_deadline_copy.tv_sec = abs_deadline.tv_sec;
+  abs_deadline_copy.tv_nsec = abs_deadline.tv_nsec;
+  gpr_timespec now1;
+  gpr_timespec now2;
+  gpr_timespec add_result;
+  gpr_timespec sub_result;
+  memset(&now1, 0, sizeof(now1));
+  memset(&now2, 0, sizeof(now2));
+  memset(&add_result, 0, sizeof(add_result));
+  memset(&sub_result, 0, sizeof(sub_result));
+#endif
   if (gpr_time_cmp(abs_deadline, gpr_inf_future(abs_deadline.clock_type)) ==
       0) {
     err = pthread_cond_wait(cv, mu);
   } else {
     struct timespec abs_deadline_ts;
 #if GPR_LINUX
-    abs_deadline = gpr_convert_clock_type(abs_deadline, GPR_CLOCK_MONOTONIC);
+    abs_deadline = gpr_convert_clock_type_debug(
+        abs_deadline, GPR_CLOCK_MONOTONIC, now1, now2, add_result, sub_result);
 #else
-    abs_deadline = gpr_convert_clock_type(abs_deadline, GPR_CLOCK_REALTIME);
+    abs_deadline = gpr_convert_clock_type_debug(
+        abs_deadline, GPR_CLOCK_REALTIME, now1, now2, add_result, sub_result);
 #endif  // GPR_LINUX
     abs_deadline_ts.tv_sec = static_cast<time_t>(abs_deadline.tv_sec);
     abs_deadline_ts.tv_nsec = abs_deadline.tv_nsec;
@@ -123,10 +200,25 @@ int gpr_cv_wait(gpr_cv* cv, gpr_mu* mu, gpr_timespec abs_deadline) {
       g_timer_wait_err = err;
       g_timer_cv_value = (int64_t)cv;
       g_timer_mu_value = (int64_t)mu;
+      g_abs_deadline_sec_value = abs_deadline_copy.tv_sec;
+      g_abs_deadline_nsec_value = abs_deadline_copy.tv_nsec;
+      g_now1_sec_value = now1.tv_sec;
+      g_now1_nsec_value = now1.tv_nsec;
+      g_now2_sec_value = now2.tv_sec;
+      g_now2_nsec_value = now2.tv_nsec;
+      g_add_result_sec_value = add_result.tv_sec;
+      g_add_result_nsec_value = add_result.tv_nsec;
+      g_sub_result_sec_value = sub_result.tv_sec;
+      g_sub_result_nsec_value = sub_result.tv_nsec;
       g_grpc_debug_timer_manager_stats(
           g_timer_manager_init_count, g_timer_manager_shutdown_count,
           g_fork_count, g_timer_wait_err, g_timer_cv_value, g_timer_mu_value,
-          g_abstime_sec_value, g_abstime_nsec_value);
+          g_abstime_sec_value, g_abstime_nsec_value, g_abs_deadline_sec_value,
+          g_abs_deadline_nsec_value, g_now1_sec_value, g_now1_nsec_value,
+          g_now2_sec_value, g_now2_nsec_value, g_add_result_sec_value,
+          g_add_result_nsec_value, g_sub_result_sec_value,
+          g_sub_result_nsec_value, g_next_value, g_start_time_sec,
+          g_start_time_nsec);
     }
   }
 #endif
diff --git a/src/core/lib/iomgr/exec_ctx.cc b/src/core/lib/iomgr/exec_ctx.cc
index d68fa0714b..683dd2f649 100644
--- a/src/core/lib/iomgr/exec_ctx.cc
+++ b/src/core/lib/iomgr/exec_ctx.cc
@@ -53,6 +53,13 @@ static void exec_ctx_sched(grpc_closure* closure, grpc_error* error) {
 
 static gpr_timespec g_start_time;
 
+// For debug of the timer manager crash only.
+// TODO (mxyan): remove after bug is fixed.
+#ifdef GRPC_DEBUG_TIMER_MANAGER
+extern int64_t g_start_time_sec;
+extern int64_t g_start_time_nsec;
+#endif  // GRPC_DEBUG_TIMER_MANAGER
+
 static grpc_millis timespec_to_millis_round_down(gpr_timespec ts) {
   ts = gpr_time_sub(ts, g_start_time);
   double x = GPR_MS_PER_SEC * static_cast<double>(ts.tv_sec) +
@@ -117,6 +124,12 @@ void ExecCtx::TestOnlyGlobalInit(gpr_timespec new_val) {
 
 void ExecCtx::GlobalInit(void) {
   g_start_time = gpr_now(GPR_CLOCK_MONOTONIC);
+  // For debug of the timer manager crash only.
+  // TODO (mxyan): remove after bug is fixed.
+#ifdef GRPC_DEBUG_TIMER_MANAGER
+  g_start_time_sec = g_start_time.tv_sec;
+  g_start_time_nsec = g_start_time.tv_nsec;
+#endif
   gpr_tls_init(&exec_ctx_);
 }
 
diff --git a/src/core/lib/iomgr/timer_manager.cc b/src/core/lib/iomgr/timer_manager.cc
index ceba79f678..cb123298cf 100644
--- a/src/core/lib/iomgr/timer_manager.cc
+++ b/src/core/lib/iomgr/timer_manager.cc
@@ -67,6 +67,7 @@ static void timer_thread(void* completed_thread_ptr);
 extern int64_t g_timer_manager_init_count;
 extern int64_t g_timer_manager_shutdown_count;
 extern int64_t g_fork_count;
+extern int64_t g_next_value;
 #endif  // GRPC_DEBUG_TIMER_MANAGER
 
 static void gc_completed_threads(void) {
@@ -193,6 +194,11 @@ static bool wait_until(grpc_millis next) {
       gpr_log(GPR_INFO, "sleep until kicked");
     }
 
+      // For debug of the timer manager crash only.
+      // TODO (mxyan): remove after bug is fixed.
+#ifdef GRPC_DEBUG_TIMER_MANAGER
+    g_next_value = next;
+#endif
     gpr_cv_wait(&g_cv_wait, &g_mu,
                 grpc_millis_to_timespec(next, GPR_CLOCK_MONOTONIC));