Merge PR ceph#52652 into main

* refs/pull/52652/head:
	PendingReleaseNotes: add note about new mdlog trimming configurations
	mds: drive mdlog trimming via a separate thread
	mds: allow runtime modification of mdlog trimming configuration
	mds: remove a bunch of heuristics from MDLog::trim()
	mds: add mdlog trimming threshold and decay counter

Reviewed-by: Leonid Usov <[email protected]>

Author: vshankar

PendingReleaseNotes

@@ -117,6 +117,10 @@ CephFS: Disallow delegating preallocated inode ranges to clients. Config
   manager module. Users may choose between two new modes: ``upmap-read``, which
   offers upmap and read optimization simultaneously, or ``read``, which may be used
   to only optimize reads. For more detailed information see https://docs.ceph.com/en/latest/rados/operations/read-balancer/#online-optimization.
+* CephFS: MDS log trimming is now driven by a separate thread which tries to
+  trim the log every second (`mds_log_trim_upkeep_interval` config). Also,
+  a couple of configs govern how much time the MDS spends in trimming its
+  logs. These configs are `mds_log_trim_threshold` and `mds_log_trim_decay_rate`.
 
 >=18.0.0
 

src/common/options/mds.yaml.in

@@ -1597,3 +1597,41 @@ options:
   - mds
   flags:
   - runtime
+- name: mds_log_trim_threshold
+  type: size
+  level: advanced
+  desc: MDS log trim threshold
+  long_desc: The threshold of the number of log segment that can be trimmed.
+  default: 128
+  min: 1
+  services:
+  - mds
+  see_also:
+  - mds_log_max_events
+  - mds_log_max_segments
+  flags:
+  - runtime
+- name: mds_log_trim_decay_rate
+  type: float
+  level: advanced
+  desc: MDS log trim decay rate
+  long_desc: The decay rate for trimming the MDS log. Increasing this value leads to the MDS spending less time in trimming the log.
+  default: 1.0
+  min: 0.01
+  services:
+  - mds
+  see_also:
+  - mds_log_max_events
+  - mds_log_max_segments
+  flags:
+  - runtime
+- name: mds_log_trim_upkeep_interval
+  type: millisecs
+  level: advanced
+  desc: MDS log trimming interval
+  long_desc: Interval in milliseconds to trim MDS logs.
+  default: 1000
+  services:
+  - mds
+  flags:
+  - runtime

src/mds/MDLog.cc

@@ -24,6 +24,7 @@
 #include "common/entity_name.h"
 #include "common/perf_counters.h"
 #include "common/Cond.h"
+#include "common/ceph_time.h"
 
 #include "events/ESubtreeMap.h"
 #include "events/ESegment.h"
@@ -45,7 +46,8 @@ MDLog::MDLog(MDSRank* m)
     mds(m),
     replay_thread(this),
     recovery_thread(this),
-    submit_thread(this)
+    submit_thread(this),
+    log_trim_counter(DecayCounter(g_conf().get_val<double>("mds_log_trim_decay_rate")))
 {
   debug_subtrees = g_conf().get_val<bool>("mds_debug_subtrees");
   event_large_threshold = g_conf().get_val<uint64_t>("mds_log_event_large_threshold");
@@ -56,6 +58,7 @@ MDLog::MDLog(MDSRank* m)
   max_events = g_conf().get_val<int64_t>("mds_log_max_events");
   skip_corrupt_events = g_conf().get_val<bool>("mds_log_skip_corrupt_events");
   skip_unbounded_events = g_conf().get_val<bool>("mds_log_skip_unbounded_events");
+  upkeep_thread = std::thread(&MDLog::log_trim_upkeep, this);
 }
 
 MDLog::~MDLog()
@@ -68,7 +71,6 @@ MDLog::~MDLog()
   }
 }
 
-
 void MDLog::create_logger()
 {
   PerfCountersBuilder plb(g_ceph_context, "mds_log", l_mdl_first, l_mdl_last);
@@ -555,6 +557,13 @@ void MDLog::shutdown()
     }
   }
 
