diff --git a/src/core/examples/sample-show-progress.cc b/src/core/examples/sample-show-progress.cc index 54bed86cd..59099d6ad 100644 --- a/src/core/examples/sample-show-progress.cc +++ b/src/core/examples/sample-show-progress.cc @@ -44,45 +44,6 @@ NS_LOG_COMPONENT_DEFINE ("SampleShowProgress"); namespace { -/** - * Utility class to record the difference between to wall-clock times. - */ -class Timestamp -{ -public: - /** Constructor */ - Timestamp () : - last (0), - diff (0) - { - stamp (); - } - - /** Record the current wall-clock time and delta since the last stamp(). */ - void stamp () - { - time_t seconds = time (NULL); - diff = seconds - last; - last = seconds; - } - - /** - * Get the last time stamp as a string. - * \return The last time stamp. - */ - std::string string () - { - std::string now = ctime ( &last ); - now.resize (now.length () - 1); // trim trailing newline - return now; - } - - time_t last; /**< The last time stamp. */ - time_t diff; /**< Difference between the two previous time stamps. */ - -}; // class Timestamp - - /** * Execute a function periodically, * which takes more or less time to run. @@ -181,20 +142,7 @@ main (int argc, char ** argv) ShowProgress spinner (interval); spinner.SetVerbose (verbose); - Timestamp ts; - ts.stamp (); - - std::cout << std::endl; - std::cout << "Start wall clock: " << ts.string () - << " (" << ts.last << ")" - << std::endl; - Simulator::Run (); - - ts.stamp (); - std::cout << "Elapsed wall clock: " << ts.diff << "s" << std::endl; - - Simulator::Destroy (); } diff --git a/src/core/model/show-progress.cc b/src/core/model/show-progress.cc index eb96d90f7..f7f2a204c 100644 --- a/src/core/model/show-progress.cc +++ b/src/core/model/show-progress.cc @@ -25,25 +25,31 @@ * ns3::ShowProgress implementation. */ -#include - +#include "show-progress.h" #include "event-id.h" #include "log.h" #include "nstime.h" #include "simulator.h" -#include "singleton.h" -#include "show-progress.h" +#include + namespace ns3 { NS_LOG_COMPONENT_DEFINE ("ShowProgress"); +/* static */ +const int64x64_t ShowProgress::HYSTERESIS = 1.414; +/* static */ +const int64x64_t ShowProgress::MAXGAIN = 2.0; + ShowProgress::ShowProgress (const Time interval /* = Seconds (1.0) */, std::ostream & os /* = std::cout */) : m_timer (), + m_stamp (), + m_elapsed (), m_interval (interval), - m_vtime (Seconds (1.0)), + m_vtime (Time (1)), m_event (), m_eventCount (0), m_printer (DefaultTimePrinter), @@ -52,16 +58,29 @@ ShowProgress::ShowProgress (const Time interval /* = Seconds (1.0) */, m_repCount (0) { NS_LOG_FUNCTION (this << interval); + ScheduleCheckProgress (); Start (); } + +ShowProgress::~ShowProgress (void) +{ + Stop (); +} + + void ShowProgress::SetInterval (const Time interval) { NS_LOG_FUNCTION (this << interval); const int64x64_t ratio = interval / m_interval; m_interval = interval; - m_vtime = m_vtime * ratio; + // If we aren't at the initial value assume we have a reasonable + // update time m_vtime, so we should rescale it + if (m_vtime > Time (1)) + { + m_vtime = m_vtime * ratio; + } Simulator::Cancel (m_event); Start (); @@ -88,41 +107,77 @@ ShowProgress::SetStream (std::ostream & os) } void -ShowProgress::Start (void) +ShowProgress::ScheduleCheckProgress (void) { NS_LOG_FUNCTION (this); - m_event = Simulator::Schedule (m_vtime, &ShowProgress::Feedback, this); + m_event = Simulator::Schedule (m_vtime, &ShowProgress::CheckProgress, this); m_timer.Start (); -} // ShowProgress::Start +} // ShowProgress::ScheduleCheckProgress void -ShowProgress::Feedback (void) +ShowProgress::GiveFeedback (uint64_t nEvents, int64x64_t ratio, int64x64_t speed) +{ + // Save stream state + auto precision = m_os->precision (); + auto flags = m_os->flags (); + + m_os->setf (std::ios::fixed, std:: ios::floatfield); + + if (m_verbose) + { + (*m_os) << std::right << std::setw (5) << m_repCount << std::left + << (ratio > (1.0 / HYSTERESIS) ? "-->" : " ") + << std::setprecision (9) + << " [del: " << m_elapsed.As (Time::S) + << "/ int: " << m_interval.As (Time::S) + << " = rat: " << ratio + << (ratio > HYSTERESIS ? " dn" : + (ratio < 1.0 / HYSTERESIS ? " up" : " --")) + << ", vt: " << m_vtime.As (Time::S) << "] "; + } + + // Print the current time + (*m_printer)(*m_os); + + (*m_os) << " (" + << std::setprecision (3) << std::setw (8) << speed.GetDouble () << "x real time) " + << nEvents << " events processed" + << std::endl + << std::flush; + + // Restore stream state + m_os->precision (precision); + m_os->flags (flags); + +} // ShowProgress::GiveFeedback + +void +ShowProgress::CheckProgress (void) { // Get elapsed wall clock time - Time elapsed = MilliSeconds (m_timer.End ()); - NS_LOG_FUNCTION (this << elapsed); + m_elapsed += MilliSeconds (m_timer.End ()); + NS_LOG_FUNCTION (this << m_elapsed); // Don't do anything unless the elapsed time is positive. - if (elapsed <= Time (0)) + if (m_elapsed <= Time (0)) { m_vtime = m_vtime * MAXGAIN; - Start (); + ++m_repCount; + ScheduleCheckProgress (); return; } // Speed: how fast are we compared to real time - const int64x64_t speed = m_vtime / elapsed; + const int64x64_t speed = m_vtime / m_elapsed; // Ratio: how much real time did we use, // compared to reporting interval target - const int64x64_t ratio = elapsed / m_interval; + const int64x64_t ratio = m_elapsed / m_interval; // Elapsed event count uint64_t events = Simulator::GetEventCount (); uint64_t nEvents = events - m_eventCount; - m_eventCount = events; - /** * \internal Update algorithm * @@ -145,11 +200,11 @@ ShowProgress::Feedback (void) ratio | vtime update | | - | *= MAXGAIN + | /= MAXGAIN | - MAXGAIN -|-------------- *= min (ratio, MAXGAIN) + MAXGAIN -|-------------- /= min (ratio, MAXGAIN) | - | *= ratio + | /= ratio | HYSTERESIS -|============================================= | @@ -161,62 +216,81 @@ ShowProgress::Feedback (void) | 1/ HYSTERESIS -|============================================== | - | *= ratio + | *= 1 / ratio | - 1/ MAXGAIN -|--------------- *= max (ratio, 1/ MAXGAIN) + 1/ MAXGAIN -|--------------- *= min (1 / ratio, MAXGAIN) | - | *= 1/MAXGAIN + | *= MAXGAIN | \endverbatim * * As indicated, when ratio is outside the hysteresis band * it amounts to multiplying \c m_vtime by the min/max of the ratio * with the appropriate MAXGAIN factor. + * + * Finally, some experimentation suggests we further dampen + * movement between HYSTERESIS and MAXGAIN, so we only apply + * half the ratio. This reduces "hunting" for a stable update + * period. + * + * \todo Evaluate if simple exponential averaging would be + * more effective, simpler. */ if (ratio > HYSTERESIS) { - m_vtime = m_vtime / std::min (ratio, MAXGAIN); + int64x64_t f = 1 + (ratio - 1) / 2; + if (ratio > MAXGAIN) + { + f = MAXGAIN; + } + + m_vtime = m_vtime / f; } else if (ratio < 1.0 / HYSTERESIS) { - m_vtime = m_vtime / std::max (ratio, 1.0 / MAXGAIN); + int64x64_t f = 1 + (1 / ratio - 1)/2; + if (1 / ratio > MAXGAIN) + { + f = MAXGAIN; + } + m_vtime = m_vtime * f; } - // Save stream state - auto precision = m_os->precision (); - auto flags = m_os->flags (); - - m_os->setf (std::ios::fixed, std:: ios::floatfield); - - if (m_verbose) + // Only give feedback if ratio is at least as big as 1/HYSTERESIS + if (ratio > (1.0 / HYSTERESIS)) { - (*m_os) << m_repCount - << " [del: " << elapsed.As (Time::S) - << "/ int: " << m_interval.As (Time::S) - << " = rat: " << ratio - << (ratio > HYSTERESIS ? " up" : - (ratio < 1.0 / HYSTERESIS ? " dn" : " --")) - << ", vt: " << m_vtime.As (Time::S) << "] "; + GiveFeedback (nEvents, ratio, speed); + m_elapsed = Time (0); + m_eventCount = events; } - m_repCount++; - - // Print the current time - (*m_printer)(*m_os); - - (*m_os) << " (" - << std::setprecision (3) << std::setw (8) << speed.GetDouble () << "x real time) " - << nEvents << " events processed" - << std::endl - << std::flush; - - // Restore stream state - m_os->precision (precision); - m_os->flags (flags); - + else + { + NS_LOG_LOGIC ("skipping update: " << ratio); + // enable this line for debugging, with --verbose + // GiveFeedback (nEvents, ratio, speed); + } + ++m_repCount; + // And do it again - Start (); + ScheduleCheckProgress (); -} // ShowProgress::Feedback +} // ShowProgress::CheckProgress +void +ShowProgress::Start (void) +{ + m_stamp.Stamp (); + (*m_os) << "Start wall clock: " << m_stamp.ToString () + << std::endl; +} // ShowProgress::Start + +void +ShowProgress::Stop (void) +{ + m_stamp.Stamp (); + (*m_os) << "End wall clock: " << m_stamp.ToString () + << "\nElapsed wall clock: " << m_stamp.GetInterval () << "s" + << std::endl; +} // ShowProgress::Stop } // namespace ns3 diff --git a/src/core/model/show-progress.h b/src/core/model/show-progress.h index 744d1bd97..3b851447b 100644 --- a/src/core/model/show-progress.h +++ b/src/core/model/show-progress.h @@ -34,6 +34,7 @@ #include "event-id.h" #include "nstime.h" #include "system-wall-clock-ms.h" +#include "system-wall-clock-timestamp.h" #include "time-printer.h" namespace ns3 { @@ -64,6 +65,21 @@ namespace ns3 { * } * \endcode * + * This generates output similar to the following: + * + * \code + * Start wall clock: Tue May 19 10:24:07 2020 + * +17.179869183s ( 4.937x real time) 29559 events processed + * +25.769803775s ( 4.965x real time) 45179 events processed + * +51.539607551s ( 8.810x real time) 49421 events processed + * +90.324463739s ( 7.607x real time) 58021 events processed + * +129.770882188s ( 7.576x real time) 53850 events processed + * +170.958751090s ( 8.321x real time) 56473 events processed + * +194.339562435s ( 12.776x real time) 30957 events processed + * End wall clock: Tue May 19 10:24:23 2020 + * Elapsed wall clock: 16s + * \endcode + * * Based on a python version by Gustavo Carneiro , * as released here: * http://mailman.isi.edu/pipermail/ns-developers/2009-January/005201.html @@ -79,6 +95,9 @@ public: ShowProgress (const Time interval = Seconds (1.0), std::ostream & os = std::cout); + /** Destructor. */ + ~ShowProgress (void); + /** * Set the target update interval, in wallclock time. * \param [in] interval The target wallclock interval to show progress. @@ -101,9 +120,6 @@ public: */ void SetStream (std::ostream & os); - /** Start the progress timer. */ - void Start (void); - /** * Set verbose mode to print real and virtual time intervals. * @@ -112,21 +128,52 @@ public: void SetVerbose (bool verbose); private: - /** Show execution progress. */ - void Feedback (void); + + /** + * Start the elapsed wallclock timestamp and print the start time. + * This is triggered by the constructor. + */ + void Start (void); + + /** + * Stop the elapsed wallclock timestamp and print the total elapsed time. + * This is triggered by the destructor. + */ + void Stop (void); + + /** + * Schedule the next CheckProgress. + */ + void ScheduleCheckProgress (void); + + /** + * Check on execution progress. + * This function is executed periodically, updates the internal + * state on rate of progress, and decides if it's time to generate + * output. + */ + void CheckProgress (void); + + /** + * Show execution progress. + * This function actually generates output, when directed by CheckProgress(). + */ + void GiveFeedback (uint64_t nEvents, int64x64_t ratio, int64x64_t speed); /** * Hysteresis factor. * \see Feedback() */ - const int64x64_t HYSTERESIS = 1.2; + static const int64x64_t HYSTERESIS; /** * Maximum growth factor. * \see Feedback() */ - const int64x64_t MAXGAIN = 2.0; + static const int64x64_t MAXGAIN; SystemWallClockMs m_timer; //!< Wallclock timer + SystemWallClockTimestamp m_stamp; //!< Elapsed wallclock time. + Time m_elapsed; //!< Total elapsed wallclock time since last update. Time m_interval; //!< The target update interval, in wallclock time Time m_vtime; //!< The virtual time interval. EventId m_event; //!< The next progress event. @@ -135,7 +182,7 @@ private: TimePrinter m_printer; //!< The TimePrinter to use std::ostream *m_os; //!< The output stream to use. bool m_verbose; //!< Verbose mode flag - uint64_t m_repCount; //!< Count of progress lines printed + uint64_t m_repCount; //!< Number of CheckProgress events }; // class ShowProgress diff --git a/src/core/model/system-wall-clock-timestamp.cc b/src/core/model/system-wall-clock-timestamp.cc new file mode 100644 index 000000000..02241625a --- /dev/null +++ b/src/core/model/system-wall-clock-timestamp.cc @@ -0,0 +1,69 @@ +/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ +/* + * Copyright (c) 2020 Lawrence Livermore National Laboratory + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License version 2 as + * published by the Free Software Foundation; + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program; if not, write to the Free Software + * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA + * + * Author: Peter D. Barnes, Jr. + */ + +#include "system-wall-clock-timestamp.h" + +/** + * \file + * \ingroup system + * ns3::SystemWallClockTimestamp implementation. + */ + +namespace ns3 { + +SystemWallClockTimestamp::SystemWallClockTimestamp (void) + : m_last (0), + m_diff (0) +{ + Stamp (); +} + +void +SystemWallClockTimestamp::Stamp (void) +{ + std::time_t seconds = std::time (NULL); + m_diff = seconds - m_last; + m_last = seconds; +} + +std::string +SystemWallClockTimestamp::ToString (void) const +{ + std::string now = std::ctime ( &m_last ); + now.resize (now.length () - 1); // trim trailing newline + return now; +} + +std::time_t +SystemWallClockTimestamp::GetLast (void) const +{ + return m_last; +} + +std::time_t +SystemWallClockTimestamp::GetInterval (void) const +{ + return m_diff; +} + + + +} // namespace ns3 + diff --git a/src/core/model/system-wall-clock-timestamp.h b/src/core/model/system-wall-clock-timestamp.h new file mode 100644 index 000000000..c579d7c05 --- /dev/null +++ b/src/core/model/system-wall-clock-timestamp.h @@ -0,0 +1,78 @@ +/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ +/* + * Copyright (c) 2020 Lawrence Livermore National Laboratory + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License version 2 as + * published by the Free Software Foundation; + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program; if not, write to the Free Software + * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA + * + * Author: Peter D. Barnes, Jr. + */ + +#ifndef SYSTEM_WALL_CLOCK_TIMESTAMP_H +#define SYSTEM_WALL_CLOCK_TIMESTAMP_H + +/** + * \file + * \ingroup system + * ns3::SystemWallClockTimestamp declaration. + */ + +#include +#include // ctime, time_t + + +namespace ns3 { + +/** + * Utility class to record the difference between two wall-clock times. + */ +class SystemWallClockTimestamp +{ +public: + /** Constructor */ + SystemWallClockTimestamp (void); + + /** Record the current wall-clock time and delta since the last stamp(). */ + void Stamp (void); + + /** + * Get the last time stamp as a string. + * \return The last time stamp. + */ + std::string ToString (void) const; + + /** + * Get the last recorded raw value. + * \returns The last time stamp recorded. + */ + std::time_t GetLast (void) const; + + /** + * Get the last recorded interval. + * \returns The interval between the last two time stamps. + */ + std::time_t GetInterval (void) const; + +private: + + /** The last time stamp. */ + std::time_t m_last; + + /** Difference between the two previous time stamps. */ + std::time_t m_diff; + +}; // class SystemWallClockTimestamp + +} // namespace ns3 + +#endif /* SYSTEM_WALL_CLOCK_TIMESTAMP_H */ diff --git a/src/core/wscript b/src/core/wscript index d40ea512d..f33dfd679 100644 --- a/src/core/wscript +++ b/src/core/wscript @@ -213,6 +213,7 @@ def build(bld): 'model/node-printer.cc', 'model/time-printer.cc', 'model/show-progress.cc', + 'model/system-wall-clock-timestamp.cc', ] if (bld.env['ENABLE_EXAMPLES']): @@ -270,6 +271,7 @@ def build(bld): 'model/synchronizer.h', 'model/make-event.h', 'model/system-wall-clock-ms.h', + 'model/system-wall-clock-timestamp.h', 'model/empty.h', 'model/callback.h', 'model/object-base.h',