Enhance StopWatch

Clean up, comments and enhancements. StopWatch lap() didn't mean lap-time, but elapsed time. Changed meaning to lap-time and added split() for split-time.

maxutils/maxbase/include/maxbase/stopwatch.hh

@@ -20,51 +20,103 @@
 namespace maxbase
 {
 
+/**
+ *   @class Clock
+ *
+ *   MaxScale "standard" std::chrono clock
+ */
 using Clock = std::chrono::steady_clock;
 
-struct Duration : public Clock::duration    // for ADL
+/**
+ *  @class Duration
+ *
+ *  Duration behaves exactly like Clock::duration, but adds ADL and, a
+ *  conveniece constructor and function secs() for seconds as a double.
+ */
+struct Duration : public Clock::duration
 {
     using Clock::duration::duration;
     Duration() = default;
     Duration(Clock::duration d) : Clock::duration(d)
     {
     }
-    Duration(long long l) : Clock::duration(l)
-    {
-    }                                               // FIXME. Get rid of this.
 
+    /** From seconds */
     explicit Duration(double secs) : Duration{rep(secs * period::den / period::num)}
     {
     }
 
+    /** To seconds */
     double secs()
     {
         return std::chrono::duration<double>(*this).count();
     }
 };
 
-typedef std::chrono::time_point<Clock, Duration> TimePoint;
+/**
+ *   @class TimePoint
+ *
+ *   A std::chrono::time_point to go with Clock and Duration.
+ */
+using TimePoint = std::chrono::time_point<Clock, Duration>;
 
+/**
+ *  @class StopWatch
+ *
+ *  Simple stopwatch for measuring time.
+ *
+ *  Example usage:
+ *    auto limit = maxbase::Duration(std::chrono::milliseconds(100));
+ *
+ *    maxbase::StopWatch sw;
+ *    foo();
+ *    auto duration = sw.split();
+ *
+ *    std::cout << "foo duration " << duration << std::endl;
+ *    if (duration > limit)
+ *    {
+ *        maxbase::Duration diff = duration - limit; // no auto, would become Clock::duration.
+ *        std::cerr << "foo exceeded the limit " << limit << " by "  << diff << std::endl;
+ *    }
+ *  Possible output:
+ *    foo duration 100.734ms
+ *    foo exceeded the limit 100ms by 733.636us
+ */
 class StopWatch
 {
 public:
-    // Starts the stopwatch, which is always running.
+    /** Create and start the stopwatch. */
     StopWatch();
-    // Get elapsed time.
+
-    Duration lap() const;
+    /** Split time. Overall duration since creation or last restart(). */
-    // Get elapsed time, restart StopWatch.
+    Duration split() const;
+
+    /** Lap time. Time since last lap() call, or if lap() was not called, creation or last restart(). */
+    Duration lap();
+
+    /** Return split time and restart stopwatch. */
     Duration restart();
 private:
     TimePoint m_start;
+    TimePoint m_lap;
 };
 
-// Returns the value as a double and string adjusted to a suffix like ms for milliseconds.
+/** Returns the duration as a double and string adjusted to a suffix like ms for milliseconds.
+ *  The double and suffix (unit) combination is selected to be easy to read.
+ *  This is for output conveniece. You can always convert a duration to a specific unit:
+ *  long ms {std::chrono::duration_cast<std::chrono::milliseconds>(dur).count()};
+ */
 std::pair<double, std::string> dur_to_human_readable(Duration dur);
 
-// Human readable output. No standard library for it yet.
+/** Create a string using dur_to_human_readable, std::ostringstream << d.first << sep << d.second. */
-std::ostream& operator<<(std::ostream&, Duration dur);
+std::string to_string(Duration dur, const std::string& sep = "");
 
-// TimePoint
+/** Stream to os << d.first << d.second. Not using to_string(), which would use a default stream. */
-std::string   time_point_to_string(TimePoint tp, const std::string& fmt = "%F %T");
+std::ostream& operator<<(std::ostream& os, Duration dur);
+
+/** TimePoint to string, formatted using strftime formats. */
+std::string to_string(TimePoint tp, const std::string& fmt = "%F %T");
+
+/** Stream to std::ostream using to_string(tp) */
 std::ostream& operator<<(std::ostream&, TimePoint tp);
-}   // maxbase
+}

maxutils/maxbase/src/eventcount.cc

@@ -42,7 +42,7 @@ void EventCount::increment()
     if (m_timestamps.empty()
         || m_timestamps.back().time_point.time_since_epoch().count() != ticks)
     {
-        m_timestamps.emplace_back(TimePoint(ticks), 1);
+        m_timestamps.emplace_back(TimePoint(Duration(nanoseconds(ticks))), 1);
     }
     else
     {

maxutils/maxbase/src/stopwatch.cc

@@ -26,17 +26,25 @@ StopWatch::StopWatch()
     restart();
 }
 
