From: Patrick Donnelly <pdonnell@redhat.com>
Date: Sat, 11 Aug 2018 18:21:43 +0000 (-0700)
Subject: mds: report lagginess at lower debug
X-Git-Tag: v12.2.9~54^2
X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=24a67c00becbfdd8f7599a7522627a4f3428980a;p=ceph.git

mds: report lagginess at lower debug

To help diagnose laggy daemons with performance tuned debug settings.

Signed-off-by: Patrick Donnelly <pdonnell@redhat.com>
(cherry picked from commit c8aff620c273fd4579b23e1647450b6f00c6bac7)

Conflicts:
	src/mds/Beacon.cc
---

diff --git a/src/mds/Beacon.cc b/src/mds/Beacon.cc
index 60b0cbe3a698..f7ad85a457d3 100644
--- a/src/mds/Beacon.cc
+++ b/src/mds/Beacon.cc
@@ -124,8 +124,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;
@@ -135,7 +135,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;
@@ -151,8 +151,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();
 }
@@ -203,14 +203,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();
 
@@ -274,13 +272,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();
@@ -309,7 +307,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 51fedf726495..885895aa63f3 100644
--- a/src/mds/MDSRank.cc
+++ b/src/mds/MDSRank.cc
@@ -246,7 +246,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;
   }
 
@@ -539,10 +539,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)) {