From c8aff620c273fd4579b23e1647450b6f00c6bac7 Mon Sep 17 00:00:00 2001
From: Patrick Donnelly <pdonnell@redhat.com>
Date: Sat, 11 Aug 2018 11:21:43 -0700
Subject: [PATCH] mds: report lagginess at lower debug

To help diagnose laggy daemons with performance tuned debug settings.

Signed-off-by: Patrick Donnelly <pdonnell@redhat.com>
---
 src/mds/Beacon.cc  | 22 ++++++++++------------
 src/mds/MDSRank.cc |  6 +++---
 2 files changed, 13 insertions(+), 15 deletions(-)

diff --git a/src/mds/Beacon.cc b/src/mds/Beacon.cc
index 27c7d5a2d8f..d1b751ee784 100644
--- a/src/mds/Beacon.cc
+++ b/src/mds/Beacon.cc
@@ -112,8 +112,8 @@ void Beacon::handle_mds_beacon(MMDSBeacon *m)
       last_acked_stamp = seq_stamp[seq];
       utime_t rtt = now - last_acked_stamp;
 
-      dout(10) << "handle_mds_beacon " << ceph_mds_state_name(m->get_state())
-	       << " seq " << m->get_seq() << " rtt " << rtt << dendl;
+      dout(5) << "handle_mds_beacon " << ceph_mds_state_name(m->get_state())
+	      << " seq " << m->get_seq() << " rtt " << rtt << dendl;
 
       if (was_laggy && rtt < g_conf()->mds_beacon_grace) {
 	dout(0) << "handle_mds_beacon no longer laggy" << dendl;
@@ -123,7 +123,7 @@ void Beacon::handle_mds_beacon(MMDSBeacon *m)
     } else {
       // Mark myself laggy if system clock goes backwards. Hopping
       // later beacons will clear it.
-      dout(1) << "handle_mds_beacon system clock goes backwards, "
+      dout(0) << "handle_mds_beacon system clock goes backwards, "
 	      << "mark myself laggy" << dendl;
       last_acked_stamp = now - utime_t(g_conf()->mds_beacon_grace + 1, 0);
       was_laggy = true;
@@ -139,8 +139,8 @@ void Beacon::handle_mds_beacon(MMDSBeacon *m)
       waiting_cond.Signal();
     }
   } else {
-    dout(10) << "handle_mds_beacon " << ceph_mds_state_name(m->get_state())
-	     << " seq " << m->get_seq() << " dne" << dendl;
+    dout(1) << "handle_mds_beacon " << ceph_mds_state_name(m->get_state())
+	    << " seq " << m->get_seq() << " dne" << dendl;
   }
   m->put();
 }
@@ -191,14 +191,12 @@ void Beacon::_send()
   if (!cct->get_heartbeat_map()->is_healthy()) {
     /* If anything isn't progressing, let avoid sending a beacon so that
      * the MDS will consider us laggy */
-    dout(1) << __func__ << " skipping beacon, heartbeat map not healthy" << dendl;
+    dout(0) << __func__ << " skipping beacon, heartbeat map not healthy" << dendl;
     return;
   }
 
   ++last_seq;
-  dout(10) << __func__ << " " << ceph_mds_state_name(want_state)
-	   << " seq " << last_seq
-	   << dendl;
+  dout(5) << __func__ << " " << ceph_mds_state_name(want_state) << " seq " << last_seq << dendl;
 
   seq_stamp[last_seq] = ceph_clock_now();
 
@@ -262,13 +260,13 @@ bool Beacon::is_laggy()
   utime_t now = ceph_clock_now();
   utime_t since = now - last_acked_stamp;
   if (since > g_conf()->mds_beacon_grace) {
-    dout(5) << "is_laggy " << since << " > " << g_conf()->mds_beacon_grace
+    dout(1) << "is_laggy " << since << " > " << g_conf()->mds_beacon_grace
 	    << " since last acked beacon" << dendl;
     was_laggy = true;
     if (since > (g_conf()->mds_beacon_grace*2) &&
 	now > last_mon_reconnect + g_conf()->mds_beacon_interval) {
       // maybe it's not us?
-      dout(5) << "initiating monitor reconnect; maybe we're not the slow one"
+      dout(1) << "initiating monitor reconnect; maybe we're not the slow one"
               << dendl;
       last_mon_reconnect = now;
       monc->reopen_session();
@@ -297,7 +295,7 @@ void Beacon::set_want_state(MDSMap const *mdsmap, MDSMap::DaemonState const news
   _notify_mdsmap(mdsmap);
 
   if (want_state != newstate) {
-    dout(10) << __func__ << ": "
+    dout(5) << __func__ << ": "
       << ceph_mds_state_name(want_state) << " -> "
       << ceph_mds_state_name(newstate) << dendl;
     want_state = newstate;
diff --git a/src/mds/MDSRank.cc b/src/mds/MDSRank.cc
index 1accfeb8508..698af9df807 100644
--- a/src/mds/MDSRank.cc
+++ b/src/mds/MDSRank.cc
@@ -295,7 +295,7 @@ void MDSRankDispatcher::tick()
   heartbeat_reset();
 
   if (beacon.is_laggy()) {
-    dout(5) << "tick bailing out since we seem laggy" << dendl;
+    dout(1) << "skipping upkeep work because connection to Monitors appears laggy" << dendl;
     return;
   }
 
@@ -596,10 +596,10 @@ bool MDSRank::_dispatch(Message *m, bool new_msg)
   }
 
   if (beacon.is_laggy()) {
-    dout(10) << " laggy, deferring " << *m << dendl;
+    dout(5) << " laggy, deferring " << *m << dendl;
     waiting_for_nolaggy.push_back(m);
   } else if (new_msg && !waiting_for_nolaggy.empty()) {
-    dout(10) << " there are deferred messages, deferring " << *m << dendl;
+    dout(5) << " there are deferred messages, deferring " << *m << dendl;
     waiting_for_nolaggy.push_back(m);
   } else {
     if (!handle_deferrable_message(m)) {
-- 
2.39.5