From 147da862f231f24f7912dc2a173c048fab39f541 Mon Sep 17 00:00:00 2001 From: Marcin Siodelski Date: Mon, 20 Mar 2023 21:44:08 +0100 Subject: [PATCH] [#2780] Report FLQ startup time in the logs --- src/lib/dhcpsrv/dhcpsrv_messages.mes | 10 ++++++---- src/lib/dhcpsrv/flq_allocator.cc | 17 +++++++++++++++-- src/lib/dhcpsrv/ip_range_permutation.h | 4 ++-- src/lib/util/stopwatch_impl.cc | 12 +++++++++--- src/lib/util/stopwatch_impl.h | 4 ---- src/lib/util/tests/stopwatch_unittest.cc | 6 ++++++ 6 files changed, 38 insertions(+), 15 deletions(-) diff --git a/src/lib/dhcpsrv/dhcpsrv_messages.mes b/src/lib/dhcpsrv/dhcpsrv_messages.mes index 3dd04687f5..b5b7834128 100644 --- 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 8a5535124c..5bf07e7090 100644 --- a/src/lib/dhcpsrv/flq_allocator.cc +++ b/src/lib/dhcpsrv/flq_allocator.cc @@ -12,6 +12,7 @@ #include #include #include +#include #include 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 0a8c417d19..93cbb096f2 100644 --- a/src/lib/dhcpsrv/ip_range_permutation.h +++ b/src/lib/dhcpsrv/ip_range_permutation.h @@ -12,7 +12,7 @@ #include -#include +#include #include 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 state_; + std::unordered_map 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 8f6bc653dd..6b23d57018 100644 --- 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 3c1ee9cfb4..0762352335 100644 --- 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 28d6c99989..96b8743f30 100644 --- 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 -- 2.47.2