-Duration StopWatch::lap() const
+Duration StopWatch::split() const
 {
     return {Clock::now() - m_start};
 }
 
+Duration StopWatch::lap()
+{
+    auto now = Clock::now();
+    Duration lap = now - m_lap;
+    m_lap = now;
+    return lap;
+}
+
 Duration StopWatch::restart()
 {
     TimePoint now = Clock::now();
-    Duration lap = now - m_start;
+    Duration split = now - m_start;
-    m_start = now;
+    m_start = m_lap = now;
-    return lap;
+    return split;
 }
 }   // maxbase
 
@@ -64,6 +72,7 @@ int convert_size = sizeof(convert) / sizeof(convert[0]);
 
 namespace maxbase
 {
+
 std::pair<double, std::string> dur_to_human_readable(Duration dur)
 {
     using namespace std::chrono;
@@ -89,6 +98,15 @@ std::pair<double, std::string> dur_to_human_readable(Duration dur)
     abort();    // should never get here
 }
 
+std::string to_string(Duration dur, const std::string& sep)
+{
+    auto p = dur_to_human_readable(dur);
+    std::ostringstream os;
+    os << p.first << sep << p.second;
+
+    return os.str();
+}
+
 std::ostream& operator<<(std::ostream& os, Duration dur)
 {
     auto p = dur_to_human_readable(dur);
@@ -97,14 +115,13 @@ std::ostream& operator<<(std::ostream& os, Duration dur)
     return os;
 }
 
-// TODO: this will require some thought. time_point_to_string() for a system_clock is
+// TODO: this will require some thought. to_string() for a system_clock is
 // obvious, but not so for a steady_clock. Maybe TimePoint belongs to a system clock
 // and sould be called something else here, and live in a time_measuring namespace.
-std::string time_point_to_string(TimePoint tp, const std::string& fmt)
+std::string to_string(TimePoint tp, const std::string& fmt)
 {
     using namespace std::chrono;
-    std::time_t timet = system_clock::to_time_t(system_clock::now()
+    std::time_t timet = system_clock::to_time_t(system_clock::now() + (tp - Clock::now()));
-                                                + (tp - Clock::now()));
 
     struct tm* ptm;
     ptm = gmtime (&timet);
@@ -116,7 +133,7 @@ std::string time_point_to_string(TimePoint tp, const std::string& fmt)
 
 std::ostream& operator<<(std::ostream& os, TimePoint tp)
 {
-    os << time_point_to_string(tp);
+    os << to_string(tp);
     return os;
 }
 
@@ -145,4 +162,4 @@ void test_stopwatch_output(std::ostream& os)
         os << Duration(dur[i]) << std::endl;
     }
 }
-}   // maxbase
+}

server/modules/filter/throttlefilter/throttlesession.cc

@@ -84,14 +84,14 @@ int ThrottleSession::real_routeQuery(GWBUF* buffer, bool is_delayed)
     }
     else if (m_state == State::THROTTLING)
     {
-        if (m_last_sample.lap() > m_filter.config().continuous_duration)
+        if (m_last_sample.split() > m_filter.config().continuous_duration)
         {
             m_state = State::MEASURING;
             MXS_INFO("Query throttling stopped session %ld user %s",
                      m_pSession->ses_id,
                      m_pSession->client_dcb->user);
         }
-        else if (m_first_sample.lap() > m_filter.config().throttling_duration)
+        else if (m_first_sample.split() > m_filter.config().throttling_duration)
         {
             MXS_NOTICE("Query throttling Session %ld user %s, throttling limit reached. Disconnect.",
                        m_pSession->ses_id,

server/modules/monitor/mariadbmon/mariadbserver.cc

@@ -195,7 +195,7 @@ bool MariaDBServer::execute_cmd_time_limit(const std::string& cmd, maxbase::Dura
         cmd_success = execute_cmd_no_retry(cmd, &error_msg, &errornum);
 
         // Check if there is time to retry.
-        Duration time_remaining = time_limit - timer.lap();
+        Duration time_remaining = time_limit - timer.split();
         keep_trying = (mxs_mysql_is_net_error(errornum) && (time_remaining.secs() > 0));
         if (!cmd_success)
         {
@@ -1442,12 +1442,12 @@ bool MariaDBServer::promote_v2(ClusterOperation* op)
 
     // Helper function for stopping a slave connection and setting error.
     auto stop_slave_helper = [this, &timer, &stop_slave_error, op, error_out](const string& conn_name) {
-        if (!stop_slave_conn(conn_name, StopMode::RESET_ALL, op->time_remaining, error_out))
+            if (!stop_slave_conn(conn_name, StopMode::RESET_ALL, op->time_remaining, error_out))
-        {
+            {
-            stop_slave_error = true;
+                stop_slave_error = true;
-        }
+            }
-        op->time_remaining -= timer.restart();
+            op->time_remaining -= timer.restart();
-    };
+        };
 
     if (op->type == OperationType::SWITCHOVER)
     {