Browse Source

[master] Merge branch 'trac3804'

Marcin Siodelski 10 years ago
parent
commit
dd1432d780

+ 16 - 4
doc/guide/logging.xml

@@ -174,8 +174,14 @@
           </listitem>
           <listitem>
             <simpara><command>kea-dhcp4.hooks</command> - this logger is used
-            during DHCPv4 hooks operation, i.e. anything related to user
-            libraries will be logged using this logger.</simpara>
+            to log messages related to management of hooks libraries, e.g.
+            registration and deregistration of the libraries.</simpara>
+          </listitem>
+          <listitem>
+            <simpara><command>kea-dhcp4.callouts</command> - this logger is used
+            to log messages pertaining to the callouts registration and execution
+            for the particular hook point.
+            </simpara>
           </listitem>
           <listitem>
             <simpara><command>kea-dhcp4.hosts</command> - this logger is used
@@ -202,8 +208,14 @@
           </listitem>
           <listitem>
             <simpara><command>kea-dhcp6.hooks</command> - this logger is used
-            during DHCPv6 hooks operation, i.e. anything related to user
-            libraries will be logged using this logger.</simpara>
+            to log messages related to management of hooks libraries, e.g.
+            registration and deregistration of the libraries.</simpara>
+          </listitem>
+          <listitem>
+            <simpara><command>kea-dhcp6.callouts</command> - this logger is used
+            to log messages pertaining to the callouts registration and execution
+            for the particular hook point.
+            </simpara>
           </listitem>
           <listitem>
             <simpara><command>kea-dhcp6.hosts</command> - this logger is used

+ 33 - 10
src/lib/hooks/callout_manager.cc

@@ -1,4 +1,4 @@
-// Copyright (C) 2013, 2015  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
@@ -18,6 +18,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>
 
