kudu-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From t...@apache.org
Subject [2/3] kudu git commit: KUDU-2297 (part 6): enable periodic stack sampling by default, avoid bias
Date Thu, 08 Mar 2018 23:52:23 GMT
KUDU-2297 (part 6): enable periodic stack sampling by default, avoid bias

This changes the timing for the collection of stack samples into the
metrics log to avoid two issues:

1) Inflexible configuration: in many cases we might want to sample
stacks more or less frequently than metrics. The previous implementation
used the same schedule for both.

2) Sampling bias: if we collect stack samples on a fixed schedule, we
risk unintended correlation with background tasks that might run on a
similar fixed schedule. For example, if we collect stacks exactly once a
minute, and the user has some monitoring software which polls the HTTP
server once a minute for some data, we might either line up perfectly
with the polling (in which case we'd overestimate its impact) or line of
perfectly away from the polling (in which case we'd never see its
effects).

This patch changes the wakeups for stacks and metrics to be decoupled.
In addition, it adds randomness to the stack sampling. The configuration
now represents the mean sampling rate rather than an exact sampling
rate.

I manually ran a master with -diagnostics-log-stack-traces-interval-ms=2000
and verified that the stack sample times were between 0 and 4 seconds apart
while the metric dumps were still exactly one minute apart. I also plan
to modify some local test clusters to configure this to be relatively
frequent to try to suss out any races or bugs which might occur in a
real workload.

Change-Id: I538eb59f95a695fa2da50f24ed82148715b15e44
Reviewed-on: http://gerrit.cloudera.org:8080/9523
Tested-by: Todd Lipcon <todd@apache.org>
Reviewed-by: Adar Dembo <adar@cloudera.com>


Project: http://git-wip-us.apache.org/repos/asf/kudu/repo
Commit: http://git-wip-us.apache.org/repos/asf/kudu/commit/0c39ed7e
Tree: http://git-wip-us.apache.org/repos/asf/kudu/tree/0c39ed7e
Diff: http://git-wip-us.apache.org/repos/asf/kudu/diff/0c39ed7e

Branch: refs/heads/master
Commit: 0c39ed7e302f08e3030e9e708739dc6a6862bf4b
Parents: 96b3b63
Author: Todd Lipcon <todd@apache.org>
Authored: Tue Mar 6 17:15:00 2018 -0800
Committer: Todd Lipcon <todd@apache.org>
Committed: Thu Mar 8 18:53:07 2018 +0000

----------------------------------------------------------------------
 src/kudu/server/diagnostics_log.cc | 119 +++++++++++++++++++-------------
 src/kudu/server/diagnostics_log.h  |   7 ++
 2 files changed, 77 insertions(+), 49 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/kudu/blob/0c39ed7e/src/kudu/server/diagnostics_log.cc
----------------------------------------------------------------------
diff --git a/src/kudu/server/diagnostics_log.cc b/src/kudu/server/diagnostics_log.cc
index 60634fa..f4dce27 100644
--- a/src/kudu/server/diagnostics_log.cc
+++ b/src/kudu/server/diagnostics_log.cc
@@ -18,8 +18,10 @@
 #include "kudu/server/diagnostics_log.h"
 
 #include <cstdint>
+#include <functional>
 #include <memory>
 #include <ostream>
+#include <queue>
 #include <string>
 #include <utility>
 #include <vector>
@@ -43,11 +45,15 @@
 #include "kudu/util/metrics.h"
 #include "kudu/util/monotime.h"
 #include "kudu/util/mutex.h"
+#include "kudu/util/random.h"
+#include "kudu/util/random_util.h"
 #include "kudu/util/rolling_log.h"
 #include "kudu/util/scoped_cleanup.h"
 #include "kudu/util/status.h"
 #include "kudu/util/thread.h"
 
+using std::pair;
+using std::priority_queue;
 using std::string;
 using std::unique_ptr;
 using std::vector;
@@ -62,13 +68,14 @@ namespace google {
 bool Symbolize(void *pc, char *out, int out_size);
 }
 
-
-// TODO(todd): this is a placeholder flag. This should actually be an interval.
-// Tagging as experimental and disabling by default while this work is in flux.
-DEFINE_bool(diagnostics_log_stack_traces, false,
-            "Whether to periodically log stack traces to the diagnostics log.");
-TAG_FLAG(diagnostics_log_stack_traces, runtime);
-TAG_FLAG(diagnostics_log_stack_traces, experimental);
+DEFINE_uint32(diagnostics_log_stack_traces_interval_ms, 60000,
+             "The interval at which the server will a snapshot of its thread stacks to the
"
+             "diagnostics log. In fact, the server will log at a random interval betweeen
"
+             "zero and twice the configured value to avoid biasing samples towards periodic
"
+             "processes which happen exactly on some particular schedule. If this is set
to "
+             "0, stack traces will be not be periodically logged.");
+TAG_FLAG(diagnostics_log_stack_traces_interval_ms, runtime);
+TAG_FLAG(diagnostics_log_stack_traces_interval_ms, experimental);
 
 namespace kudu {
 namespace server {
@@ -149,56 +156,70 @@ void DiagnosticsLog::Stop() {
   WARN_NOT_OK(log_->Close(), "Unable to close diagnostics log");
 }
 
-void DiagnosticsLog::RunThread() {
-  // How long to wait before trying again if we experience a failure
-  // logging metrics.
-  const MonoDelta kWaitBetweenFailures = MonoDelta::FromSeconds(60);
+MonoTime DiagnosticsLog::ComputeNextWakeup(DiagnosticsLog::WakeupType type) const {
+  switch (type) {
+    case WakeupType::STACKS:
+      if (FLAGS_diagnostics_log_stack_traces_interval_ms > 0) {
+        // Instead of directly using the configured interval, we use a uniform random
+        // interval whose mean is the configured value. This prevents biasing our stack
+        // samples. For example, if there is some background process which happens once a
+        // minute, and the user also configured the stacks to once a minute, an operator
+        // might incorrectly surmise that the background task was _always_ running.
+        // Randomizing the samples avoids such correlations.
+        Random rng(GetRandomSeed32());
+        int64_t ms = rng.Uniform(FLAGS_diagnostics_log_stack_traces_interval_ms * 2);
+        return MonoTime::Now() + MonoDelta::FromMilliseconds(ms);
+      } else {
+        // Stack tracing is disabled. However we still wake up periodically because the
+        // flag is runtime-modifiable, and we need to wake up to notice that it might have
+        // changed.
+        return MonoTime::Now() + MonoDelta::FromSeconds(5);
+      }
+      break;
+    case WakeupType::METRICS:
+      return MonoTime::Now() + metrics_log_interval_;
+  }
+  __builtin_unreachable();
+}
 
+void DiagnosticsLog::RunThread() {
   MutexLock l(lock_);
 
-  MonoTime next_log = MonoTime::Now();
+  // Set up a priority queue which tracks our future scheduled wake-ups.
+  typedef pair<MonoTime, WakeupType> QueueElem;
+  priority_queue<QueueElem, vector<QueueElem>, std::greater<QueueElem>>
wakeups;
+  wakeups.emplace(ComputeNextWakeup(WakeupType::METRICS), WakeupType::METRICS);
+  wakeups.emplace(ComputeNextWakeup(WakeupType::STACKS), WakeupType::STACKS);
+
   while (!stop_) {
+    MonoTime next_log = wakeups.top().first;
     wake_.TimedWait(next_log - MonoTime::Now());
-    bool reached_time = MonoTime::Now() > next_log;
-
-    if (reached_time) {
-      Status s;
-      {
-        // Unlock the mutex while actually logging metrics since it's somewhat
-        // slow and we don't want to block threads trying to signal us.
-        l.Unlock();
-        SCOPED_CLEANUP({ l.Lock(); });
-        s = LogMetrics();
-      }
 
-      if (!s.ok()) {
-        WARN_NOT_OK(s, Substitute(
-            "Unable to collect metrics to diagnostics log. Will try again in $0",
-            kWaitBetweenFailures.ToString()));
-        next_log = MonoTime::Now() + kWaitBetweenFailures;
-      } else {
-        next_log = MonoTime::Now() + metrics_log_interval_;
-      }
+    string reason;
+    WakeupType what;
+    if (dump_stacks_now_reason_) {
+      what = WakeupType::STACKS;
+      reason = std::move(*dump_stacks_now_reason_);
+      dump_stacks_now_reason_ = boost::none;
+    } else if (MonoTime::Now() >= next_log) {
+      what = wakeups.top().second;
+      reason = "periodic";
+      wakeups.pop();
+      wakeups.emplace(ComputeNextWakeup(what), what);
+    } else {
+      // Spurious wakeup, or a stop trigger.
+      continue;
     }
 
-    if ((reached_time && FLAGS_diagnostics_log_stack_traces) ||
-        dump_stacks_now_reason_) {
-      string reason = dump_stacks_now_reason_.value_or("periodic");
-      Status s;
-      {
-        // Unlock the mutex while actually logging stacks since it's somewhat
-        // slow and we don't want to block threads trying to signal us.
-        l.Unlock();
-        SCOPED_CLEANUP({ l.Lock(); });
-        s = LogStacks(reason);
-      }
-      if (!s.ok()) {
-        WARN_NOT_OK(s, "Unable to collect stacks to diagnostics log");
-        next_log = MonoTime::Now() + kWaitBetweenFailures;
-      } else {
-        next_log = MonoTime::Now() + metrics_log_interval_;
-      }
-      dump_stacks_now_reason_ = boost::none;
+    // Unlock the mutex while actually logging metrics or stacks since it's somewhat
+    // slow and we don't want to block threads trying to signal us.
+    l.Unlock();
+    SCOPED_CLEANUP({ l.Lock(); });
+    Status s;
+    if (what == WakeupType::METRICS) {
+      WARN_NOT_OK(LogMetrics(), "Unable to collect metrics to diagnostics log");
+    } else if (what == WakeupType::STACKS && FLAGS_diagnostics_log_stack_traces_interval_ms
> 0) {
+      WARN_NOT_OK(LogStacks(reason), "Unable to collect stacks to diagnostics log");
     }
   }
 }

http://git-wip-us.apache.org/repos/asf/kudu/blob/0c39ed7e/src/kudu/server/diagnostics_log.h
----------------------------------------------------------------------
diff --git a/src/kudu/server/diagnostics_log.h b/src/kudu/server/diagnostics_log.h
index bbf97ad..5b8cfab 100644
--- a/src/kudu/server/diagnostics_log.h
+++ b/src/kudu/server/diagnostics_log.h
@@ -56,10 +56,17 @@ class DiagnosticsLog {
  private:
   class SymbolSet;
 
+  enum class WakeupType {
+    METRICS,
+    STACKS
+  };
+
   void RunThread();
   Status LogMetrics();
   Status LogStacks(const std::string& reason);
 
+  MonoTime ComputeNextWakeup(DiagnosticsLog::WakeupType type) const;
+
   const std::string log_dir_;
   const MetricRegistry* metric_registry_;
 


Mime
View raw message