+  upkeep_log_trim_shutdown = true;
+  cond.notify_one();
+
+  mds->mds_lock.unlock();
+  upkeep_thread.join();
+  mds->mds_lock.lock();
+
   // Replay thread can be stuck inside e.g. Journaler::wait_for_readable,
   // so we need to shutdown the journaler first.
   if (journaler) {
@@ -605,11 +614,23 @@ void MDLog::try_to_commit_open_file_table(uint64_t last_seq)
   }
 }
 
-void MDLog::trim(int m)
+void MDLog::log_trim_upkeep(void) {
+  dout(10) << dendl;
+
+  std::unique_lock mds_lock(mds->mds_lock);
+  while (!upkeep_log_trim_shutdown.load()) {
+    if (mds->is_active() || mds->is_stopping()) {
+      trim();
+    }
+
+    cond.wait_for(mds_lock, g_conf().get_val<std::chrono::milliseconds>("mds_log_trim_upkeep_interval"));
+  }
+  dout(10) << __func__ << ": finished" << dendl;
+}
+
+void MDLog::trim()
 {
   int max_ev = max_events;
-  if (m >= 0)
-    max_ev = m;
 
   if (mds->mdcache->is_readonly()) {
     dout(10) << "trim, ignoring read-only FS" <<  dendl;
@@ -636,10 +657,6 @@ void MDLog::trim(int m)
     return;
   }
 
-  // hack: only trim for a few seconds at a time
-  utime_t stop = ceph_clock_now();
-  stop += 2.0;
-
   int op_prio = CEPH_MSG_PRIO_LOW +
 		(CEPH_MSG_PRIO_HIGH - CEPH_MSG_PRIO_LOW) *
 		expiring_segments.size() / max_segments;
@@ -648,32 +665,43 @@ void MDLog::trim(int m)
 
   unsigned new_expiring_segments = 0;
 
-  unsigned max_expiring_segments = 0;
-  if (pre_segments_size > 0){
-    max_expiring_segments = max_segments/2;
+  if (pre_segments_size > 0) {
     ceph_assert(segments.size() >= pre_segments_size);
-    max_expiring_segments = std::max<unsigned>(max_expiring_segments,segments.size() - pre_segments_size);
   }
-  
+
   map<uint64_t,LogSegment*>::iterator p = segments.begin();
+
+  auto trim_start = ceph::coarse_mono_clock::now();
+  std::optional<ceph::coarse_mono_time> trim_end;
+
+  auto log_trim_counter_start = log_trim_counter.get();
+  auto log_trim_threshold = g_conf().get_val<Option::size_t>("mds_log_trim_threshold");
+
   while (p != segments.end()) {
-    if (stop < ceph_clock_now())
+    // throttle - break out of trimmming if we've hit the threshold
+    if (log_trim_counter_start + new_expiring_segments >= log_trim_threshold) {
+      auto time_spent = std::chrono::duration<double>::zero();
+      if (trim_end) {
+	time_spent = std::chrono::duration<double>(*trim_end - trim_start);
+      }
+      dout(10) << __func__ << ": breaking out of trim loop - trimmed "
+	       << new_expiring_segments << " segment(s) in " << time_spent.count()
+	       << "s" << dendl;
       break;
+    }
 
     unsigned num_remaining_segments = (segments.size() - expired_segments.size() - expiring_segments.size());
-    if ((num_remaining_segments <= max_segments) &&
-	(max_ev < 0 || (num_events - expiring_events - expired_events) <= (uint64_t)max_ev))
-      break;
+    dout(10) << __func__ << ": new_expiring_segments=" << new_expiring_segments
+	     << ", num_remaining_segments=" << num_remaining_segments
+	     << ", max_segments=" << max_segments << dendl;
 
-    // Do not trim too many segments at once for peak workload. If mds keeps creating N segments each tick,
-    // the upper bound of 'num_remaining_segments - max_segments' is '2 * N'
-    if (new_expiring_segments * 2 > num_remaining_segments)
+    if ((num_remaining_segments <= max_segments) &&
+	(max_ev < 0 || (num_events - expiring_events - expired_events) <= (uint64_t)max_ev)) {
+      dout(10) << __func__ << ": breaking out of trim loop - segments/events fell below ceiling"
+	       << " max_segments/max_ev" << dendl;
       break;
+    }
 
-    if (max_expiring_segments > 0 &&
-	expiring_segments.size() >= max_expiring_segments)
-      break;
-    
     // look at first segment
     LogSegment *ls = p->second;
     ceph_assert(ls);
@@ -699,6 +727,8 @@ void MDLog::trim(int m)
 
       uint64_t last_seq = ls->seq;
       try_expire(ls, op_prio);
+      log_trim_counter.hit();
+      trim_end = ceph::coarse_mono_clock::now();
 
       submit_mutex.lock();
       p = segments.lower_bound(last_seq + 1);
@@ -784,6 +814,7 @@ int MDLog::trim_all()
 
 void MDLog::try_expire(LogSegment *ls, int op_prio)
 {
+  ceph_assert(ceph_mutex_is_locked(mds->mds_lock));
   MDSGatherBuilder gather_bld(g_ceph_context);
   ls->try_to_expire(mds, gather_bld, op_prio);
 
@@ -1581,4 +1612,7 @@ void MDLog::handle_conf_change(const std::set<std::string>& changed, const MDSMa
   if (changed.count("mds_log_skip_unbounded_events")) {
     skip_unbounded_events = g_conf().get_val<bool>("mds_log_skip_unbounded_events");
   }
+  if (changed.count("mds_log_trim_decay_rate")){
+    log_trim_counter = DecayCounter(g_conf().get_val<double>("mds_log_trim_decay_rate"));
+  }
 }

src/mds/MDLog.h

@@ -46,6 +46,7 @@ enum {
 
 #include "MDSContext.h"
 #include "common/Cond.h"
+#include "common/DecayCounter.h"
 #include "common/Finisher.h"
 #include "common/Thread.h"
 
@@ -65,6 +66,7 @@ class ESubtreeMap;
 
 class MDLog {
 public:
+
   MDLog(MDSRank *m);
   ~MDLog();
 
@@ -145,7 +147,6 @@ class MDLog {
   }
 
   void trim_expired_segments();
-  void trim(int max=-1);
   int trim_all();
 
   void create(MDSContext *onfinish);  // fresh, empty log! 
@@ -287,6 +288,9 @@ class MDLog {
   void _trim_expired_segments();
   void write_head(MDSContext *onfinish);
 
+  void trim();
+  void log_trim_upkeep(void);
+
   bool debug_subtrees;
   std::atomic_uint64_t event_large_threshold; // accessed by submit thread
   uint64_t events_per_segment;
@@ -301,5 +305,14 @@ class MDLog {
   std::set<LogSegment*> expired_segments;
   std::set<LogSegment*> expiring_segments;
   uint64_t events_since_last_major_segment = 0;
+
+  // log trimming decay counter
+  DecayCounter log_trim_counter;
+
+  // log trimming upkeeper thread
+  std::thread upkeep_thread;
+  // guarded by mds_lock
+  std::condition_variable_any cond;
+  std::atomic<bool> upkeep_log_trim_shutdown{false};
 };
 #endif

src/mds/MDSRank.cc

@@ -743,10 +743,6 @@ void MDSRankDispatcher::tick()
   // update average session uptime
   sessionmap.update_average_session_age();
 
-  if (is_active() || is_stopping()) {
-    mdlog->trim();  // NOT during recovery!
-  }
-
   // ...
   if (is_clientreplay() || is_active() || is_stopping()) {
     server->clear_laggy_clients();
@@ -789,7 +785,6 @@ void MDSRankDispatcher::tick()
 
   // shut down?
   if (is_stopping()) {
-    mdlog->trim();
     if (mdcache->shutdown_pass()) {
       uint64_t pq_progress = 0 ;
       uint64_t pq_total = 0;
@@ -3880,6 +3875,8 @@ const char** MDSRankDispatcher::get_tracked_conf_keys() const
     "mds_session_max_caps_throttle_ratio",
     "mds_symlink_recovery",
     "mds_session_metadata_threshold",
+    "mds_log_trim_threshold",
+    "mds_log_trim_decay_rate",
     NULL
   };
   return KEYS;