ShowProgress burnin

This commit is contained in:
Peter Barnes
2020-06-02 15:50:09 +00:00
parent c316c0de8c
commit 0c4ace3b18
6 changed files with 335 additions and 117 deletions

View File

@@ -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 ();
}

View File

@@ -25,25 +25,31 @@
* ns3::ShowProgress implementation.
*/
#include <iomanip>
#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 <iomanip>
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

View File

@@ -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 <gjcarneiro@gmail.com>,
* 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

View File

@@ -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. <pdbarnes@llnl.gov>
*/
#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

View File

@@ -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. <pdbarnes@llnl.gov>
*/
#ifndef SYSTEM_WALL_CLOCK_TIMESTAMP_H
#define SYSTEM_WALL_CLOCK_TIMESTAMP_H
/**
* \file
* \ingroup system
* ns3::SystemWallClockTimestamp declaration.
*/
#include <string>
#include <ctime> // 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 */

View File

@@ -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',