From 2e674dea6367a12469ee7fae03ab8cca0abb4fde Mon Sep 17 00:00:00 2001 From: Greg Farnum Date: Tue, 22 Apr 2014 15:10:47 -0700 Subject: [PATCH] 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 --- src/common/TrackedOp.cc | 20 ++++++++++---------- src/common/TrackedOp.h | 10 ++++++---- src/osd/OpRequest.cc | 2 +- 3 files changed, 17 insertions(+), 15 deletions(-) diff --git a/src/common/TrackedOp.cc b/src/common/TrackedOp.cc index 65239ab2e0560..0a2a2896dd7ca 100644 --- 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 &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 &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 &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::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 102d0bd50d904..28f0874048eec 100644 --- 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 > 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 949071a03512f..a6e908791081e 100644 --- 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) { -- 2.39.5