[3804] Measure callout execution time and log it.

src/lib/hooks/callout_manager.cc

@@ -1,4 +1,4 @@
-// Copyright (C) 2013  Internet Systems Consortium, Inc. ("ISC")
+// Copyright (C) 2013,2015  Internet Systems Consortium, Inc. ("ISC")
 //
 // Permission to use, copy, modify, and/or distribute this software for any
 // purpose with or without fee is hereby granted, provided that the above
@@ -16,6 +16,7 @@
 #include <hooks/callout_manager.h>
 #include <hooks/hooks_log.h>
 #include <hooks/pointer_converter.h>
+#include <util/stopwatch.h>
 
 #include <boost/static_assert.hpp>
 
@@ -134,6 +135,8 @@ CalloutManager::callCallouts(int hook_index, CalloutHandle& callout_handle) {
         // change and potentially affect the iteration through that vector.
         CalloutVector callouts(hook_vector_[hook_index]);
 
+        util::Stopwatch stopwatch;
+
         // Call all the callouts.
         for (CalloutVector::const_iterator i = callouts.begin();
              i != callouts.end(); ++i) {
@@ -144,17 +147,21 @@ CalloutManager::callCallouts(int hook_index, CalloutHandle& callout_handle) {
 
             // Call the callout
             try {
+                stopwatch.start();
                 int status = (*i->second)(callout_handle);
+                stopwatch.stop();
                 if (status == 0) {
                     LOG_DEBUG(hooks_logger, HOOKS_DBG_EXTENDED_CALLS,
                               HOOKS_CALLOUT_CALLED).arg(current_library_)
                         .arg(server_hooks_.getName(current_hook_))
-                        .arg(PointerConverter(i->second).dlsymPtr());
+                        .arg(PointerConverter(i->second).dlsymPtr())
+                        .arg(stopwatch.logFormatLastDuration());
                 } else {
                     LOG_ERROR(hooks_logger, HOOKS_CALLOUT_ERROR)
                         .arg(current_library_)
                         .arg(server_hooks_.getName(current_hook_))
-                        .arg(PointerConverter(i->second).dlsymPtr());
+                        .arg(PointerConverter(i->second).dlsymPtr())
+                        .arg(stopwatch.logFormatLastDuration());
                 }
             } catch (const std::exception& e) {
                 // Any exception, not just ones based on isc::Exception
@@ -162,7 +169,8 @@ CalloutManager::callCallouts(int hook_index, CalloutHandle& callout_handle) {
                     .arg(current_library_)
                     .arg(server_hooks_.getName(current_hook_))
                     .arg(PointerConverter(i->second).dlsymPtr())
-                    .arg(e.what());
+                    .arg(e.what())
+                    .arg(stopwatch.logFormatLastDuration());
             }
 
         }

src/lib/hooks/hooks_messages.mes

@@ -27,7 +27,7 @@ the specified hook.  This is similar to the HOOKS_DEREGISTER_ALL_CALLOUTS
 message (and the two are likely to be seen together), but is issued at a
 higher-level in the hook framework.
 
-% HOOKS_CALLOUT_CALLED hooks library with index %1 has called a callout on hook %2 that has address %3
+% HOOKS_CALLOUT_CALLED hooks library with index %1 has called a callout on hook %2 that has address %3 (callout duration: %4)
 Only output at a high debugging level, this message indicates that
 a callout on the named hook registered by the library with the given
 index (in the list of loaded libraries) has been called and returned a
@@ -38,13 +38,13 @@ A debug message issued when all instances of a particular callouts on
 the hook identified in the message that were registered by the library
 with the given index have been removed.
 
-% HOOKS_CALLOUT_ERROR error returned by callout on hook %1 registered by library with index %2 (callout address %3)
+% HOOKS_CALLOUT_ERROR error returned by callout on hook %1 registered by library with index %2 (callout address %3) (callout duration %4)
 If a callout returns an error status when called, this error message
 is issued.  It identifies the hook to which the callout is attached, the
 index of the library (in the list of loaded libraries) that registered
 it and the address of the callout.  The error is otherwise ignored.
 
-% HOOKS_CALLOUT_EXCEPTION exception thrown by callout on hook %1 registered by library with index %2 (callout address %3): %4
+% HOOKS_CALLOUT_EXCEPTION exception thrown by callout on hook %1 registered by library with index %2 (callout address %3): %4 (callout duration: $5)
 If a callout throws an exception when called, this error message is
 issued.  It identifies the hook to which the callout is attached, the
 index of the library (in the list of loaded libraries) that registered

src/lib/util/stopwatch.cc

@@ -28,6 +28,10 @@ Stopwatch::Stopwatch(const bool autostart)
     }
 }
 
+Stopwatch::~Stopwatch() {
+    delete impl_;
+}
+
 void
 Stopwatch::start() {
     impl_->start();
@@ -73,5 +77,15 @@ Stopwatch::getTotalMicroseconds() const {
     return (getTotalDuration().total_microseconds());
 }
 
+std::string
+Stopwatch::logFormatLastDuration() const {
+    return (StopwatchImpl::logFormat(getLastDuration()));
+}
+
+std::string
+Stopwatch::logFormatTotalDuration() const {
+    return (StopwatchImpl::logFormat(getTotalDuration()));
+}
+
 } // end of isc::util
 } // end of isc

