Commit 63b9881a authored by Utkarsh Ayachit's avatar Utkarsh Ayachit

Add ability to generate temporal summary.

When --shortlog is used instead of --log as a command line argument,
oscillators app now generate a summary for time/memory stats over time
rather than reporting values for each timestep seperately.
parent 30fcbce0
......@@ -110,7 +110,8 @@ int main(int argc, char** argv)
>> Option('j', "jobs", threads, "number of threads to use")
;
bool sync = ops >> Present("sync", "synchronize after each time step");
bool log = ops >> Present("log", "generate time and memory usage log");
bool log = ops >> Present("log", "generate full time and memory usage log");
bool shortlog = ops >> Present("shortlog", "generate a summary time and memory usage log");
std::string infn;
if ( ops >> Present('h', "help", "show help") ||
......@@ -125,7 +126,8 @@ int main(int argc, char** argv)
return 1;
}
timer::SetLogging(log);
timer::SetLogging(log || shortlog);
timer::SetTrackSummariesOverTime(shortlog);
timer::MarkStartEvent("oscillators::initialize");
Oscillators oscillators;
......
......@@ -7,6 +7,7 @@
#include <cstring>
#include <sstream>
#include <stdint.h>
#include <strings.h>
#include <map>
#include <list>
......@@ -63,29 +64,88 @@ namespace impl
struct Event
{
enum
{
MIN=0,
MAX=1,
SUM=2
};
std::string Name;
double Duration;
uint64_t VmHWM;
Event() : Duration(-1.0), VmHWM(0) {}
std::list<Event> SubEvents;
double Duration[3];
uint64_t VmHWM[3];
int Count;
Event() : Count(0)
{
bzero(this->Duration, sizeof(double)*3);
bzero(this->VmHWM, sizeof(uint64_t)*3);
}
/// Add other into this.
void Add(const Event& other)
{
this->Count += other.Count;
this->Duration[MIN] = std::min(this->Duration[MIN], other.Duration[MIN]);
this->Duration[MAX] = std::max(this->Duration[MAX], other.Duration[MAX]);
this->Duration[SUM] += other.Duration[SUM];
this->VmHWM[MIN] = std::min(this->VmHWM[MIN], other.VmHWM[MIN]);
this->VmHWM[MAX] = std::max(this->VmHWM[MAX], other.VmHWM[MAX]);
this->VmHWM[SUM] += other.VmHWM[SUM];
if (this->SubEvents.size() == other.SubEvents.size())
{
std::list<Event>::iterator me_iter = this->SubEvents.begin();
std::list<Event>::const_iterator other_iter = other.SubEvents.begin();
for (; me_iter != this->SubEvents.end() && other_iter != other.SubEvents.end();
++me_iter, ++other_iter)
{
me_iter->Add(*other_iter);
}
}
}
bool IsValid() const
{ return this->Duration > -1.0; }
{ return this->Count > 0; }
void PrintLog(std::ostream& stream, Indent indent) const
{
stream << indent << this->Name.c_str() << " = "
<< this->Duration << " s, " << this->VmHWM << " kB" << endl;
if (this->Count == 0) { return; }
if (this->Count == 1)
{
stream << indent << this->Name.c_str() << " = ("
<< this->Duration[MIN] << "s), (" << this->VmHWM[MIN] << "kB)" << endl;
}
else
{
stream << indent << this->Name.c_str() << " = "
<< "( min: " << this->Duration[MIN]
<< "s, max: " << this->Duration[MAX]
<< "s, avg:" << this->Duration[SUM] / this->Count << "s ), "
<< "( min: " << this->VmHWM[MIN]
<< "kB, max: " << this->VmHWM[MAX]
<< "kB, avg: " << this->VmHWM[SUM] / this->Count << "kB )" << endl;
}
for (std::list<Event>::const_iterator iter = this->SubEvents.begin();
iter != this->SubEvents.end(); ++iter)
{
iter->PrintLog(stream, indent.GetNextIndent());
}
}
std::list<Event> SubEvents;
};
static std::list<Event> GlobalEvents;
static std::list<Event> Mark;
static bool LoggingEnabled = true;
static bool TrackSummariesOverTime = true;
static int ActiveTimeStep = -1;
static double ActiveTime = 0.0;
void PrintLog(std::ostream& stream, Indent indent)
{
......@@ -109,6 +169,18 @@ bool GetLogging()
return impl::LoggingEnabled;
}
//-----------------------------------------------------------------------------
void SetTrackSummariesOverTime(bool val)
{
impl::TrackSummariesOverTime = val;
}
//-----------------------------------------------------------------------------
bool GetTrackSummariesOverTime()
{
return impl::TrackSummariesOverTime;
}
//-----------------------------------------------------------------------------
void MarkStartEvent(const char* eventname)
{
......@@ -116,7 +188,8 @@ void MarkStartEvent(const char* eventname)
{
impl::Event evt;
evt.Name = eventname? eventname : "(none)";
evt.Duration = impl::get_mark();
evt.Duration[0] = evt.Duration[1] = evt.Duration[2] = impl::get_mark();
evt.Count = 1;
impl::Mark.push_back(evt);
}
......@@ -138,8 +211,8 @@ void MarkEndEvent(const char* eventname)
abort();
}
evt.Duration = impl::get_mark() - evt.Duration;
evt.VmHWM = impl::get_vmhwm();
evt.Duration[0] = evt.Duration[1] = evt.Duration[2] = impl::get_mark() - evt.Duration[0];
evt.VmHWM[0] = evt.VmHWM[1] = evt.VmHWM[2] = impl::get_vmhwm();
impl::Mark.pop_back();
if (impl::Mark.empty())
......@@ -154,27 +227,64 @@ void MarkEndEvent(const char* eventname)
}
//-----------------------------------------------------------------------------
void MarkStartTimeStep(int timestep, double Duration)
void MarkStartTimeStep(int timestep, double time)
{
impl::ActiveTimeStep = timestep;
impl::ActiveTime = time;
std::ostringstream mk;
mk << "timestep: " << impl::ActiveTimeStep << " time: " << impl::ActiveTime;
MarkStartEvent(mk.str().c_str());
}
//-----------------------------------------------------------------------------
void MarkEndTimeStep()
{
std::ostringstream mk;
mk << "timestep: " << impl::ActiveTimeStep << " time: " << impl::ActiveTime;
MarkEndEvent(mk.str().c_str());
// Try to merge with previous timestep.
std::list<impl::Event> &activeEventList =
impl::Mark.empty()? impl::GlobalEvents :
impl::Mark.back().SubEvents;
if (activeEventList.size() >= 2 && impl::TrackSummariesOverTime)
{
std::list<impl::Event>::reverse_iterator iter = activeEventList.rbegin();
impl::Event& cur = *iter;
iter++;
impl::Event& prev = *iter;
if (strncmp(prev.Name.c_str(), "timestep:", 9) == 0)
{
prev.Add(cur);
std::ostringstream summary_label;
summary_label << "timestep: (summary over " << prev.Count << " timesteps)";
prev.Name = summary_label.str();
activeEventList.pop_back();
}
}
impl::ActiveTimeStep = -1;
impl::ActiveTime = 0.0;
}
//-----------------------------------------------------------------------------
void PrintLog(std::ostream& stream)
{
stream
<< "=================================================================\n"
<< " Time/Memory log :\n"
<< " -----------------\n"
<< " Prints duration and VmHWM at the end of each step.\n"
<< "-----------------------------------------------------------------\n";
impl::PrintLog(stream, impl::Indent());
stream
<< "=================================================================\n";
if (impl::LoggingEnabled)
{
stream
<< "=================================================================\n"
<< " Time/Memory log :\n"
<< " -----------------\n"
<< " Prints duration and VmHWM at the end of each step.\n"
<< "-----------------------------------------------------------------\n";
impl::PrintLog(stream, impl::Indent());
stream
<< "=================================================================\n";
}
}
}
......
......@@ -5,12 +5,25 @@
namespace timer
{
/// @brief Enable/Disable logging (default is enabled).
/// @brief Enable/Disable logging (default is `true`).
void SetLogging(bool val);
/// @brief Get whether logging is enabled.
bool GetLogging();
/// @brief Enable/Disable tracking temporal summaries (default is `false`).
///
/// For runs where the event markers are consistent across timesteps
/// i.e. they occur in same order and exactly as many across different
/// timesteps, one can use this to track a summary instead of full values
/// for duration and memory used. This not only keeps the memory overhead
/// for long runs low, but also make it easier to process the generated
/// output.
void SetTrackSummariesOverTime(bool val);
/// @brief Return whether summaries are tracked over time.
bool GetTrackSummariesOverTime();
/// @brief Log start of a log-able event.
///
/// This marks the beginning of a event that must be logged.
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment