From: Francis Dupont Date: Mon, 10 Dec 2018 19:09:13 +0000 (+0100) Subject: [283-perfdhcp-fix-send-due] Added sending delay statistics X-Git-Tag: 283-perfdhcp-sending-thread_base~1 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=refs%2Fheads%2F283-perfdhcp-fix-send-due;p=thirdparty%2Fkea.git [283-perfdhcp-fix-send-due] Added sending delay statistics --- diff --git a/src/bin/perfdhcp/rate_control.h b/src/bin/perfdhcp/rate_control.h index 5b40395567..59f12b99a3 100644 --- a/src/bin/perfdhcp/rate_control.h +++ b/src/bin/perfdhcp/rate_control.h @@ -57,6 +57,11 @@ public: return (send_due_); } + /// \brief Returns time the last message was sent. + boost::posix_time::ptime getLast() const { + return (last_sent_); + } + /// \brief Returns number of messages to be sent "now". /// /// This function calculates how many messages of the given type should @@ -132,13 +137,6 @@ public: /// and increment the sent counter. void updateSendTime(); -protected: - - /// \brief Convenience function returning current time. - /// - /// \return current time. - static boost::posix_time::ptime currentTime(); - /// \brief Calculates the send due. /// /// This function calculates the send due timestamp using the current time @@ -153,6 +151,13 @@ protected: /// already sent packets. void updateSendDue(); +protected: + + /// \brief Convenience function returning current time. + /// + /// \return current time. + static boost::posix_time::ptime currentTime(); + /// \brief Holds a timestamp when the next message should be sent. boost::posix_time::ptime send_due_; diff --git a/src/bin/perfdhcp/stats_mgr.h b/src/bin/perfdhcp/stats_mgr.h index 5e3181d1cb..371e4cc4b2 100644 --- a/src/bin/perfdhcp/stats_mgr.h +++ b/src/bin/perfdhcp/stats_mgr.h @@ -1,4 +1,4 @@ -// Copyright (C) 2012-2016 Internet Systems Consortium, Inc. ("ISC") +// Copyright (C) 2012-2018 Internet Systems Consortium, Inc. ("ISC") // // This Source Code Form is subject to the terms of the Mozilla Public // License, v. 2.0. If a copy of the MPL was not distributed with this @@ -276,10 +276,14 @@ public: archived_packets_(), archive_enabled_(archive_enabled), drop_time_(drop_time), - min_delay_(std::numeric_limits::max()), - max_delay_(0.), - sum_delay_(0.), - sum_delay_squared_(0.), + min_sent_delay_(std::numeric_limits::max()), + max_sent_delay_(0.), + sum_sent_delay_(0.), + sum_sent_delay_squared_(0.), + min_recv_delay_(std::numeric_limits::max()), + max_recv_delay_(0.), + sum_recv_delay_(0.), + sum_recv_delay_squared_(0.), orphans_(0), collected_(0), unordered_lookup_size_sum_(0), @@ -319,7 +323,48 @@ public: rcvd_packets_.push_back(packet); } - /// \brief Update delay counters. + /// \brief Update send delay counters. + /// + /// Method updates delay counters based on timestamps of + /// due and effective sending. + /// + /// \param due due time. + /// \param effective effective time. + /// \throw isc::Unexpected if failed to calculate timestamps + void updateSentDelays(const boost::posix_time::ptime due, + const boost::posix_time::ptime effective) { + if (due.is_not_a_date_time() || + effective.is_not_a_date_time()) { + isc_throw(Unexpected, + "Bad values sent tp updateSentDelays"); + } + boost::posix_time::time_period period(due, effective); + // We don't bother calculating deltas in nanoseconds. It is much + // more convenient to use seconds instead because we are going to + // sum them up. + double delta = + static_cast(period.length().total_nanoseconds()) / 1e9; + + if (delta < 0) { + // Should happen only in unit tests. Ignore it. + return; + } + + // Record the minimum delay between due and effective send time. + if (delta < min_sent_delay_) { + min_sent_delay_ = delta; + } + // Record the maximum delay between due and effective send time. + if (delta > max_sent_delay_) { + max_sent_delay_ = delta; + } + // Update delay sum and square sum. That will be used to calculate + // mean delays. + sum_sent_delay_ += delta; + sum_sent_delay_squared_ += delta * delta; + } + + /// \brief Update receive delay counters. /// /// Method updates delay counters based on timestamps of /// sent and received packets. @@ -328,8 +373,8 @@ public: /// \param rcvd_packet received packet /// \throw isc::BadValue if sent or received packet is null. /// \throw isc::Unexpected if failed to calculate timestamps - void updateDelays(const boost::shared_ptr& sent_packet, - const boost::shared_ptr& rcvd_packet) { + void updateRecvDelays(const boost::shared_ptr& sent_packet, + const boost::shared_ptr& rcvd_packet) { if (!sent_packet) { isc_throw(BadValue, "Sent packet is null"); } @@ -359,17 +404,17 @@ public: } // Record the minimum delay between sent and received packets. - if (delta < min_delay_) { - min_delay_ = delta; + if (delta < min_recv_delay_) { + min_recv_delay_ = delta; } // Record the maximum delay between sent and received packets. - if (delta > max_delay_) { - max_delay_ = delta; + if (delta > max_recv_delay_) { + max_recv_delay_ = delta; } // Update delay sum and square sum. That will be used to calculate // mean delays. - sum_delay_ += delta; - sum_delay_squared_ += delta * delta; + sum_recv_delay_ += delta; + sum_recv_delay_squared_ += delta * delta; } /// \brief Match received packet with the corresponding sent packet. @@ -534,19 +579,49 @@ public: return(sent_packet); } + /// \brief Return minimum delay between due and effective send. + /// + /// Method returns minimum delay between due and effective send. + /// + /// \return minimum delay in send. + double getMinSentDelay() const { return(min_sent_delay_); } + /// \brief Return minimum delay between sent and received packet. /// /// Method returns minimum delay between sent and received packet. /// /// \return minimum delay between packets. - double getMinDelay() const { return(min_delay_); } + double getMinRecvDelay() const { return(min_recv_delay_); } + + /// \brief Return maximum delay between due and effective send. + /// + /// Method returns maximum delay between due and effective send. + /// + /// \return maximum delay in send. + double getMaxSentDelay() const { return(max_sent_delay_); } /// \brief Return maximum delay between sent and received packet. /// /// Method returns maximum delay between sent and received packet. /// /// \return maximum delay between packets. - double getMaxDelay() const { return(max_delay_); } + double getMaxRecvDelay() const { return(max_recv_delay_); } + + /// \brief Return average sending delay. + /// + /// Method returns average sending delay. If no packets have been + /// sent for this exchange avg delay can't be calculated and + /// thus method throws exception. + /// + /// \throw isc::InvalidOperation if no packets for this exchange + /// have been sent yet. + /// \return average sending delay. + double getAvgSentDelay() const { + if (sent_packets_num_ == 0) { + isc_throw(InvalidOperation, "no packets sent"); + } + return(sum_sent_delay_ / sent_packets_num_); + } /// \brief Return average packet delay. /// @@ -557,11 +632,29 @@ public: /// \throw isc::InvalidOperation if no packets for this exchange /// have been received yet. /// \return average packet delay. - double getAvgDelay() const { + double getAvgRecvDelay() const { if (rcvd_packets_num_ == 0) { isc_throw(InvalidOperation, "no packets received"); } - return(sum_delay_ / rcvd_packets_num_); + return(sum_recv_delay_ / rcvd_packets_num_); + } + + /// \brief Return standard deviation of sending delay. + /// + /// Method returns standard deviation of sending delay. If no + /// packets have been sent for this exchange, the standard + /// deviation can't be calculated and thus method throws + /// exception. + /// + /// \throw isc::InvalidOperation if number of sent packets + /// for the exchange is equal to zero. + /// \return standard deviation of sending delay. + double getStdDevSentDelay() const { + if (sent_packets_num_ == 0) { + isc_throw(InvalidOperation, "no packets sent"); + } + return(sqrt(sum_sent_delay_squared_ / sent_packets_num_ - + getAvgSentDelay() * getAvgSentDelay())); } /// \brief Return standard deviation of packet delay. @@ -574,12 +667,12 @@ public: /// \throw isc::InvalidOperation if number of received packets /// for the exchange is equal to zero. /// \return standard deviation of packet delay. - double getStdDevDelay() const { + double getStdDevRecvDelay() const { if (rcvd_packets_num_ == 0) { isc_throw(InvalidOperation, "no packets received"); } - return(sqrt(sum_delay_squared_ / rcvd_packets_num_ - - getAvgDelay() * getAvgDelay())); + return(sqrt(sum_recv_delay_squared_ / rcvd_packets_num_ - + getAvgRecvDelay() * getAvgRecvDelay())); } /// \brief Return number of orphan packets. @@ -688,6 +781,31 @@ public: // << "orphans: " << getOrphans() << endl; } + /// \brief Print sending delay statistics. + /// + /// Method prints sending delay statistics. Statistics + /// includes minimum sending delay, maximum sending delay, average + /// sending delay and standard deviation of delays. Sending delay + /// is a duration between the due time and the effective time in + /// sending queries. + void printSentStats() const { + using namespace std; + try { + cout << fixed << setprecision(3) + << "min sending delay: " << getMinSentDelay() * 1e3 + << " ms" << endl + << "avg sending delay: " << getAvgSentDelay() * 1e3 + << " ms" << endl + << "max sending delay: " << getMaxSentDelay() * 1e3 + << " ms" << endl + << "std deviation: " << getStdDevSentDelay() * 1e3 + << " ms" << endl; + } catch (const Exception&) { + cout << "Sending delay summary unavailable! No packets sent." + << endl; + } + } + /// \brief Print round trip time packets statistics. /// /// Method prints round trip time packets statistics. Statistics @@ -699,11 +817,14 @@ public: using namespace std; try { cout << fixed << setprecision(3) - << "min delay: " << getMinDelay() * 1e3 << " ms" << endl - << "avg delay: " << getAvgDelay() * 1e3 << " ms" << endl - << "max delay: " << getMaxDelay() * 1e3 << " ms" << endl - << "std deviation: " << getStdDevDelay() * 1e3 << " ms" + << "min delay: " << getMinRecvDelay() * 1e3 << " ms" + << endl + << "avg delay: " << getAvgRecvDelay() * 1e3 << " ms" + << endl + << "max delay: " << getMaxRecvDelay() * 1e3 << " ms" << endl + << "std deviation: " << getStdDevRecvDelay() * 1e3 + << " ms" << endl << "collected packets: " << getCollectedNum() << endl; } catch (const Exception&) { cout << "Delay summary unavailable! No packets received." << endl; @@ -790,7 +911,7 @@ public: /// \param it iterator pointing to packet to be erased. /// \return iterator pointing to packet following erased /// packet or sent_packets_.end() if packet not found. - PktListIterator eraseSent(const PktListIterator it) { + PktListIterator eraseSent(const PktListIterator it) { if (archive_enabled_) { // We don't want to keep list of all sent packets // because it will affect packet lookup performance. @@ -837,14 +958,19 @@ public: /// before packet is assumed dropped. double drop_time_; - double min_delay_; ///< Minimum delay between sent - ///< and received packets. - double max_delay_; ///< Maximum delay between sent - ///< and received packets. - double sum_delay_; ///< Sum of delays between sent - ///< and received packets. - double sum_delay_squared_; ///< Squared sum of delays between - ///< sent and received packets. + double min_sent_delay_; ///< Minimum delay in sending. + double max_sent_delay_; ///< Maximum delay in sending. + double sum_sent_delay_; ///< Sum of delays in sending. + double sum_sent_delay_squared_; ///< Squared sum of delays in sending. + + double min_recv_delay_; ///< Minimum delay between sent + ///< and received packets. + double max_recv_delay_; ///< Maximum delay between sent + ///< and received packets. + double sum_recv_delay_; ///< Sum of delays between sent + ///< and received packets. + double sum_recv_delay_squared_; ///< Squared sum of delays between + ///< sent and received packets. uint64_t orphans_; ///< Number of orphan received packets. @@ -1010,6 +1136,17 @@ public: xchg_stats->appendSent(packet); } + /// \brief Register sent times. + /// + /// \param due due time. + /// \param effective effective time. + void passSentTimes(const ExchangeType xchg_type, + const boost::posix_time::ptime due, + const boost::posix_time::ptime effective) { + ExchangeStatsPtr xchg_stats = getExchangeStats(xchg_type); + xchg_stats->updateSentDelays(due, effective); + } + /// \brief Add new received packet and match with sent packet. /// /// Method adds new packet to the list of received packets. It @@ -1031,7 +1168,7 @@ public: = xchg_stats->matchPackets(packet); if (sent_packet) { - xchg_stats->updateDelays(sent_packet, packet); + xchg_stats->updateRecvDelays(sent_packet, packet); if (archive_enabled_) { xchg_stats->appendRcvd(packet); } @@ -1039,6 +1176,19 @@ public: return(sent_packet); } + /// \brief Return minimum delay between due and effective send. + /// + /// Method returns minimum delay between due and effective send + /// for specified exchange type. + /// + /// \param xchg_type exchange type. + /// \throw isc::BadValue if invalid exchange type specified. + /// \return minimum delay in send. + double getMinSentDelay(const ExchangeType xchg_type) const { + ExchangeStatsPtr xchg_stats = getExchangeStats(xchg_type); + return(xchg_stats->getMinSentDelay()); + } + /// \brief Return minimum delay between sent and received packet. /// /// Method returns minimum delay between sent and received packet @@ -1047,9 +1197,22 @@ public: /// \param xchg_type exchange type. /// \throw isc::BadValue if invalid exchange type specified. /// \return minimum delay between packets. - double getMinDelay(const ExchangeType xchg_type) const { + double getMinRecvDelay(const ExchangeType xchg_type) const { ExchangeStatsPtr xchg_stats = getExchangeStats(xchg_type); - return(xchg_stats->getMinDelay()); + return(xchg_stats->getMinRecvDelay()); + } + + /// \brief Return maximum delay between due and effective send. + /// + /// Method returns maximum delay between due and effective send + /// for specified exchange type. + /// + /// \param xchg_type exchange type. + /// \throw isc::BadValue if invalid exchange type specified. + /// \return maximum delay in send. + double getMaxSentDelay(const ExchangeType xchg_type) const { + ExchangeStatsPtr xchg_stats = getExchangeStats(xchg_type); + return(xchg_stats->getMaxSentDelay()); } /// \brief Return maximum delay between sent and received packet. @@ -1060,9 +1223,20 @@ public: /// \param xchg_type exchange type. /// \throw isc::BadValue if invalid exchange type specified. /// \return maximum delay between packets. - double getMaxDelay(const ExchangeType xchg_type) const { + double getMaxRecvDelay(const ExchangeType xchg_type) const { ExchangeStatsPtr xchg_stats = getExchangeStats(xchg_type); - return(xchg_stats->getMaxDelay()); + return(xchg_stats->getMaxRecvDelay()); + } + + /// \brief Return average sending delay. + /// + /// Method returns average sending delay for specified + /// exchange type. + /// + /// \return average sending delay. + double getAvgSentDelay(const ExchangeType xchg_type) const { + ExchangeStatsPtr xchg_stats = getExchangeStats(xchg_type); + return(xchg_stats->getAvgSentDelay()); } /// \brief Return average packet delay. @@ -1071,9 +1245,20 @@ public: /// exchange type. /// /// \return average packet delay. - double getAvgDelay(const ExchangeType xchg_type) const { + double getAvgRecvDelay(const ExchangeType xchg_type) const { + ExchangeStatsPtr xchg_stats = getExchangeStats(xchg_type); + return(xchg_stats->getAvgRecvDelay()); + } + + /// \brief Return standard deviation of sending delay. + /// + /// Method returns standard deviation of sending delay + /// for specified exchange type. + /// + /// \return standard deviation of sending delay. + double getStdDevSentDelay(const ExchangeType xchg_type) const { ExchangeStatsPtr xchg_stats = getExchangeStats(xchg_type); - return(xchg_stats->getAvgDelay()); + return(xchg_stats->getStdDevSentDelay()); } /// \brief Return standard deviation of packet delay. @@ -1082,9 +1267,9 @@ public: /// for specified exchange type. /// /// \return standard deviation of packet delay. - double getStdDevDelay(const ExchangeType xchg_type) const { + double getStdDevRecvDelay(const ExchangeType xchg_type) const { ExchangeStatsPtr xchg_stats = getExchangeStats(xchg_type); - return(xchg_stats->getStdDevDelay()); + return(xchg_stats->getStdDevRecvDelay()); } /// \brief Return number of orphan packets. @@ -1252,6 +1437,10 @@ public: /// - average packets delay, /// - maximum packets delay, /// - standard deviation of packets delay. + /// - minimum sending delay, + /// - average sending delay, + /// - maximum sending delay + /// - standard deviation of sending delay. /// /// \throw isc::InvalidOperation if no exchange type added to /// track statistics. @@ -1270,6 +1459,8 @@ public: std::cout << std::endl; xchg_stats->printRTTStats(); std::cout << std::endl; + xchg_stats->printSentStats(); + std::cout << std::endl; } } diff --git a/src/bin/perfdhcp/test_control.cc b/src/bin/perfdhcp/test_control.cc index f27fc27090..972eaec5b8 100644 --- a/src/bin/perfdhcp/test_control.cc +++ b/src/bin/perfdhcp/test_control.cc @@ -941,6 +941,10 @@ TestControl::sendPackets(const TestControlSocket& socket, const bool preload /* = false */) { CommandOptions& options = CommandOptions::instance(); for (uint64_t i = packets_num; i > 0; --i) { + // A packet was sent so get the next packet due time. + if (packets_num > i) { + basic_rate_control_.updateSendDue(); + } if (options.getIpVersion() == 4) { // No template packets means that no -T option was specified. // We have to build packets ourselves. @@ -1729,6 +1733,9 @@ TestControl::sendDiscover4(const TestControlSocket& socket, "hasn't been initialized"); } stats_mgr4_->passSentPacket(StatsMgr4::XCHG_DO, pkt4); + stats_mgr4_->passSentTimes(StatsMgr4::XCHG_DO, + basic_rate_control_.getDue(), + basic_rate_control_.getLast()); } saveFirstPacket(pkt4); } @@ -1783,6 +1790,9 @@ TestControl::sendDiscover4(const TestControlSocket& socket, // Update packet stats. stats_mgr4_->passSentPacket(StatsMgr4::XCHG_DO, boost::static_pointer_cast(pkt4)); + stats_mgr4_->passSentTimes(StatsMgr4::XCHG_DO, + basic_rate_control_.getDue(), + basic_rate_control_.getLast()); } saveFirstPacket(pkt4); } @@ -2259,6 +2269,9 @@ TestControl::sendSolicit6(const TestControlSocket& socket, "hasn't been initialized"); } stats_mgr6_->passSentPacket(StatsMgr6::XCHG_SA, pkt6); + stats_mgr6_->passSentTimes(StatsMgr6::XCHG_SA, + basic_rate_control_.getDue(), + basic_rate_control_.getLast()); } saveFirstPacket(pkt6); @@ -2311,6 +2324,9 @@ TestControl::sendSolicit6(const TestControlSocket& socket, } // Update packet stats. stats_mgr6_->passSentPacket(StatsMgr6::XCHG_SA, pkt6); + stats_mgr6_->passSentTimes(StatsMgr6::XCHG_SA, + basic_rate_control_.getDue(), + basic_rate_control_.getLast()); } saveFirstPacket(pkt6); } diff --git a/src/bin/perfdhcp/tests/stats_mgr_unittest.cc b/src/bin/perfdhcp/tests/stats_mgr_unittest.cc index 37f0361a03..5f9bff8765 100644 --- a/src/bin/perfdhcp/tests/stats_mgr_unittest.cc +++ b/src/bin/perfdhcp/tests/stats_mgr_unittest.cc @@ -1,4 +1,4 @@ -// Copyright (C) 2012-2017 Internet Systems Consortium, Inc. ("ISC") +// Copyright (C) 2012-2018 Internet Systems Consortium, Inc. ("ISC") // // This Source Code Form is subject to the terms of the Mozilla Public // License, v. 2.0. If a copy of the MPL was not distributed with this @@ -266,9 +266,9 @@ TEST_F(StatsMgrTest, Constructor) { stats_mgr->addExchangeStats(StatsMgr4::XCHG_DO); EXPECT_DOUBLE_EQ( std::numeric_limits::max(), - stats_mgr->getMinDelay(StatsMgr4::XCHG_DO) + stats_mgr->getMinRecvDelay(StatsMgr4::XCHG_DO) ); - EXPECT_DOUBLE_EQ(0, stats_mgr->getMaxDelay(StatsMgr4::XCHG_DO)); + EXPECT_DOUBLE_EQ(0, stats_mgr->getMaxRecvDelay(StatsMgr4::XCHG_DO)); EXPECT_EQ(0, stats_mgr->getOrphans(StatsMgr4::XCHG_DO)); EXPECT_EQ(0, stats_mgr->getOrderedLookups(StatsMgr4::XCHG_DO)); EXPECT_EQ(0, stats_mgr->getUnorderedLookups(StatsMgr4::XCHG_DO)); @@ -276,8 +276,8 @@ TEST_F(StatsMgrTest, Constructor) { EXPECT_EQ(0, stats_mgr->getRcvdPacketsNum(StatsMgr4::XCHG_DO)); EXPECT_EQ(0, stats_mgr->getCollectedNum(StatsMgr4::XCHG_DO)); - EXPECT_THROW(stats_mgr->getAvgDelay(StatsMgr4::XCHG_DO), InvalidOperation); - EXPECT_THROW(stats_mgr->getStdDevDelay(StatsMgr4::XCHG_DO), + EXPECT_THROW(stats_mgr->getAvgRecvDelay(StatsMgr4::XCHG_DO), InvalidOperation); + EXPECT_THROW(stats_mgr->getStdDevRecvDelay(StatsMgr4::XCHG_DO), InvalidOperation); EXPECT_THROW(stats_mgr->getAvgUnorderedLookupSetSize(StatsMgr4::XCHG_DO), InvalidOperation); @@ -490,16 +490,16 @@ TEST_F(StatsMgrTest, Delays) { // Initially min delay is equal to MAX_DOUBLE. After first packets // are passed, it is expected to set to actual value. - EXPECT_LT(stats_mgr->getMinDelay(StatsMgr4::XCHG_DO), + EXPECT_LT(stats_mgr->getMinRecvDelay(StatsMgr4::XCHG_DO), std::numeric_limits::max()); - EXPECT_GT(stats_mgr->getMinDelay(StatsMgr4::XCHG_DO), 1); + EXPECT_GT(stats_mgr->getMinRecvDelay(StatsMgr4::XCHG_DO), 1); // Max delay is supposed to the same value as minimum // or maximum delay. - EXPECT_GT(stats_mgr->getMaxDelay(StatsMgr4::XCHG_DO), 1); + EXPECT_GT(stats_mgr->getMaxRecvDelay(StatsMgr4::XCHG_DO), 1); // Delay sums are now the same as minimum or maximum delay. - EXPECT_GT(stats_mgr->getAvgDelay(StatsMgr4::XCHG_DO), 1); + EXPECT_GT(stats_mgr->getAvgRecvDelay(StatsMgr4::XCHG_DO), 1); // Simulate another DISCOVER-OFFER exchange with delay between // sent and received packets. Delay is now shorter than earlier @@ -507,7 +507,7 @@ TEST_F(StatsMgrTest, Delays) { const unsigned int delay2 = 1; passDOPacketsWithDelay(stats_mgr, delay2, common_transid + 1); // Standard deviation is expected to be non-zero. - EXPECT_GT(stats_mgr->getStdDevDelay(StatsMgr4::XCHG_DO), 0); + EXPECT_GT(stats_mgr->getStdDevRecvDelay(StatsMgr4::XCHG_DO), 0); } TEST_F(StatsMgrTest, CustomCounters) {