KUDU-2322: don't spew logs about behind-log-GC follower

This patch addresses the issue of a leader spewing a lot of INFO
log messages about missing logs segments for a follower that falls
behind log GC.  In the 3-4-3 replica management scheme, such followers
linger around until corresponding non-voter replica catches up with
the leader.  That might take long time.

With this patch, the leader throttles messages about missing log
segments for a behind-log-GC follower, outputting 1 message per minute.

Change-Id: I4438e63aef0be26c149c57f9f58cb54327e41a33
Reviewed-on: http://gerrit.cloudera.org:8080/9573
Reviewed-by: Todd Lipcon <t...@apache.org>
Reviewed-by: Alexey Serbin <aser...@cloudera.com>
Tested-by: Kudu Jenkins


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

Branch: refs/heads/master
Commit: d856107e0b58067f0bbebbbda52f4f67c674897a
Parents: 4889a91
Author: Alexey Serbin <aser...@cloudera.com>
Authored: Fri Mar 9 20:31:24 2018 -0800
Committer: Alexey Serbin <aser...@cloudera.com>
Committed: Tue Mar 13 18:30:15 2018 +0000

----------------------------------------------------------------------
 src/kudu/consensus/consensus-test-util.h |  3 ++-
 src/kudu/consensus/consensus_peers.cc    |  3 +--
 src/kudu/consensus/consensus_queue.cc    | 34 ++++++++++++++++++++-------
 src/kudu/consensus/consensus_queue.h     | 20 +++++-----------
 src/kudu/util/logging.h                  |  2 +-
 5 files changed, 36 insertions(+), 26 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/kudu/blob/d856107e/src/kudu/consensus/consensus-test-util.h
----------------------------------------------------------------------
diff --git a/src/kudu/consensus/consensus-test-util.h 
b/src/kudu/consensus/consensus-test-util.h
index 9cb0473..36c2354 100644
--- a/src/kudu/consensus/consensus-test-util.h
+++ b/src/kudu/consensus/consensus-test-util.h
@@ -27,16 +27,17 @@
 #include <boost/bind.hpp>
 #include <gmock/gmock.h>
 
+#include "kudu/clock/clock.h"
 #include "kudu/common/timestamp.h"
 #include "kudu/common/wire_protocol.h"
 #include "kudu/consensus/consensus_peers.h"
 #include "kudu/consensus/consensus_queue.h"
 #include "kudu/consensus/log.h"
+#include "kudu/consensus/opid_util.h"
 #include "kudu/consensus/raft_consensus.h"
 #include "kudu/gutil/map-util.h"
 #include "kudu/gutil/strings/substitute.h"
 #include "kudu/rpc/messenger.h"
-#include "kudu/clock/clock.h"
 #include "kudu/util/countdown_latch.h"
 #include "kudu/util/locks.h"
 #include "kudu/util/pb_util.h"

