Merge pull request #38939 from ronen-fr/wip-ronenf-scrub-blocked

osd: issue a warning if the scrubber blocks for too long on an object

Reviewed-by: David Zafman <dzafman@redhat.com>

src/osd/OSD.cc

@@ -2521,6 +2521,70 @@ std::set<int64_t> OSD::get_mapped_pools()
   return pools;
 }
 
+OSD::PGRefOrError OSD::locate_asok_target(const cmdmap_t& cmdmap,
+				     stringstream& ss,
+				     bool only_primary)
+{
+  string pgidstr;
+  if (!cmd_getval(cmdmap, "pgid", pgidstr)) {
+    ss << "no pgid specified";
+    return OSD::PGRefOrError{std::nullopt, -EINVAL};
+  }
+
+  pg_t pgid;
+  if (!pgid.parse(pgidstr.c_str())) {
+    ss << "couldn't parse pgid '" << pgidstr << "'";
+    return OSD::PGRefOrError{std::nullopt, -EINVAL};
+  }
+
+  spg_t pcand;
+  PGRef pg;
+  if (get_osdmap()->get_primary_shard(pgid, &pcand) && (pg = _lookup_lock_pg(pcand))) {
+    if (pg->is_primary() || !only_primary) {
+      return OSD::PGRefOrError{pg, 0};
+    }
+
+    ss << "not primary for pgid " << pgid;
+    pg->unlock();
+    return OSD::PGRefOrError{std::nullopt, -EAGAIN};
+  } else {
+    ss << "i don't have pgid " << pgid;
+    return OSD::PGRefOrError{std::nullopt, -ENOENT};
+  }
+}
+
+// note that the cmdmap is explicitly copied into asok_route_to_pg()
+int OSD::asok_route_to_pg(
+  bool only_primary,
+  std::string_view prefix,
+  cmdmap_t cmdmap,
+  Formatter* f,
+  stringstream& ss,
+  const bufferlist& inbl,
+  bufferlist& outbl,
+  std::function<void(int, const std::string&, bufferlist&)> on_finish)
+{
+  auto [target_pg, ret] = locate_asok_target(cmdmap, ss, only_primary);
+
+  if (!target_pg.has_value()) {
+    // 'ss' and 'ret' already contain the error information
+    on_finish(ret, ss.str(), outbl);
+    return ret;
+  }
+
+  //  the PG was locked by locate_asok_target()
+  try {
+    (*target_pg)->do_command(prefix, cmdmap, inbl, on_finish);
+    (*target_pg)->unlock();
+    return 0;  // the pg handler calls on_finish directly
+  } catch (const TOPNSPC::common::bad_cmd_get& e) {
+    (*target_pg)->unlock();
+    ss << e.what();
+    on_finish(ret, ss.str(), outbl);
+    return -EINVAL;
+  }
+}
+
 void OSD::asok_command(
   std::string_view prefix, const cmdmap_t& cmdmap,
   Formatter *f,
@@ -2581,6 +2645,13 @@ void OSD::asok_command(
     }
   }
 
+  // --- PG commands that will be answered even if !primary ---
+
+  else if (prefix == "scrubdebug") {
+    asok_route_to_pg(false, prefix, cmdmap, f, ss, inbl, outbl, on_finish);
+    return;
+  }
+
   // --- OSD commands follow ---
 
   else if (prefix == "status") {
@@ -4140,6 +4211,14 @@ void OSD::final_init()
     asok_hook,
     "Scrub purged_snaps vs snapmapper index");
   ceph_assert(r == 0);
+  r = admin_socket->register_command(
+    "scrubdebug "						\
+    "name=pgid,type=CephPgid "	                                \
+    "name=cmd,type=CephChoices,strings=block|unblock "          \
+    "name=value,type=CephString,req=false",
+    asok_hook,
+    "debug the scrubber");
+  ceph_assert(r == 0);
 
   // -- pg commands --
   // old form: ceph pg <pgid> command ...

src/osd/OSD.h

@@ -1177,6 +1177,16 @@ protected:
   // asok
   friend class OSDSocketHook;
   class OSDSocketHook *asok_hook;