@@ -67,7 +68,7 @@ CalloutManager::checkLibraryIndex(int library_index) const {
 void
 CalloutManager::registerCallout(const std::string& name, CalloutPtr callout) {
     // Note the registration.
-    LOG_DEBUG(hooks_logger, HOOKS_DBG_CALLS, HOOKS_CALLOUT_REGISTRATION)
+    LOG_DEBUG(callouts_logger, HOOKS_DBG_CALLS, HOOKS_CALLOUT_REGISTRATION)
         .arg(current_library_).arg(name);
 
     // Sanity check that the current library index is set to a valid value.
@@ -136,6 +137,14 @@ CalloutManager::callCallouts(int hook_index, CalloutHandle& callout_handle) {
         // change and potentially affect the iteration through that vector.
         CalloutVector callouts(hook_vector_[hook_index]);
 
+        // This object will be used to measure execution time of each callout
+        // and the total time spent in callouts for this hook point.
+        util::Stopwatch stopwatch;
+
+        // Mark that the callouts begin for the hook.
+        LOG_DEBUG(callouts_logger, HOOKS_DBG_CALLS, HOOKS_CALLOUTS_BEGIN)
+            .arg(server_hooks_.getName(current_hook_));
+
         // Call all the callouts.
         for (CalloutVector::const_iterator i = callouts.begin();
              i != callouts.end(); ++i) {
@@ -146,29 +155,43 @@ 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,
+                    LOG_DEBUG(callouts_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)
+                    LOG_ERROR(callouts_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) {
+                // If an exception occurred, the stopwatch.stop() hasn't been
+                // called, so we have to call it here.
+                stopwatch.stop();
                 // Any exception, not just ones based on isc::Exception
-                LOG_ERROR(hooks_logger, HOOKS_CALLOUT_EXCEPTION)
+                LOG_ERROR(callouts_logger, HOOKS_CALLOUT_EXCEPTION)
                     .arg(current_library_)
                     .arg(server_hooks_.getName(current_hook_))
                     .arg(PointerConverter(i->second).dlsymPtr())
-                    .arg(e.what());
+                    .arg(e.what())
+                    .arg(stopwatch.logFormatLastDuration());
             }
 
         }
 
+        // Mark end of callout execution. Include the total execution
+        // time for callouts.
+        LOG_DEBUG(callouts_logger, HOOKS_DBG_CALLS, HOOKS_CALLOUTS_COMPLETE)
+            .arg(server_hooks_.getName(current_hook_))
+            .arg(stopwatch.logFormatTotalDuration());
+
         // Reset the current hook and library indexs to an invalid value to
         // catch any programming errors.
         current_hook_ = -1;
@@ -214,7 +237,7 @@ CalloutManager::deregisterCallout(const std::string& name, CalloutPtr callout) {
     // Return an indication of whether anything was removed.
     bool removed = initial_size != hook_vector_[hook_index].size();
     if (removed) {
-        LOG_DEBUG(hooks_logger, HOOKS_DBG_EXTENDED_CALLS,
+        LOG_DEBUG(callouts_logger, HOOKS_DBG_EXTENDED_CALLS,
                   HOOKS_CALLOUT_DEREGISTERED).arg(current_library_).arg(name);
     }
 
@@ -249,7 +272,7 @@ CalloutManager::deregisterAllCallouts(const std::string& name) {
     // Return an indication of whether anything was removed.
     bool removed = initial_size != hook_vector_[hook_index].size();
     if (removed) {
-        LOG_DEBUG(hooks_logger, HOOKS_DBG_EXTENDED_CALLS,
+        LOG_DEBUG(callouts_logger, HOOKS_DBG_EXTENDED_CALLS,
                   HOOKS_ALL_CALLOUTS_DEREGISTERED).arg(current_library_)
                                                 .arg(name);
     }

+ 5 - 3
src/lib/hooks/hooks_log.cc

@@ -1,4 +1,4 @@
-// Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+// Copyright (C) 2011,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
@@ -12,15 +12,17 @@
 // OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 // PERFORMANCE OF THIS SOFTWARE.
 
-/// Defines the logger used by the NSAS
+/// Defines the logger used by the Hooks
 
-#include "hooks/hooks_log.h"
+#include <hooks/hooks_log.h>
 
 namespace isc {
 namespace hooks {
 
 isc::log::Logger hooks_logger("hooks");
 
+isc::log::Logger callouts_logger("callouts");
+
 } // namespace hooks
 } // namespace isc
 

+ 8 - 1
src/lib/hooks/hooks_log.h

@@ -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
@@ -44,6 +44,13 @@ const int HOOKS_DBG_EXTENDED_CALLS = DBGLVL_TRACE_DETAIL_DATA;
 /// space.
 extern isc::log::Logger hooks_logger;
 
+/// @brief Callouts logger
+///
+/// This is the specialized logger used to log messages pertaining to the
+/// callouts execution. In particular, it logs when the callout is invoked
+/// and when it ends. It also logs the callout execution times.
+extern isc::log::Logger callouts_logger;
+
 } // namespace hooks
 } // namespace isc
 

+ 16 - 4
src/lib/hooks/hooks_messages.mes

@@ -20,6 +20,15 @@ by the library with the given index were removed.  This is similar to
 the HOOKS_CALLOUTS_REMOVED message (and the two are likely to be seen
 together), but is issued at a lower-level in the hook framework.
 
+% HOOKS_CALLOUTS_BEGIN begin all callouts for hook %1
+This debug message is issued when callout manager begins to invoke callouts
+for the hook. The argument specifies the hook name.
+
+% HOOKS_CALLOUTS_COMPLETE completed callouts for hook %1 (total callouts duration: %2)
+This debug message is issued when callout manager has completed execution
+of all callouts for the particular hook. The arguments specify the hook
+name and total execution time for all callouts in milliseconds.
+
 % HOOKS_CALLOUTS_REMOVED callouts removed from hook %1 for library %2
 This is a debug message issued during library unloading.  It notes that
 one of more callouts registered by that library have been removed from
@@ -27,28 +36,31 @@ 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
-success state.  The address of the callout is given in the message
+success state.  The address of the callout is given in the message.
+The message includes the callout execution time in milliseconds.
 
 % HOOKS_CALLOUT_DEREGISTERED hook library at index %1 deregistered a callout on hook %2
 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.
+The error message includes the callout execution time in milliseconds.
 
-% 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
 it and the address of the callout.  The error is otherwise ignored.
+The error message includes the callout execution time in milliseconds.
 
 % HOOKS_CALLOUT_REGISTRATION hooks library with index %1 registering callout for hook '%2'
 This is a debug message, output when a library (whose index in the list

+ 2 - 0
src/lib/util/Makefile.am

@@ -22,6 +22,8 @@ libkea_util_la_SOURCES += pid_file.h pid_file.cc
 libkea_util_la_SOURCES += process_spawn.h process_spawn.cc
 libkea_util_la_SOURCES += range_utilities.h
 libkea_util_la_SOURCES += signal_set.cc signal_set.h
+libkea_util_la_SOURCES += stopwatch.cc stopwatch.h
+libkea_util_la_SOURCES += stopwatch_impl.cc stopwatch_impl.h
 libkea_util_la_SOURCES += encode/base16_from_binary.h
 libkea_util_la_SOURCES += encode/base32hex.h encode/base64.h
 libkea_util_la_SOURCES += encode/base32hex_from_binary.h

+ 91 - 0
src/lib/util/stopwatch.cc

@@ -0,0 +1,91 @@
+// Copyright (C) 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
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#include <util/stopwatch.h>
+#include <util/stopwatch_impl.h>
+
+namespace isc {
+namespace util {
+
+using namespace boost::posix_time;
+
+Stopwatch::Stopwatch(const bool autostart)
+    : impl_(new StopwatchImpl()) {
+    // If the autostart has been specified, invoke start.
+    if (autostart) {
+        start();
+    }
+}
+
+Stopwatch::~Stopwatch() {
+    delete impl_;
+}
+
+void
+Stopwatch::start() {
+    impl_->start();
+}
+
+void
+Stopwatch::stop() {
+    impl_->stop();
+}
+
+void
+Stopwatch::reset() {
+    impl_->reset();
+}
+
+boost::posix_time::time_duration
+Stopwatch::getLastDuration() const {
+    return (impl_->getLastDuration());
+}
+
+boost::posix_time::time_duration
+Stopwatch::getTotalDuration() const {
+    return (impl_->getTotalDuration());
+}
+
+long
+Stopwatch::getLastMilliseconds() const {
+    return (getLastDuration().total_milliseconds());
+}
+
+long
+Stopwatch::getTotalMilliseconds() const {
+    return (getTotalDuration().total_milliseconds());
+}
+
+long
+Stopwatch::getLastMicroseconds() const {
+    return (getLastDuration().total_microseconds());
+}
+
+long
+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

+ 136 - 0
src/lib/util/stopwatch.h

@@ -0,0 +1,136 @@
+// Copyright (C) 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
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#ifndef STOPWATCH_H
+#define STOPWATCH_H
+
+#include <boost/date_time/posix_time/posix_time.hpp>
+
+namespace isc {
+namespace util {
+
+/// @brief Forward declaration to the @c Stopwatch implementation.
+class StopwatchImpl;
+
+/// @brief Utility class to measure code execution times.
+///
+/// The API of this class is based on the use cases of a stopwatch. It is
+/// used to measure time spent executing portions of the code. The typical
+/// use case for the @c Stopwatch is to measure the time spent invoking
+/// callouts in hooks library. This provides means for diagnosing the
+/// server's performance degradations when hooks libraries are in use.
+///
+/// This class exposes functions like @c start, @c stop and @c reset which
+/// behave in the same way as a stopwatch used to measure time for sport
+/// activities.
+///
+/// It is possible to measure the cumulative execution time by invoking
+/// @c start and @c stop consecutively. The total measured time will be
+/// a sum of durations between the invocations of respective starts and
+/// stops.
+class Stopwatch {
+public:
+
+    /// @brief Constructor.
+    ///
+    /// @param autostart Indicates if the stopwatch should be initialized to
+    /// the "started" state. In this state the stopwatch is measuring the time
+    /// since it has been started (object has been constructed in this case.
+    /// If the parameter is set to false (default value), the
+    /// @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
+    /// is measuring the duration since @c Stopwatch::start has been invoked.
+    ///
+    //// This method is no-op if the stopwatch is already in the "started"
+    /// state.
+    void start();
+
+    /// @brief Stops the stopwatch.
+    ///
+    /// Sets the stopwatch to the "stopped" state. The stopwatch stops the time
+    /// measurement and records the duration between the last stopwatch start
+    /// and the stop invocation. It also updates the total measured duration,
+    /// i.e. the sum of durations between all start/stop invocations. Both
+    /// values can be retrieved using @c Stopwatch::getLastDuration and
+    /// @c Stopwatch::getTotalDuration respectively, or their variants.
+    ///
+    /// This method is no-op if the stopwatch is already in the "stopped" state.
+    void stop();
+
+    /// @brief Resets the stopwatch.
+    ///
+    /// It resets the stopwatch to the initial state. In this state, the last
+    /// measured duration and the total duration is set to 0. The stopwatch
+    /// is set to the "stopped" state.
+    void reset();
+
+    /// @brief Retrieves last measured duration.
+    ///
+    /// If the stopwatch is in the "stopped" state this method retrieves the
+    /// duration between the last start and stop. If the stopwatch is in the
+    /// "started" state, the retrieved duration is the duration between the
+    /// last start of the stopwatch and the current time.
+    boost::posix_time::time_duration getLastDuration() const;
+
+    /// @brief Retrieves total measured duration.
+    ///
+    /// If the stopwatch is in the "stopped" state this method retrieves the
+    /// total duration between all starts and stops invoked  during the
+    /// lifetime of the object or since the last reset. If the stopwatch is
+    /// in the "started" state, the returned is the sum of all durations
+    /// between respective starts and stops, and the duration since the
+    /// stopwatch has been last started and the current time.
+    boost::posix_time::time_duration getTotalDuration() const;
+
+    /// @brief Retrieves the last measured duration in milliseconds.
+    long getLastMilliseconds() const;
+
+    /// @brief Retrieves the total measured duration in milliseconds.
+    long getTotalMilliseconds() const;
+
+    /// @brief Retrieves the last measured duration in microseconds.
+    long getLastMicroseconds() const;
+
+    /// @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.
+    StopwatchImpl* impl_;
+
+};
+
+}
+}
+
+#endif // STOPWATCH_H
+

+ 103 - 0
src/lib/util/stopwatch_impl.cc

@@ -0,0 +1,103 @@
+// Copyright (C) 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
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#include <util/stopwatch_impl.h>
+#include <iomanip>
+#include <sstream>
+
+namespace isc {
+namespace util {
+
+using namespace boost::posix_time;
+
+StopwatchImpl::StopwatchImpl()
+    : started_(false),
+      last_start_(getCurrentTime()),
+      last_stop_(last_start_),
+      cumulative_time_(microseconds(0)) {
+}
+
+StopwatchImpl::~StopwatchImpl() {
+}
+
+void
+StopwatchImpl::start() {
+    // If stopwatch is "stopped", start it.
+    if (!started_) {
+        last_start_ = getCurrentTime();
+        started_ = true;
+    }
+}
+
+void
+StopwatchImpl::stop() {
+    // Is stopwatch is "started", stop it.
+    if (started_) {
+        last_stop_ = getCurrentTime();
+        // Update the total time with the last measured duration.
+        cumulative_time_ += last_stop_ - last_start_;
+        started_ = false;
+    }
+}
+
+void
+StopwatchImpl::reset() {
+    // Set last start and stop values to the current time. This is the
+    // same as in the constructor. As a result the last duration will
+    // be 0.
+    last_start_ = getCurrentTime();
+    last_stop_ = last_start_;
+    // Set the total duration to 0.
+    cumulative_time_ = microseconds(0);
+    started_ = false;
+}
+
+time_duration
+StopwatchImpl::getLastDuration() const {
+    // If the stopwatch is started, the time measured is between the
+    // start time and the current time. Otherwise, it is between the
+    // start time and last stop.
+    ptime end_time = started_ ? getCurrentTime() : last_stop_;
+    return (end_time - last_start_);
+}
+
+time_duration
+StopwatchImpl::getTotalDuration() const {
+    // Get the total time recorded so far.
+    time_duration total_duration = cumulative_time_;
+    if (started_) {
+        // If the stopwatch is started, add the duration between the
+        // start time and current time.
+        total_duration += (getCurrentTime() - last_start_);
+    }
+    return (total_duration);
+}
+
+std::string
+StopwatchImpl::logFormat(const boost::posix_time::time_duration& duration) {
+    std::ostringstream s;
+    s << duration.total_milliseconds() << ".";
+    s << std::setfill('0') << std::setw(3) << (duration.total_microseconds() % 1000)
+      << " ms";
+    return (s.str());
+}
+
+ptime
+StopwatchImpl::getCurrentTime() const {
+    return (microsec_clock::universal_time());
+}
+
+
+} // end of isc::util
+} // end of isc

+ 134 - 0
src/lib/util/stopwatch_impl.h

@@ -0,0 +1,134 @@
+// Copyright (C) 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
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#ifndef STOPWATCH_IMPL_H
+#define STOPWATCH_IMPL_H
+
+#include <boost/date_time/posix_time/posix_time.hpp>
+#include <boost/scoped_ptr.hpp>
+
+namespace isc {
+namespace util {
+
+/// @brief @c Stopwatch class implementation.
+///
+/// The @c Stopwatch class uses the plimpl idiom to make it easier to unit
+/// test behavior of the @c Stopwatch class without a need to rely on the system
+/// clock. The @c StopwatchImpl API allows for overriding the @c getCurrentTime
+/// method to return the arbitrary time value as current time to various
+/// methods. By setting the current time to arbitrary values the test can expect
+/// arbitrary values being returned by the class methods.
+///
+/// Also, by using the pimpl idiom the @c Stopwatch class hides its implementation
+/// details and leaves the header with only the pointer to the @c StopwatchImpl
+/// class.
+class StopwatchImpl {
+public:
+
+    /// @brief Constructor.
+    ///
+    /// Initializes the internally used timestamps. It also sets the state of
+    /// the stopwatch to "stopped".
+    StopwatchImpl();
+
+    /// @brief Virtual destructor.
+    ///
+    /// This destructor is virtual because the @c StopwatchImpl::getCurrentTime
+    /// is virtual.
+    virtual ~StopwatchImpl();
+
+    /// @brief Starts the stopwatch.
+    ///
+    /// Sets the stopwatch to the "started" state. It also records the time when
+    /// the stopwatch is started. This method is no-op if the stopwatch is
+    /// already in the "started" state.
+    ///
+    /// Also see the @c Stopwatch::start for details.
+    void start();
+
+    /// @brief Stop the stopwatch.
+    ///
+    /// Sets the stopwatch to the "stopped" state. The stop time is recorded and
+    /// the cumulative time is updated to include the duration between the most
+    /// recent start and stop. This method is no-op if the stopwatch is already
+    /// in the "stopped" state.
+    ///
+    /// Also see the @c Stopwatch::stop for details.
+    void stop();
+
+    /// @brief Reset the stopwatch.
+    ///
+    /// Also see the @c Stopwatch::reset for details.
+    void reset();
+
+    /// @brief Retrieves the measured duration.
+    ///
+    /// Also see the @c Stopwatch::getLastDuration for details.
+    boost::posix_time::time_duration getLastDuration() const;
+
+    /// @brief Retrieves the total measured duration.
+    ///
+    /// 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.
+    ///
+    /// This method is used internally by the @c StopwatchImpl class and
+    /// its derivations. This class simply returns the value of
+    /// @c boost::posix_time::micrisec_clock::univeral_time(), which is
+    /// a current timestamp. The derivations may replace it with the
+    /// custom implementations. The typical use case is for the unit tests
+    /// to customize the behavior of this function to return well known
+    /// (deterministic) values. As a result, it is possible to influence
+    /// the "measured" values returned by accessors of this class, which
+    /// can be compared against some exact values.
+    virtual boost::posix_time::ptime getCurrentTime() const;
+
+private:
+
+    /// @brief Holds the state of the stopwatch.
+    bool started_;
+
+    /// @brief Holds the timestamp when the stopwatch has been last started.
+    boost::posix_time::ptime last_start_;
+
+    /// @brief Holds the timestamp when the stopwatch has been last stopped.
+    boost::posix_time::ptime last_stop_;
+
+    /// @brief Holds the total measured time since the stopwatch has been
+    /// first started after creation or reset.
+    boost::posix_time::time_duration cumulative_time_;
+
+};
+
+}
+}
+
+#endif // STOPWATCH_H
+

+ 1 - 0
src/lib/util/tests/Makefile.am

@@ -49,6 +49,7 @@ run_unittests_SOURCES += strutil_unittest.cc
 run_unittests_SOURCES += time_utilities_unittest.cc
 run_unittests_SOURCES += range_utilities_unittest.cc
 run_unittests_SOURCES += signal_set_unittest.cc
+run_unittests_SOURCES += stopwatch_unittest.cc
 
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
 run_unittests_LDFLAGS = $(AM_LDFLAGS) $(GTEST_LDFLAGS)

+ 300 - 0
src/lib/util/tests/stopwatch_unittest.cc

@@ -0,0 +1,300 @@
+// Copyright (C) 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
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#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;
+using namespace isc::util;
+using namespace boost::posix_time;
+
+/// @brief @c StopwatchImpl mock object.
+///
+/// This class derives from the @c StopwatchImpl to override the
+/// @c StopwatchImpl::getCurrentTime. This method is internally called by
+/// the @c StopwatchImpl to determine the current time. By providing the
+/// implementation of this method which returns the fixed (well known)
+/// timestamp value we can obtain the deterministic values from the accessors
+/// of this class.
+///
+/// This class also includes some convenience methods to return the time
+/// durations in milliseconds.
+class StopwatchMock : public StopwatchImpl {
+public:
+
+    /// @brief Constructor.
+    ///
+    /// @param ref_time Reference time, i.e. the arbitrary time value from
+    /// which time is measured. The @c current_time_ value returned by the
+    /// @c StopwatchMock::getCurrentTime is initialized to this value.
+    /// Subsequent calls to the @c StopwatchMock::ffwd move the value of
+    /// the @c current_time_ forward.
+    StopwatchMock(const ptime& ref_time);
+
+    /// @brief Fast forward time.
+    ///
+    /// Moves the value of the @c current_time_ forward by the specified
+    /// 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.
+    /// @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;
+
+    /// @brief Returns the total duration in milliseconds.
+    uint32_t getTotalDurationInMs() const;
+
+protected:
+
+    /// @brief Returs the current time.
+    ///
+    /// This method returns the fixed @c current_time_ timestamp.
+    virtual ptime getCurrentTime() const;
+
+private:
+
+    /// @brief Holds the current time to be returned by the
+    /// @c StopwatchMock::getCurrentTime.
+    ptime current_time_;
+
+};
+
+StopwatchMock::StopwatchMock(const ptime& ref_time)
+    : StopwatchImpl(), current_time_(ref_time) {
+}
+
+void
+StopwatchMock::ffwd(const uint32_t ms, const uint32_t us) {
+    current_time_ += milliseconds(ms);
+    current_time_ += microseconds(us);
+}
+
+uint32_t
+StopwatchMock::getLastDurationInMs() const {
+    return (getLastDuration().total_milliseconds());
+}
+
+uint32_t
+StopwatchMock::getTotalDurationInMs() const {
+    return (getTotalDuration().total_milliseconds());
+}
+
+ptime
+StopwatchMock::getCurrentTime() const {
+    return (current_time_);
+}
+
+/// @brief Test fixture class for testing @c StopwatchImpl.
+class StopwatchTest : public ::testing::Test {
+protected:
+
+    /// @brief Set up the test.
+    ///
+    /// Initializes the reference time to be used to create the instances
+    /// of the @c StopwatchMock objects.
+    virtual void SetUp();
+
+    /// @brief Holds the reference time to be used to create the instances
+    /// of the @c StopwatchMock objects.
+    ptime ref_time_;
+};
+
+void
+StopwatchTest::SetUp() {
+    ref_time_ = microsec_clock::universal_time();
+}
+
+/// This test checks the behavior of the stopwatch when it is started
+/// and stopped multiple times. It uses the StopwatchMock object to
+/// control the "time flow" by setting the current time to arbitrary
+/// values using the StopwatchMock::ffwd. In addition, this test
+/// checks that the stopwatch can be reset.
+TEST_F(StopwatchTest, multipleMeasurements) {
+    StopwatchMock stopwatch(ref_time_);
+    // The stopwatch shouldn't automatically start. The initial
+    // durations should be set to 0.
+    EXPECT_EQ(0, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(0, stopwatch.getTotalDurationInMs());
+
+    stopwatch.start();
+
+    // Even though the stopwatch is started, the time is still set to
+    // the initial value. The durations should not be affected.
+    EXPECT_EQ(0, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(0, stopwatch.getTotalDurationInMs());
+
+    // Move the time by 10 ms.
+    stopwatch.ffwd(10);
+
+    // It should be possible to retrieve the durations even when the
+    // stopwatch is running.
+    EXPECT_EQ(10, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(10, stopwatch.getTotalDurationInMs());
+
+    // Now stop it and make sure that the same values are returned.
+    stopwatch.stop();
+
+    EXPECT_EQ(10, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(10, stopwatch.getTotalDurationInMs());
+
+    // Start it again, but don't move the time forward yet.
+    stopwatch.start();
+
+    // The new duration should be 0, but the total should be equal to
+    // the previously measured duration.
+    EXPECT_EQ(0, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(10, stopwatch.getTotalDurationInMs());
+
+    // Move time by 5 ms.
+    stopwatch.ffwd(5);
+
+    // New measured duration should be 5 ms. The total should be 15 ms.
+    EXPECT_EQ(5, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(15, stopwatch.getTotalDurationInMs());
+
+    // Stop it again and make sure the values returned are the same.
+    stopwatch.stop();
+
+    EXPECT_EQ(5, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(15, stopwatch.getTotalDurationInMs());
+
+    // Move the time forward while the stopwatch is stopped.
+    stopwatch.ffwd(8);
+
+    // The measured values should not be affected.
+    EXPECT_EQ(5, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(15, stopwatch.getTotalDurationInMs());
+
+    // Stop should be no-op in this case.
+    stopwatch.stop();
+
+    EXPECT_EQ(5, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(15, stopwatch.getTotalDurationInMs());
+
+    // Start the stopwatch again.
+    stopwatch.start();
+
+    // Move time by 3 ms.
+    stopwatch.ffwd(3);
+
+    // Since the stopwatch is running, the measured duration should
+    // get updated again.
+    EXPECT_EQ(3, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(18, stopwatch.getTotalDurationInMs());
+
+    // Move the time by 2 ms.
+    stopwatch.ffwd(2);
+
+    // Start should be no-op in this case.
+    stopwatch.start();
+
+    // But the durations should be updated.
+    EXPECT_EQ(5, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(20, stopwatch.getTotalDurationInMs());
+
+    // Make sure we can reset.
+    stopwatch.reset();
+
+    EXPECT_EQ(0, stopwatch.getLastDurationInMs());
+    EXPECT_EQ(0, stopwatch.getTotalDurationInMs());
+}
+
+// This test checks that the stopwatch works when the real clock is in use.
+TEST_F(StopwatchTest, realTime) {
+    // Initially, the measured time should be 0.
+    Stopwatch stopwatch;
+    EXPECT_EQ(0, stopwatch.getLastMilliseconds());
+    EXPECT_EQ(0, stopwatch.getTotalMilliseconds());
+
+    // Start the stopwatch.
+    stopwatch.start();
+
+    // Sleep for 1 ms. The stopwatch should measure this duration.
+    usleep(1000);
+
+    stopwatch.stop();
+
+    // The measured duration should be greater or equal 1 ms.
+    long current_duration = stopwatch.getLastMilliseconds();
+    EXPECT_GE(current_duration, 1);
+    EXPECT_EQ(current_duration, stopwatch.getTotalMilliseconds());
+
+    // Sleep for another 2 ms while the stopwatch is in the stopped state.
+    usleep(2000);
+
+    // In the stopped state, we should still have old durations measured.
+    EXPECT_EQ(current_duration, stopwatch.getLastMilliseconds());
+    EXPECT_EQ(current_duration, stopwatch.getTotalMilliseconds());
+
+    // Start it again.
+    stopwatch.start();
+
+    // Slee for 1 ms.
+    usleep(1000);
+
+    // The durations should get updated as appropriate.
+    current_duration = stopwatch.getLastMilliseconds();
+    EXPECT_GE(stopwatch.getLastMilliseconds(), 1);
+    EXPECT_GE(stopwatch.getTotalMilliseconds(), 2);
+}
+
+// Make sure that we can obtain the durations as microseconds.
+TEST_F(StopwatchTest, getLastMicroseconds) {
+    Stopwatch stopwatch;
+    stopwatch.start();
+
+    usleep(1000);
+
+    stopwatch.stop();
+
+    long current_duration = stopwatch.getLastMicroseconds();
+    EXPECT_GE(current_duration, 1000);
+    EXPECT_EQ(current_duration, stopwatch.getTotalMicroseconds());
+}
+
+// Make sure that we can use the "autostart" option to start the time
+// measurement in the constructor.
+TEST_F(StopwatchTest, autostart) {
+    Stopwatch stopwatch(true);
+    usleep(1000);
+
+    stopwatch.stop();
+
+    EXPECT_GE(stopwatch.getLastMilliseconds(), 1);
+    EXPECT_EQ(stopwatch.getLastMilliseconds(), stopwatch.getTotalMilliseconds());
+}
+
+// Make sure that the conversion to the loggable string works as expected.
+TEST_F(StopwatchTest, logFormat) {
+    time_duration duration = microseconds(223043);
+    EXPECT_EQ("223.043 ms", StopwatchImpl::logFormat(duration));
+
+    duration = microseconds(1234);
+    EXPECT_EQ("1.234 ms", StopwatchImpl::logFormat(duration));
+
+    duration = microseconds(2000);
+    EXPECT_EQ("2.000 ms", StopwatchImpl::logFormat(duration));
+}
+
+} // end of anonymous namespace