[#2780] Report FLQ startup time in the logs

diff --git a/src/lib/dhcpsrv/dhcpsrv_messages.mes b/src/lib/dhcpsrv/dhcpsrv_messages.mes
index 3dd04687f57bf8e6f256e45cf4b28121c16ff832..b5b7834128ca2db45fcdf83b8578024faccd6f86 100644 (file)
--- a/src/lib/dhcpsrv/dhcpsrv_messages.mes
+++ b/src/lib/dhcpsrv/dhcpsrv_messages.mes
@@ -86,18 +86,20 @@ This informational message is issued when the server begins building a queue
 of free address leases for the given subnet. It can take a considerable amount
 of time, depending on the size of the address pools.
 
-% DHCPSRV_CFGMGR_FLQ_POPULATE_FREE_ADDRESS_LEASES_DONE populating free address leases for the FLQ allocator in subnet %1 completed
+% DHCPSRV_CFGMGR_FLQ_POPULATE_FREE_ADDRESS_LEASES_DONE populating free address leases for the FLQ allocator in subnet %1 completed in %2
 This informational message is issued when the server ends building a queue
-of free address leases for a given subnet.
+of free address leases for a given subnet. The second argument logs the
+duration.
 
 % DHCPSRV_CFGMGR_FLQ_POPULATE_FREE_PREFIX_LEASES populating free prefix leases for the FLQ allocator in subnet %1; it can take a while!
 This informational message is issued when the server begins building a queue
 of free leases for the given subnet. It can take a considerable amount of
 time, depending on the size of the delegated prefix pools.
 
-% DHCPSRV_CFGMGR_FLQ_POPULATE_FREE_PREFIX_LEASES_DONE populating free prefix leases for the FLQ allocator in subnet %1 completed
+% DHCPSRV_CFGMGR_FLQ_POPULATE_FREE_PREFIX_LEASES_DONE populating free prefix leases for the FLQ allocator in subnet %1 completed in %2
 This informational message is issued when the server ends building a queue
-of free prefix leases for a given subnet.
+of free prefix leases for a given subnet. The second argument logs the
+duration.
 
 % DHCPSRV_CFGMGR_IPV4_RESERVATIONS_NON_UNIQUE_IGNORED ignoring "ip-reservations-unique" setting because at least one of the host database backends does not support non-unique IP reservations in a subnet
 This warning message is issued when the server failed to use the new setting

diff --git a/src/lib/dhcpsrv/flq_allocator.cc b/src/lib/dhcpsrv/flq_allocator.cc
index 8a5535124c973cbf90118983b6ba4a1e563b73b1..5bf07e7090f716c82aee360690c7f60ffcb214f3 100644 (file)
--- a/src/lib/dhcpsrv/flq_allocator.cc
+++ b/src/lib/dhcpsrv/flq_allocator.cc
@@ -12,6 +12,7 @@
 #include <dhcpsrv/ip_range_permutation.h>
 #include <dhcpsrv/lease_mgr_factory.h>
 #include <dhcpsrv/subnet.h>
+#include <util/stopwatch.h>
 #include <unordered_set>
 
 using namespace isc::asiolink;
@@ -184,6 +185,8 @@ FreeLeaseQueueAllocator::populateFreeAddressLeases(const LeaseCollectionType& le
     LOG_INFO(dhcpsrv_logger, DHCPSRV_CFGMGR_FLQ_POPULATE_FREE_ADDRESS_LEASES)
         .arg(subnet->toText());
 
+    Stopwatch stopwatch;
+
     // Let's iterate over the lease queue and index them with the
     // unordered_set. Also, elminate the expired leases and those
     // in the expired-reclaimed state.
@@ -211,8 +214,12 @@ FreeLeaseQueueAllocator::populateFreeAddressLeases(const LeaseCollectionType& le
             }
         }
     }
+
+    stopwatch.stop();
+
     LOG_INFO(dhcpsrv_logger, DHCPSRV_CFGMGR_FLQ_POPULATE_FREE_ADDRESS_LEASES_DONE)
-        .arg(subnet->toText());
+        .arg(subnet->toText())
+        .arg(stopwatch.logFormatLastDuration());
 }
 
 void