src/lib/util/stopwatch.h

@@ -16,7 +16,6 @@
 #define STOPWATCH_H
 
 #include <boost/date_time/posix_time/posix_time.hpp>
-#include <boost/scoped_ptr.hpp>
 
 namespace isc {
 namespace util {
@@ -52,6 +51,11 @@ public:
     /// @c Stopwatch::start must be called to start time measurement.
     Stopwatch(const bool autostart = true);
 
+    /// @brief Destructor.
+    ///
+    /// Destroys the implementation instance.
+    ~Stopwatch();
+
     /// @brief Starts the stopwatch.
     ///
     /// Sets the stopwatch to the "started" state. In this state the stopwatch
@@ -110,10 +114,18 @@ public:
     /// @brief Retrieves the total measured duration in microseconds.
     long getTotalMicroseconds() const;
 
+    /// @brief Returns the last measured duration in the format directly
+    /// usable in log messages.
+    std::string logFormatLastDuration() const;
+
+    /// @brief Returns the total measured duration in the format directly
+    /// usable in the log messages.
+    std::string logFormatTotalDuration() const;
+
 private:
 
     /// @brief Pointer to the @c StopwatchImpl.
-    boost::scoped_ptr<StopwatchImpl> impl_;
+    StopwatchImpl* impl_;
 
 };
 

src/lib/util/stopwatch_impl.cc

@@ -13,6 +13,7 @@
 // PERFORMANCE OF THIS SOFTWARE.
 
 #include <util/stopwatch_impl.h>
+#include <sstream>
 
 namespace isc {
 namespace util {
@@ -82,6 +83,14 @@ StopwatchImpl::getTotalDuration() const {
     return (total_duration);
 }
 
+std::string
+StopwatchImpl::logFormat(const boost::posix_time::time_duration& duration) {
+    std::ostringstream s;
+    s << duration.total_milliseconds() << ".";
+    s << (duration.total_microseconds() % 1000) << " ms";
+    return (s.str());
+}
+
 ptime
 StopwatchImpl::getCurrentTime() const {
     return (microsec_clock::universal_time());

src/lib/util/stopwatch_impl.h

@@ -82,6 +82,19 @@ public:
     /// Also see the @c Stopwatch::getTotalDuration for details.
     boost::posix_time::time_duration getTotalDuration() const;
 
+    /// @brief Returns the duration in the textual format which can be
+    /// directly used in log messages.
+    ///
+    /// @todo Currently this function returns the duration as fractional
+    /// milliseconds. We may come up with something more sophisticated
+    /// in the future.
+    ///
+    /// @param duration Duration to be converted to the textual format.
+    ///
+    /// @return Converted value which can be used to log duration.
+    static std::string
+    logFormat(const boost::posix_time::time_duration& duration);
+
 protected:
 
     /// @brief Returns the current time.

src/lib/util/tests/stopwatch_unittest.cc

@@ -14,8 +14,10 @@
 
 #include <util/stopwatch.h>
 #include <util/stopwatch_impl.h>
+#include <boost/date_time/posix_time/posix_time.hpp>
 #include <gtest/gtest.h>
 #include <unistd.h>
+
 namespace {
 
 using namespace isc;
@@ -48,12 +50,14 @@ public:
     /// @brief Fast forward time.
     ///
     /// Moves the value of the @c current_time_ forward by the specified
-    /// number of milliseconds. As a result the timestamp returned by the
-    /// @c StopwatchMock::getCurrentTime moves by this value. This simulates
-    /// the time progress.
+    /// number of milliseconds (microseconds). As a result the timestamp
+    /// returned by the @c StopwatchMock::getCurrentTime moves by this value.
+    /// This simulates the time progress.
     ///
     /// @param ms Specifies the number of milliseconds to move current time.
-    void ffwd(const uint32_t ms);
+    /// @param us Specifies the number of fractional microseconds to move
+    /// current time.
+    void ffwd(const uint32_t ms, const uint32_t us = 0);
 
     /// @brief Returns the last duration in milliseconds.
     uint32_t getLastDurationInMs() const;
@@ -81,8 +85,9 @@ StopwatchMock::StopwatchMock(const ptime& ref_time)
 }
 
 void
-StopwatchMock::ffwd(const uint32_t ms) {
+StopwatchMock::ffwd(const uint32_t ms, const uint32_t us) {
     current_time_ += milliseconds(ms);
+    current_time_ += microseconds(us);
 }
 
 uint32_t
@@ -280,4 +285,16 @@ TEST_F(StopwatchTest, autostart) {
     EXPECT_EQ(stopwatch.getMilliseconds(), stopwatch.getTotalMilliseconds());
 }
 
+// Make sure that the conversion to the loggable string works as expected.
+TEST_F(StopwatchTest, logFormat) {
+    time_duration duration = microseconds(223543);
+    EXPECT_EQ("223.543 ms", StopwatchImpl::logFormat(duration));
+
+    duration = microseconds(1234);
+    EXPECT_EQ("1.234 ms", StopwatchImpl::logFormat(duration));
+
+    duration = microseconds(2000);
+    EXPECT_EQ("2.0 ms", StopwatchImpl::logFormat(duration));
+}
+
 } // end of anonymous namespace