common/TrackedOp: cache op description

Only calculate it once.  Invalidate from OSD after a full decode (when it
changes).

Signed-off-by: Sage Weil <sage@redhat.com>

diff --git a/src/common/TrackedOp.cc b/src/common/TrackedOp.cc
index 08a56a0af8a25b4a2c83db7d79685b98b9cb5f4b..bd04ca754476a3e91b9f8c0c1e82ea27a4c6622b 100644 (file)
--- a/src/common/TrackedOp.cc
+++ b/src/common/TrackedOp.cc
@@ -273,9 +273,8 @@ bool OpTracker::check_ops_in_flight(std::vector<string> &warning_vector, int *sl
         utime_t age = now - i->get_initiated();
         stringstream ss;
         ss << "slow request " << age << " seconds old, received at "
-           << i->get_initiated() << ": ";
-        i->_dump_op_descriptor_unlocked(ss);
-        ss << " currently "
+           << i->get_initiated() << ": " << i->get_desc()
+          << " currently "
           << (i->current.size() ? i->current : i->state_string());
         warning_vector.push_back(ss.str());
 
@@ -316,19 +315,9 @@ void OpTracker::get_age_ms_histogram(pow2_hist_t *h)
   }
 }
 
-void OpTracker::mark_event(TrackedOp *op, const char *evt,
-                          utime_t time)
-{
-  if (!op->state)
-    return;
 
-  dout(5);
-  *_dout <<  "seq: " << op->seq
-        << ", time: " << time << ", event: " << evt
-        << ", op: ";
-  op->_dump_op_descriptor_unlocked(*_dout);
-  *_dout << dendl;
-}
+#undef dout_context
+#define dout_context tracker->cct
 
 void TrackedOp::mark_event_string(const string &event, utime_t stamp)
 {
@@ -339,7 +328,11 @@ void TrackedOp::mark_event_string(const string &event, utime_t stamp)
     Mutex::Locker l(lock);
     events.push_back(Event(stamp, event));
   }
-  tracker->mark_event(this, event.c_str());
+  dout(5) <<  "seq: " << seq
+         << ", time: " << stamp
+         << ", event: " << event
+         << ", op: " << get_desc()
+         << dendl;
   _event_marked();
 }
 
@@ -351,8 +344,13 @@ void TrackedOp::mark_event(const char *event, utime_t stamp)
   {
     Mutex::Locker l(lock);
     events.push_back(Event(stamp, event));
+    current = event;
   }
-  tracker->mark_event(this, event);
+  dout(5) <<  "seq: " << seq
+         << ", time: " << stamp
+         << ", event: " << event
+         << ", op: " << get_desc()
+         << dendl;
   _event_marked();
 }
 
@@ -361,9 +359,7 @@ void TrackedOp::dump(utime_t now, Formatter *f) const
   // Ignore if still in the constructor
   if (!state)
     return;
-  stringstream name;
-  _dump_op_descriptor_unlocked(name);
-  f->dump_string("description", name.str().c_str()); // this TrackedOp
+  f->dump_string("description", get_desc());
   f->dump_stream("initiated_at") << get_initiated();
   f->dump_float("age", now - get_initiated());
   f->dump_float("duration", get_duration());

diff --git a/src/common/TrackedOp.h b/src/common/TrackedOp.h
index 04c997bb2fff29a31b95b38ff99acc91d348945f..3bd865bdec77918dc6c77ebbba1bf8453f1fbf28 100644 (file)
--- a/src/common/TrackedOp.h
+++ b/src/common/TrackedOp.h
@@ -100,9 +100,6 @@ public:
   bool check_ops_in_flight(std::vector<string> &warning_strings,
                           int *slow = NULL);
 
-  void mark_event(TrackedOp *op, const char *evt,
-                 utime_t time = ceph_clock_now());
-
   void on_shutdown() {
     history.on_shutdown();
   }
@@ -189,6 +186,9 @@ protected:
   };
   atomic<int> state = {STATE_UNTRACKED};
 
+  mutable string desc_str;   ///< protected by lock
+  mutable const char *desc = nullptr;  ///< readable without lock
+
   TrackedOp(OpTracker *_tracker, const utime_t& initiated) :
     tracker(_tracker),
     initiated_at(initiated),
@@ -237,6 +237,23 @@ public:
     }
   }
 
+  const char *get_desc() const {
+    if (!desc) {
+      Mutex::Locker l(lock);
+      _gen_desc();
+    }
+    return desc;
+  }
+  void _gen_desc() const {
+    ostringstream ss;
+    _dump_op_descriptor_unlocked(ss);
+    desc_str = ss.str();
+    desc = desc_str.c_str();
+  }
+  void reset_desc() {
+    desc = nullptr;
+  }
+
   const utime_t& get_initiated() const {
     return initiated_at;
   }

diff --git a/src/messages/MOSDOp.h b/src/messages/MOSDOp.h
index d04955c7c397bfcfe934aa8d911a3b0c554b4e59..0d2a03f271a4dda99c82353640ca3e94d8e5dc6d 100755 (executable)
--- a/src/messages/MOSDOp.h
+++ b/src/messages/MOSDOp.h
@@ -470,10 +470,10 @@ struct ceph_osd_request_head {
     partial_decode_needed = false;
   }
 
-  void finish_decode() {
+  bool finish_decode() {
     assert(!partial_decode_needed); // partial decoding required
     if (!final_decode_needed)
-      return; // Message is already final decoded
+      return false; // Message is already final decoded
     assert(header.version >= 7);
 
     ::decode(client_inc, p);
@@ -498,6 +498,7 @@ struct ceph_osd_request_head {
     OSDOp::split_osd_op_vector_in_data(ops, data);
 
     final_decode_needed = false;
+    return true;
   }
 
   void clear_buffers() {

diff --git a/src/osd/PrimaryLogPG.cc b/src/osd/PrimaryLogPG.cc
index cfd88d4b5684f09faac0b96fcecf22e0089ad9cf..6f2b164dea99d26f173f6865a7ac32ae038bd8e9 100644 (file)
--- a/src/osd/PrimaryLogPG.cc
+++ b/src/osd/PrimaryLogPG.cc
@@ -1705,7 +1705,9 @@ void PrimaryLogPG::do_op(OpRequestRef& op)
   MOSDOp *m = static_cast<MOSDOp*>(op->get_req());
   assert(m->get_type() == CEPH_MSG_OSD_OP);
 
-  m->finish_decode();
+  if (m->finish_decode()) {
+    op->reset_desc();   // for TrackedOp
+  }
   m->clear_payload();
 
   dout(20) << __func__ << ": op " << *m << dendl;