+  using PGRefOrError = std::tuple<std::optional<PGRef>, int>;
+  PGRefOrError locate_asok_target(const cmdmap_t& cmdmap, stringstream& ss, bool only_primary);
+  int asok_route_to_pg(bool only_primary,
+    std::string_view prefix,
+    cmdmap_t cmdmap,
+    Formatter *f,
+    stringstream& ss,
+    const bufferlist& inbl,
+    bufferlist& outbl,
+    std::function<void(int, const std::string&, bufferlist&)> on_finish);
   void asok_command(
     std::string_view prefix,
     const cmdmap_t& cmdmap,

src/osd/PrimaryLogPG.cc

@@ -1184,6 +1184,21 @@ void PrimaryLogPG::do_command(
     outbl.append(ss.str());
   }
 
+  else if (prefix == "block" || prefix == "unblock") {
+    string value;
+    cmd_getval(cmdmap, "value", value);
+
+    if (is_primary()) {
+      ret = m_scrubber->asok_debug(prefix, value, f.get(), ss);
+      f->open_object_section("result");
+      f->dump_bool("success", true);
+      f->close_section();
+    } else {
+      ss << "Not primary";
+      ret = -EPERM;
+    }
+    outbl.append(ss.str());
+  }
   else {
     ret = -ENOSYS;
     ss << "prefix '" << prefix << "' not implemented";

src/osd/pg_scrubber.cc

@@ -642,6 +642,12 @@ bool PgScrubber::select_range()
 
   dout(15) << __func__ << " range selected: " << m_start << " //// " << m_end << " //// "
 	   << m_max_end << dendl;
+
+  // debug: be 'blocked' if told so by the 'pg scrub_debug block' asok command
+  if (m_debug_blockrange > 0) {
+    m_debug_blockrange--;
+    return false;
+  }
   return true;
 }
 
@@ -695,6 +701,11 @@ bool PgScrubber::range_intersects_scrub(const hobject_t& start, const hobject_t&
   return (start < m_max_end && end >= m_start);
 }
 
+Scrub::BlockedRangeWarning PgScrubber::acquire_blocked_alarm()
+{
+  return std::make_unique<blocked_range_t>(m_osds, ceph::timespan{300s}, m_pg_id);
+}
+
 /**
  *  if we are required to sleep:
  *	arrange a callback sometimes later.
@@ -2008,6 +2019,23 @@ ostream& PgScrubber::show(ostream& out) const
   return out << " [ " << m_pg_id << ": " << m_flags << " ] ";
 }
 
+int PgScrubber::asok_debug(std::string_view cmd,
+			   std::string param,
+			   Formatter* f,
+			   stringstream& ss)
+{
+  dout(10) << __func__ << " cmd: " << cmd << " param: " << param << dendl;
+
+  if (cmd == "block") {
+    // set a flag that will cause the next 'select_range' to report a blocked object
+    m_debug_blockrange = 1;
+  } else if (cmd == "unblock") {
+    // send an 'unblock' event, as if a blocked range was freed
+    m_debug_blockrange = 0;
+    m_fsm->process_event(Unblocked{});
+  }
+  return 0;
+}
 // ///////////////////// preemption_data_t //////////////////////////////////
 
 PgScrubber::preemption_data_t::preemption_data_t(PG* pg) : m_pg{pg}
@@ -2270,4 +2298,31 @@ ostream& operator<<(ostream& out, const MapsCollectionStatus& sf)
   return out << " ] ";
 }
 
+// ///////////////////// blocked_range_t ///////////////////////////////
+
+blocked_range_t::blocked_range_t(OSDService* osds, ceph::timespan waittime, spg_t pg_id)
+    : m_osds{osds}
+{
+  auto now_is = std::chrono::system_clock::now();
+  m_callbk = new LambdaContext([now_is, pg_id, osds]([[maybe_unused]] int r) {
+    std::time_t now_c = std::chrono::system_clock::to_time_t(now_is);
+    char buf[50];
+    strftime(buf, sizeof(buf), "%Y-%m-%dT%H:%M:%S", std::localtime(&now_c));
+    lgeneric_subdout(g_ceph_context, osd, 10)
+      << "PgScrubber: " << pg_id << " blocked on an object for too long (since " << buf
+      << ")" << dendl;
+    osds->clog->warn() << "osd." << osds->whoami << " PgScrubber: " << pg_id << " blocked on an object for too long (since " << buf << ")";
+    return;
+  });
+
+  std::lock_guard l(m_osds->sleep_lock);
+  m_osds->sleep_timer.add_event_after(waittime, m_callbk);
+}
+
+blocked_range_t::~blocked_range_t()
+{
+  std::lock_guard l(m_osds->sleep_lock);
+  m_osds->sleep_timer.cancel_event(m_callbk);
+}
+
 }  // namespace Scrub

src/osd/pg_scrubber.h

@@ -139,6 +139,7 @@ class MapsCollectionStatus {
   friend ostream& operator<<(ostream& out, const MapsCollectionStatus& sf);
 };
 
+
 }  // namespace Scrub
 
 
@@ -335,11 +336,19 @@ class PgScrubber : public ScrubPgIF, public ScrubMachineListener {
     return false;
   }
 
+  int asok_debug(std::string_view cmd,
+		 std::string param,
+		 Formatter* f,
+		 stringstream& ss) override;
+  int m_debug_blockrange{0};
+
   // -------------------------------------------------------------------------------------------
   // the I/F used by the state-machine (i.e. the implementation of ScrubMachineListener)
 
   void select_range_n_notify() final;
 
+  Scrub::BlockedRangeWarning acquire_blocked_alarm() final;
+
   /// walk the log to find the latest update that affects our chunk
   eversion_t search_log_for_updates() const final;
 

src/osd/scrub_machine.cc

@@ -149,10 +149,21 @@ sc::result ActiveScrubbing::react(const FullReset&)
 /*
  * Blocked. Will be released by kick_object_context_blocked() (or upon
  * an abort)
+ *
+ * Note: we are never expected to be waiting for long for a blocked object.
+ * Unfortunately we know from experience that a bug elsewhere might result
+ * in an indefinite wait in this state, for an object that is never released.
+ * If that happens, all we can do is to issue a warning message to help
+ * with the debugging.
  */
 RangeBlocked::RangeBlocked(my_context ctx) : my_base(ctx)
 {
   dout(10) << "-- state -->> Act/RangeBlocked" << dendl;
+  DECLARE_LOCALS;  // 'scrbr' & 'pg_id' aliases
+
+  // arrange to have a warning message issued if we are stuck in this
+  // state for longer than some reasonable number of minutes.
+  m_timeout = scrbr->acquire_blocked_alarm();
 }
 
 // ----------------------- PendingTimer -----------------------------------

src/osd/scrub_machine.h

@@ -206,6 +206,8 @@ struct ActiveScrubbing : sc::state<ActiveScrubbing, ScrubMachine, PendingTimer>
 struct RangeBlocked : sc::state<RangeBlocked, ActiveScrubbing> {
   explicit RangeBlocked(my_context ctx);
   using reactions = mpl::list<sc::transition<Unblocked, PendingTimer>>;
+
+  Scrub::BlockedRangeWarning m_timeout;
 };
 
 struct PendingTimer : sc::state<PendingTimer, ActiveScrubbing> {

src/osd/scrub_machine_lstnr.h

@@ -40,6 +40,18 @@ struct preemption_t {
   virtual bool disable_and_test() = 0;
 };
 
+/// an aux used when blocking on a busy object.
+/// Issues a log warning if still blocked after 'waittime'.
+struct blocked_range_t {
+  blocked_range_t(OSDService* osds, ceph::timespan waittime, spg_t pg_id);
+  ~blocked_range_t();
+
+  OSDService* m_osds;
+  Context* m_callbk;
+};
+
+using BlockedRangeWarning = std::unique_ptr<blocked_range_t>;
+
 }  // namespace Scrub
 
 struct ScrubMachineListener {
@@ -53,6 +65,8 @@ struct ScrubMachineListener {
 
   virtual void select_range_n_notify() = 0;
 
+  virtual Scrub::BlockedRangeWarning acquire_blocked_alarm() = 0;
+
   /// walk the log to find the latest update that affects our chunk
   virtual eversion_t search_log_for_updates() const = 0;
 

src/osd/scrubber_common.h

@@ -277,4 +277,11 @@ struct ScrubPgIF {
   virtual void scrub_requested(scrub_level_t scrub_level,
 			       scrub_type_t scrub_type,
 			       requested_scrub_t& req_flags) = 0;
+
+  // --------------- debugging via the asok ------------------------------
+
+  virtual int asok_debug(std::string_view cmd,
+			 std::string param,
+			 Formatter* f,
+			 stringstream& ss) = 0;
 };