http://git-wip-us.apache.org/repos/asf/kudu/blob/d856107e/src/kudu/consensus/consensus_peers.cc
----------------------------------------------------------------------
diff --git a/src/kudu/consensus/consensus_peers.cc 
b/src/kudu/consensus/consensus_peers.cc
index 4724ad9..8f3dadd 100644
--- a/src/kudu/consensus/consensus_peers.cc
+++ b/src/kudu/consensus/consensus_peers.cc
@@ -227,8 +227,7 @@ void Peer::SendNextRequest(bool even_if_queue_empty) {
       request_.committed_index() : kMinimumOpIdIndex;
 
   if (PREDICT_FALSE(!s.ok())) {
-    LOG_WITH_PREFIX_UNLOCKED(INFO) << "Could not obtain request from queue for 
peer: "
-        << peer_pb_.permanent_uuid() << ". Status: " << s.ToString();
+    VLOG_WITH_PREFIX_UNLOCKED(1) << s.ToString();
     return;
   }
 

http://git-wip-us.apache.org/repos/asf/kudu/blob/d856107e/src/kudu/consensus/consensus_queue.cc
----------------------------------------------------------------------
diff --git a/src/kudu/consensus/consensus_queue.cc 
b/src/kudu/consensus/consensus_queue.cc
index 5b6206d..28110aa 100644
--- a/src/kudu/consensus/consensus_queue.cc
+++ b/src/kudu/consensus/consensus_queue.cc
@@ -20,6 +20,7 @@
 #include <cstdint>
 #include <functional>
 #include <iostream>
+#include <memory>
 #include <mutex>
 #include <string>
 #include <unordered_set>
@@ -122,6 +123,19 @@ const char* PeerStatusToString(PeerStatus p) {
   return "<unknown>";
 }
 
+PeerMessageQueue::TrackedPeer::TrackedPeer(RaftPeerPB peer_pb)
+    : peer_pb(std::move(peer_pb)),
+      next_index(kInvalidOpIdIndex),
+      last_received(MinimumOpId()),
+      last_known_committed_index(MinimumOpId().index()),
+      last_exchange_status(PeerStatus::NEW),
+      last_communication_time(MonoTime::Now()),
+      wal_catchup_possible(true),
+      last_overall_health_status(HealthReportPB::UNKNOWN),
+      status_log_throttler(std::make_shared<logging::LogThrottler>()),
+      last_seen_term_(0) {
+}
+
 std::string PeerMessageQueue::TrackedPeer::ToString() const {
   return Substitute("Peer: $0, Status: $1, Last received: $2, Next index: $3, "
                     "Last known committed idx: $4, Time since last 
communication: $5",
@@ -587,7 +601,8 @@ Status PeerMessageQueue::RequestForPeer(const string& uuid,
 
     TrackedPeer* peer = FindPtrOrNull(peers_map_, uuid);
     if (PREDICT_FALSE(peer == nullptr || queue_state_.mode == NON_LEADER)) {
-      return Status::NotFound("Peer not tracked or queue not in leader mode.");
+      return Status::NotFound(Substitute("peer $0 is no longer tracked or "
+                                         "queue is not in leader mode", uuid));
     }
     peer_copy = *peer;
 
@@ -645,17 +660,20 @@ Status PeerMessageQueue::RequestForPeer(const string& 
uuid,
                                   &preceding_id);
     if (PREDICT_FALSE(!s.ok())) {
       // It's normal to have a NotFound() here if a follower falls behind where
-      // the leader has GCed its logs.
+      // the leader has GCed its logs. The follower replica will hang around
+      // for a while until it's evicted.
       if (PREDICT_TRUE(s.IsNotFound())) {
-        string msg = Substitute("The logs necessary to catch up peer $0 have 
been "
-                                "garbage collected. The follower will never be 
able "
-                                "to catch up ($1)", uuid, s.ToString());
+        KLOG_EVERY_N_SECS_THROTTLER(INFO, 60, *peer_copy.status_log_throttler, 
"logs_gced")
+            << LogPrefixUnlocked()
+            << Substitute("The logs necessary to catch up peer $0 have been "
+                          "garbage collected. The follower will never be able "
+                          "to catch up ($1)", uuid, s.ToString());
         wal_catchup_failure = true;
         return s;
-      // IsIncomplete() means that we tried to read beyond the head of the log
-      // (in the future). See KUDU-1078.
       }
       if (s.IsIncomplete()) {
+        // IsIncomplete() means that we tried to read beyond the head of the 
log
+        // (in the future). See KUDU-1078.
         LOG_WITH_PREFIX_UNLOCKED(ERROR) << "Error trying to read ahead of the 
log "
                                         << "while preparing peer request: "
                                         << s.ToString() << ". Destination 
peer: "
@@ -690,7 +708,7 @@ Status PeerMessageQueue::RequestForPeer(const string& uuid,
   if (request->ops_size() > 0) {
     int64_t last_op_sent = request->ops(request->ops_size() - 1).id().index();
     if (last_op_sent < request->committed_index()) {
-      KLOG_EVERY_N_SECS_THROTTLER(INFO, 3, peer_copy.status_log_throttler, 
"lagging")
+      KLOG_EVERY_N_SECS_THROTTLER(INFO, 3, *peer_copy.status_log_throttler, 
"lagging")
           << LogPrefixUnlocked() << "Peer " << uuid << " is lagging by at 
least "
           << (request->committed_index() - last_op_sent)
           << " ops behind the committed index " << THROTTLE_MSG;

http://git-wip-us.apache.org/repos/asf/kudu/blob/d856107e/src/kudu/consensus/consensus_queue.h
----------------------------------------------------------------------
diff --git a/src/kudu/consensus/consensus_queue.h 
b/src/kudu/consensus/consensus_queue.h
index e3a148c..626f8e3 100644
--- a/src/kudu/consensus/consensus_queue.h
+++ b/src/kudu/consensus/consensus_queue.h
@@ -24,7 +24,6 @@
 #include <memory>
 #include <string>
 #include <unordered_map>
-#include <utility>
 #include <vector>
 
 #include <boost/optional/optional.hpp>
@@ -34,13 +33,11 @@
 #include "kudu/consensus/log_cache.h"
 #include "kudu/consensus/metadata.pb.h"
 #include "kudu/consensus/opid.pb.h"
-#include "kudu/consensus/opid_util.h"
 #include "kudu/consensus/ref_counted_replicate.h"
 #include "kudu/gutil/gscoped_ptr.h"
 #include "kudu/gutil/ref_counted.h"
 #include "kudu/gutil/threading/thread_collision_warner.h"
 #include "kudu/util/locks.h"
-#include "kudu/util/logging.h"
 #include "kudu/util/metrics.h"
 #include "kudu/util/monotime.h"
 #include "kudu/util/status.h"
@@ -53,6 +50,10 @@ namespace log {
 class Log;
 }
 
+namespace logging {
+class LogThrottler;
+}
+
 namespace consensus {
 class ConsensusRequestPB;
 class ConsensusResponsePB;
@@ -114,16 +115,7 @@ const char* PeerStatusToString(PeerStatus p);
 class PeerMessageQueue {
  public:
   struct TrackedPeer {
-    explicit TrackedPeer(RaftPeerPB peer_pb)
-        : peer_pb(std::move(peer_pb)),
-          next_index(kInvalidOpIdIndex),
-          last_received(MinimumOpId()),
-          last_known_committed_index(MinimumOpId().index()),
-          last_exchange_status(PeerStatus::NEW),
-          last_communication_time(MonoTime::Now()),
-          wal_catchup_possible(true),
-          last_overall_health_status(HealthReportPB::UNKNOWN),
-          last_seen_term_(0) {}
+    explicit TrackedPeer(RaftPeerPB peer_pb);
 
     TrackedPeer() = default;
 
@@ -180,7 +172,7 @@ class PeerMessageQueue {
 
     // Throttler for how often we will log status messages pertaining to this
     // peer (eg when it is lagging, etc).
-    logging::LogThrottler status_log_throttler;
+    std::shared_ptr<logging::LogThrottler> status_log_throttler;
 
    private:
     // The last term we saw from a given peer.

http://git-wip-us.apache.org/repos/asf/kudu/blob/d856107e/src/kudu/util/logging.h
----------------------------------------------------------------------
diff --git a/src/kudu/util/logging.h b/src/kudu/util/logging.h
index 9aa06ac..fbd614f 100644
--- a/src/kudu/util/logging.h
+++ b/src/kudu/util/logging.h
@@ -155,7 +155,7 @@ class ScopedDisableRedaction {
 
 #define KLOG_EVERY_N_SECS_THROTTLER(severity, n_secs, throttler, tag) \
   int VARNAME_LINENUM(num_suppressed) = 0;                            \
-  if (throttler.ShouldLog(n_secs, tag, &VARNAME_LINENUM(num_suppressed)))  \
+  if ((throttler).ShouldLog(n_secs, tag, &VARNAME_LINENUM(num_suppressed)))  \
     google::LogMessage( \
       __FILE__, __LINE__, google::GLOG_ ## severity, 
VARNAME_LINENUM(num_suppressed), \
       &google::LogMessage::SendToLog).stream()

Reply via email to