@@ -221,6 +228,8 @@ FreeLeaseQueueAllocator::populateFreePrefixDelegationLeases(const Lease6Collecti
     LOG_INFO(dhcpsrv_logger, DHCPSRV_CFGMGR_FLQ_POPULATE_FREE_PREFIX_LEASES)
         .arg(subnet->toText());
 
+    Stopwatch stopwatch;
+
     // Let's iterate over the lease queue and index them with the
     // unordered_set. Also, elminate the expired leases and those
     // in the expired-reclaimed state.
@@ -252,8 +261,12 @@ FreeLeaseQueueAllocator::populateFreePrefixDelegationLeases(const Lease6Collecti
             }
         }
     }
+
+    stopwatch.stop();
+
     LOG_INFO(dhcpsrv_logger, DHCPSRV_CFGMGR_FLQ_POPULATE_FREE_PREFIX_LEASES_DONE)
-        .arg(subnet->toText());
+        .arg(subnet->toText())
+        .arg(stopwatch.logFormatLastDuration());
 }
 
 SubnetFreeLeaseQueueAllocationStatePtr

diff --git a/src/lib/dhcpsrv/ip_range_permutation.h b/src/lib/dhcpsrv/ip_range_permutation.h
index 0a8c417d19a106c5e646c6f8dfb97373cec19120..93cbb096f228f0bac9be65c668ef665a524f2568 100644 (file)
--- a/src/lib/dhcpsrv/ip_range_permutation.h
+++ b/src/lib/dhcpsrv/ip_range_permutation.h
@@ -12,7 +12,7 @@
 
 #include <boost/shared_ptr.hpp>
 
-#include <map>
+#include <unordered_map>
 #include <random>
 
 namespace isc {
@@ -128,7 +128,7 @@ private:
     /// Keeps the current permutation state. The state associates the
     /// swapped IP addresses or delegated prefixes with their positions in
     /// the permutation.
-    std::map<uint64_t, asiolink::IOAddress> state_;
+    std::unordered_map<uint64_t, asiolink::IOAddress> state_;
 
     /// Indicates if the addresses or delegated prefixes are exhausted.
     bool done_;

diff --git a/src/lib/util/stopwatch_impl.cc b/src/lib/util/stopwatch_impl.cc
index 8f6bc653dd63f18f941fa5cf90636c18f481aca5..6b23d570184204a7c5e729bd55e72c9345755af8 100644 (file)
--- a/src/lib/util/stopwatch_impl.cc
+++ b/src/lib/util/stopwatch_impl.cc
@@ -81,9 +81,15 @@ StopwatchImpl::getTotalDuration() const {
 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";
+    if (duration.total_seconds() > 0) {
+        s << duration.total_seconds() << "."
+          << std::setfill('0') << std::setw(2) << (duration.total_milliseconds()/10 % 100)
+          << " s";
+    } else {
+        s << duration.total_milliseconds() << ".";
+        s << std::setfill('0') << std::setw(3) << (duration.total_microseconds() % 1000)
+          << " ms";
+    }
     return (s.str());
 }
 

diff --git a/src/lib/util/stopwatch_impl.h b/src/lib/util/stopwatch_impl.h
index 3c1ee9cfb4627247ecbfb2354f674fed3a207ef1..07623523353a9c9f2ca86cc290e0e38ce335b556 100644 (file)
--- a/src/lib/util/stopwatch_impl.h
+++ b/src/lib/util/stopwatch_impl.h
@@ -77,10 +77,6 @@ public:
     /// @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.

diff --git a/src/lib/util/tests/stopwatch_unittest.cc b/src/lib/util/tests/stopwatch_unittest.cc
index 28d6c99989e4c4bcafb52960fa472f51a2332478..96b8743f30881c6312fa3dc6428ea33c3e3b6b54 100644 (file)
--- a/src/lib/util/tests/stopwatch_unittest.cc
+++ b/src/lib/util/tests/stopwatch_unittest.cc
@@ -296,6 +296,12 @@ TEST_F(StopwatchTest, logFormat) {
 
     duration = microseconds(2000);
     EXPECT_EQ("2.000 ms", StopwatchImpl::logFormat(duration));
+
+    duration = milliseconds(2100);
+    EXPECT_EQ("2.10 s", StopwatchImpl::logFormat(duration));
+
+    duration = milliseconds(3123);
+    EXPECT_EQ("3.12 s", StopwatchImpl::logFormat(duration));
 }
 
 } // end of anonymous namespace