From: Patrick Donnelly <pdonnell@redhat.com>
Date: Fri, 25 Jan 2019 23:59:13 +0000 (-0800)
Subject: mds: add extra details for cache drop output
X-Git-Tag: v13.2.7~24^2~3
X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=e33cfe925d8f8ff3b3e8355ae432fb80d9beb2a8;p=ceph.git

mds: add extra details for cache drop output

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

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

diff --git a/src/mds/MDSRank.cc b/src/mds/MDSRank.cc
index c89b486ecba..182cbcef2cf 100644
--- a/src/mds/MDSRank.cc
+++ b/src/mds/MDSRank.cc
@@ -319,7 +319,7 @@ private:
   void recall_client_state() {
     dout(20) << __func__ << dendl;
     auto now = mono_clock::now();
-    auto duration = std::chrono::duration<double>(recall_start-now).count();
+    auto duration = std::chrono::duration<double>(now-recall_start).count();
 
     MDSGatherBuilder *gather = new MDSGatherBuilder(g_ceph_context);
     auto [throttled, count] = server->recall_client_state(gather, Server::RecallFlags::STEADY);
@@ -327,6 +327,7 @@ private:
              << (throttled ? " (throttled)" : "")
              << " recalled " << count << " caps" << dendl;
 
+    caps_recalled += count;
     if ((throttled || count > 0) && (recall_timeout == 0 || duration < recall_timeout)) {
       auto timer = new FunctionContext([this](int _) {
         recall_client_state();
@@ -360,6 +361,7 @@ private:
     f->open_object_section("client_recall");
     f->dump_int("return_code", r);
     f->dump_string("message", cpp_strerror(r));
+    f->dump_int("recalled", caps_recalled);
     f->close_section();
 
     // we can still continue after recall timeout
@@ -402,6 +404,7 @@ private:
     dout(10) << __func__
              << (throttled ? " (throttled)" : "")
              << " trimmed " << count << " caps" << dendl;
+    dentries_trimmed += count;
     if (throttled && count > 0) {
       auto timer = new FunctionContext([this](int _) {
         trim_cache();
@@ -415,9 +418,12 @@ private:
   void cache_status() {
     dout(20) << __func__ << dendl;
 
+    f->open_object_section("trim_cache");
+    f->dump_int("trimmed", dentries_trimmed);
+    f->close_section();
+
     // cache status section
     mdcache->cache_status(f);
-    f->close_section();
 
     complete(0);
   }
@@ -425,6 +431,10 @@ private:
   void finish(int r) override {
     dout(20) << __func__ << ": r=" << r << dendl;
 
+    auto d = std::chrono::duration<double>(mono_clock::now()-recall_start);
+    f->dump_float("duration", d.count());
+
+    f->close_section();
     on_finish->complete(r);
   }
 
@@ -438,6 +448,8 @@ private:
 
   int retval = 0;
   std::stringstream ss;
+  uint64_t caps_recalled = 0;
+  uint64_t dentries_trimmed = 0;
 
   // so as to use dout
   mds_rank_t whoami;
diff --git a/src/mds/Server.cc b/src/mds/Server.cc
index 9abed22544f..fbfdb6a5bc1 100644
--- a/src/mds/Server.cc
+++ b/src/mds/Server.cc
@@ -1454,9 +1454,8 @@ std::pair<bool, uint64_t> Server::recall_client_state(MDSGatherBuilder* gather,
       if (gather) {
         flush_session(session, gather);
       }
-      session->notify_recall_sent(newlim);
+      caps_recalled += session->notify_recall_sent(newlim);
       recall_counter.hit(ceph_clock_now(), recall);
-      caps_recalled += recall;
     }
   }
 
diff --git a/src/mds/SessionMap.cc b/src/mds/SessionMap.cc
index 3d284c45fb6..598ad653f14 100644
--- a/src/mds/SessionMap.cc
+++ b/src/mds/SessionMap.cc
@@ -911,9 +911,10 @@ void Session::notify_cap_release(size_t n_caps)
  * in order to generate health metrics if the session doesn't see
  * a commensurate number of calls to ::notify_cap_release
  */
-void Session::notify_recall_sent(const size_t new_limit)
+uint64_t Session::notify_recall_sent(const size_t new_limit)
 {
   const auto num_caps = caps.size();
+  ceph_assert(new_limit < num_caps);
   const auto count = num_caps-new_limit;
 
   /* Entering recall phase, set up counters so we can later judge whether the
@@ -921,6 +922,7 @@ void Session::notify_recall_sent(const size_t new_limit)
    * released caps from a previous recall.
    */
 
+  uint64_t new_change;
   if (recall_limit != new_limit) {
     const auto now = clock::now();
     recalled_at = now;
@@ -928,6 +930,9 @@ void Session::notify_recall_sent(const size_t new_limit)
     recall_count = count;
     recall_release_count = 0;
     recall_limit = new_limit;
+    new_change = count;
+  } else {
+    new_change = 0; /* no change! */
   }
 
   /* Always hit the session counter as a RECALL message is still sent to the
@@ -936,6 +941,7 @@ void Session::notify_recall_sent(const size_t new_limit)
    * throttle future RECALL messages).
    */
   cap_recalled.hit(count);
+  return new_change;
 }
 
 void Session::clear_recalled()
diff --git a/src/mds/SessionMap.h b/src/mds/SessionMap.h
index 16cc485c94b..c72b98fc025 100644
--- a/src/mds/SessionMap.h
+++ b/src/mds/SessionMap.h
@@ -171,7 +171,7 @@ public:
   interval_set<inodeno_t> pending_prealloc_inos; // journaling prealloc, will be added to prealloc_inos
 
   void notify_cap_release(size_t n_caps);
-  void notify_recall_sent(const size_t new_limit);
+  uint64_t notify_recall_sent(const size_t new_limit);
   auto cap_recalled_counter() const {
     return cap_recalled.get(ceph_clock_now());
   }