From 42a64f8f3fb999a94b9af9f74c300f19ef62569a Mon Sep 17 00:00:00 2001
From: Patrick Donnelly <pdonnell@redhat.com>
Date: Fri, 25 Jan 2019 15:59:13 -0800
Subject: [PATCH] mds: add extra details for cache drop output

Signed-off-by: Patrick Donnelly <pdonnell@redhat.com>
(cherry picked from commit 3bc093fd9e9daf99f09abe68ce0c0077ef0f58da)
---
 src/mds/MDSRank.cc    | 16 ++++++++++++++--
 src/mds/Server.cc     |  3 +--
 src/mds/SessionMap.cc |  8 +++++++-
 src/mds/SessionMap.h  |  2 +-
 4 files changed, 23 insertions(+), 6 deletions(-)

diff --git a/src/mds/MDSRank.cc b/src/mds/MDSRank.cc
index 24416aa20d2b3..89b6e97b06580 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 result = server->recall_client_state(gather, Server::RecallFlags::STEADY);
@@ -329,6 +329,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();
@@ -362,6 +363,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
@@ -406,6 +408,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();
@@ -419,9 +422,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);
   }
@@ -429,6 +435,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);
   }
 
@@ -442,6 +452,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 dea4a35a5bb61..6e4b874dcf925 100644
--- a/src/mds/Server.cc
+++ b/src/mds/Server.cc
@@ -1319,9 +1319,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 8b58295e45ea0..a5439165f10e5 100644
--- a/src/mds/SessionMap.cc
+++ b/src/mds/SessionMap.cc
@@ -874,9 +874,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
@@ -884,6 +885,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;
@@ -891,6 +893,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
@@ -899,6 +904,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 24cf2113f9276..a9fc880e64e02 100644
--- a/src/mds/SessionMap.h
+++ b/src/mds/SessionMap.h
@@ -176,7 +176,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());
   }
-- 
2.39.5