TrackedOp: rename arrived_at to initiated_at, specify when constructed

Instead of relying on the message's get_recv_stamp, take a timestamp
when the TrackedOp is constructed. Rename get_received_at() -> get_initiated().

Signed-off-by: Greg Farnum <greg@inktank.com>

diff --git a/src/common/TrackedOp.cc b/src/common/TrackedOp.cc
index 65239ab2e05605f5a46cb99774b08f622399fce1..0a2a2896dd7ca6eee40e2112f7e7c9ec2a8c9f8e 100644 (file)
--- a/src/common/TrackedOp.cc
+++ b/src/common/TrackedOp.cc
@@ -40,7 +40,7 @@ void OpHistory::insert(utime_t now, TrackedOpRef op)
   if (shutdown)
     return;
   duration.insert(make_pair(op->get_duration(), op));
-  arrived.insert(make_pair(op->get_arrived(), op));
+  arrived.insert(make_pair(op->get_initiated(), op));
   cleanup(now);
 }
 
@@ -57,7 +57,7 @@ void OpHistory::cleanup(utime_t now)
 
   while (duration.size() > history_size) {
     arrived.erase(make_pair(
-       duration.begin()->second->get_arrived(),
+       duration.begin()->second->get_initiated(),
        duration.begin()->second));
     duration.erase(duration.begin());
   }
@@ -141,7 +141,7 @@ bool OpTracker::check_ops_in_flight(std::vector<string> &warning_vector)
   utime_t too_old = now;
   too_old -= complaint_time;
 
-  utime_t oldest_secs = now - ops_in_flight.front()->get_arrived();
+  utime_t oldest_secs = now - ops_in_flight.front()->get_initiated();
 
   dout(10) << "ops_in_flight.size: " << ops_in_flight.size()
            << "; oldest is " << oldest_secs
@@ -155,11 +155,11 @@ bool OpTracker::check_ops_in_flight(std::vector<string> &warning_vector)
 
   int slow = 0;     // total slow
   int warned = 0;   // total logged
-  while (!i.end() && (*i)->get_arrived() < too_old) {
+  while (!i.end() && (*i)->get_initiated() < too_old) {
     slow++;
 
     // exponential backoff of warning intervals
-    if (((*i)->get_arrived() +
+    if (((*i)->get_initiated() +
         (complaint_time * (*i)->warn_interval_multiplier)) < now) {
       // will warn
       if (warning_vector.empty())
@@ -168,9 +168,9 @@ bool OpTracker::check_ops_in_flight(std::vector<string> &warning_vector)
       if (warned > log_threshold)
         break;
 
-      utime_t age = now - (*i)->get_arrived();
+      utime_t age = now - (*i)->get_initiated();
       stringstream ss;
-      ss << "slow request " << age << " seconds old, received at " << (*i)->get_arrived()
+      ss << "slow request " << age << " seconds old, received at " << (*i)->get_initiated()
         << ": " << *((*i)->request) << " currently "
         << ((*i)->current.size() ? (*i)->current : (*i)->state_string());
       warning_vector.push_back(ss.str());
@@ -204,7 +204,7 @@ void OpTracker::get_age_ms_histogram(pow2_hist_t *h)
   uint32_t lb = 1 << (bin-1);  // lower bound for this bin
   int count = 0;
   for (xlist<TrackedOp*>::iterator i = ops_in_flight.begin(); !i.end(); ++i) {
-    utime_t age = now - (*i)->get_arrived();
+    utime_t age = now - (*i)->get_initiated();
     uint32_t ms = (long)(age * 1000.0);
     if (ms >= lb) {
       count++;
@@ -267,8 +267,8 @@ void TrackedOp::dump(utime_t now, Formatter *f) const
   stringstream name;
   _dump_op_descriptor(name);
   f->dump_string("description", name.str().c_str()); // this TrackedOp
-  f->dump_stream("received_at") << get_arrived();
-  f->dump_float("age", now - get_arrived());
+  f->dump_stream("initiated_at") << get_initiated();
+  f->dump_float("age", now - get_initiated());
   f->dump_float("duration", get_duration());
   {
     f->open_array_section("type_data");

diff --git a/src/common/TrackedOp.h b/src/common/TrackedOp.h
index 102d0bd50d9047a6e3d24fc576df20e8f019bcc7..28f0874048eecf8a7e593da4be6141638e5f32eb 100644 (file)
--- a/src/common/TrackedOp.h
+++ b/src/common/TrackedOp.h
@@ -130,6 +130,7 @@ protected:
   Message *request; /// the logical request we are tracking
   OpTracker *tracker; /// the tracker we are associated with
 
+  utime_t initiated_at;
   list<pair<utime_t, string> > events; /// list of events and their times
   Mutex lock; /// to protect the events list
   string current; /// the current state the event is in
@@ -137,10 +138,11 @@ protected:
 
   uint32_t warn_interval_multiplier; // limits output of a given op warning
 
-  TrackedOp(Message *req, OpTracker *_tracker) :
+  TrackedOp(Message *req, OpTracker *_tracker, const utime_t& initiated) :
     xitem(this),
     request(req),
     tracker(_tracker),
+    initiated_at(initiated),
     lock("TrackedOp::lock"),
     seq(0),
     warn_interval_multiplier(1)
@@ -158,13 +160,13 @@ protected:
 public:
   virtual ~TrackedOp() { assert(request); request->put(); }
 
-  utime_t get_arrived() const {
-    return request->get_recv_stamp();
+  const utime_t& get_initiated() const {
+    return initiated_at;
   }
   // This function maybe needs some work; assumes last event is completion time
   double get_duration() const {
     return events.size() ?
-      (events.rbegin()->first - get_arrived()) :
+      (events.rbegin()->first - get_initiated()) :
       0.0;
   }
   Message *get_req() const { return request; }

diff --git a/src/osd/OpRequest.cc b/src/osd/OpRequest.cc
index 949071a03512f5eebc4e7fd80792d9fee38c2997..a6e908791081ecd141fb5130ed63ed25b1388b3c 100644 (file)
--- a/src/osd/OpRequest.cc
+++ b/src/osd/OpRequest.cc
@@ -15,7 +15,7 @@
 
 
 OpRequest::OpRequest(Message *req, OpTracker *tracker) :
-  TrackedOp(req, tracker),
+  TrackedOp(req, tracker, req->get_recv_stamp()),
   rmw_flags(0),
   hit_flag_points(0), latest_flag_point(0) {
   if (req->get_priority() < tracker->cct->_conf->osd_client_op_priority) {