From e558166db36040adbff88c94d4c970985934424a Mon Sep 17 00:00:00 2001 From: Giovanni Bussi <giovanni.bussi@gmail.com> Date: Mon, 30 Apr 2018 08:59:16 +0200 Subject: [PATCH] Improved StopWatch class Changed so that start()/stop()/pause() return *this. This allows things like sw.start().stop() Stopwatch can be initialized with the reference to a log. In this case, it logs itself at destruction, provided the log is open. Added Stopwatch::Handler class It allows writing exception safe stopwatches which automatically stop when an exception is caught. Removed unnecessary start/stop in PlumedMain constructor. Simplified interface: Use default arguments instead of multiple functions. --- regtest/basic/rt0/plumed.dat | 2 + src/core/PlumedMain.cpp | 60 ++++---- src/core/PlumedMain.h | 9 +- src/function/FuncSumHills.cpp | 10 +- src/tools/Stopwatch.cpp | 44 ++---- src/tools/Stopwatch.h | 279 +++++++++++++++++++++++++++++++--- 6 files changed, 315 insertions(+), 89 deletions(-) diff --git a/regtest/basic/rt0/plumed.dat b/regtest/basic/rt0/plumed.dat index b82c0096e..93cc1fba5 100644 --- a/regtest/basic/rt0/plumed.dat +++ b/regtest/basic/rt0/plumed.dat @@ -31,6 +31,8 @@ PRINT ... ## DUMPDERIVATIVES ARG=rmsd3,rmsd3n FILE=check3 ## DUMPDERIVATIVES ARG=rmsd4,rmsd4n FILE=check4 +DEBUG DETAILED_TIMERS + ENDPLUMED text here should be ignored diff --git a/src/core/PlumedMain.cpp b/src/core/PlumedMain.cpp index ee7740b29..65191791f 100644 --- a/src/core/PlumedMain.cpp +++ b/src/core/PlumedMain.cpp @@ -64,6 +64,8 @@ const std::unordered_map<std::string, int> & plumedMainWordMap() { PlumedMain::PlumedMain(): initialized(false), +// automatically write on log in destructor + stopwatch_fwd(log), step(0), active(false), mydatafetcher(DataFetchingObject::create(sizeof(double),*this)), @@ -82,14 +84,10 @@ PlumedMain::PlumedMain(): { log.link(comm); log.setLinePrefix("PLUMED: "); - stopwatch.start(); - stopwatch.pause(); } +// destructor needed to delete forward declarated objects PlumedMain::~PlumedMain() { - stopwatch.start(); - stopwatch.stop(); - if(initialized) log<<stopwatch; } ///////////////////////////////////////////////////////////// @@ -104,7 +102,7 @@ void PlumedMain::cmd(const std::string & word,void*val) { try { - stopwatch.start(); + auto ss=stopwatch.startPause(); std::vector<std::string> words=Tools::getWords(word); unsigned nw=words.size(); @@ -464,7 +462,6 @@ void PlumedMain::cmd(const std::string & word,void*val) { break; } } - stopwatch.pause(); } catch (Exception &e) { if(log.isOpen()) { @@ -600,7 +597,8 @@ void PlumedMain::prepareCalc() { // traverse them in this order: void PlumedMain::prepareDependencies() { - stopwatch.start("1 Prepare dependencies"); +// Stopwatch is stopped when sw goes out of scope + auto sw=stopwatch.startStop("1 Prepare dependencies"); // activate all the actions which are on step // activation is recursive and enables also the dependencies @@ -629,15 +627,14 @@ void PlumedMain::prepareDependencies() { } } - stopwatch.stop("1 Prepare dependencies"); } void PlumedMain::shareData() { // atom positions are shared (but only if there is something to do) if(!active)return; - stopwatch.start("2 Sharing data"); +// Stopwatch is stopped when sw goes out of scope + auto sw=stopwatch.startStop("2 Sharing data"); if(atoms.getNatoms()>0) atoms.share(); - stopwatch.stop("2 Sharing data"); } void PlumedMain::performCalcNoUpdate() { @@ -656,14 +653,15 @@ void PlumedMain::performCalc() { void PlumedMain::waitData() { if(!active)return; - stopwatch.start("3 Waiting for data"); +// Stopwatch is stopped when sw goes out of scope + auto sw=stopwatch.startStop("3 Waiting for data"); if(atoms.getNatoms()>0) atoms.wait(); - stopwatch.stop("3 Waiting for data"); } void PlumedMain::justCalculate() { if(!active)return; - stopwatch.start("4 Calculating (forward loop)"); +// Stopwatch is stopped when sw goes out of scope + auto sw=stopwatch.startStop("4 Calculating (forward loop)"); bias=0.0; work=0.0; @@ -672,11 +670,13 @@ void PlumedMain::justCalculate() { for(const auto & pp : actionSet) { Action* p(pp.get()); if(p->isActive()) { - std::string actionNumberLabel; +// Stopwatch is stopped when sw goes out of scope. +// We explicitly declare a Stopwatch::Handler here to allow for conditional initialization. + Stopwatch::Handler sw; if(detailedTimers) { + std::string actionNumberLabel; Tools::convert(iaction,actionNumberLabel); - actionNumberLabel="4A "+actionNumberLabel+" "+p->getLabel(); - stopwatch.start(actionNumberLabel); + sw=stopwatch.startStop("4A "+actionNumberLabel+" "+p->getLabel()); } ActionWithValue*av=dynamic_cast<ActionWithValue*>(p); ActionAtomistic*aa=dynamic_cast<ActionAtomistic*>(p); @@ -696,11 +696,9 @@ void PlumedMain::justCalculate() { if(av)av->setGradientsIfNeeded(); ActionWithVirtualAtom*avv=dynamic_cast<ActionWithVirtualAtom*>(p); if(avv)avv->setGradientsIfNeeded(); - if(detailedTimers) stopwatch.stop(actionNumberLabel); } iaction++; } - stopwatch.stop("4 Calculating (forward loop)"); } void PlumedMain::justApply() { @@ -711,17 +709,20 @@ void PlumedMain::justApply() { void PlumedMain::backwardPropagate() { if(!active)return; int iaction=0; - stopwatch.start("5 Applying (backward loop)"); +// Stopwatch is stopped when sw goes out of scope + auto sw=stopwatch.startStop("5 Applying (backward loop)"); // apply them in reverse order for(auto pp=actionSet.rbegin(); pp!=actionSet.rend(); ++pp) { const auto & p(pp->get()); if(p->isActive()) { - std::string actionNumberLabel; +// Stopwatch is stopped when sw goes out of scope. +// We explicitly declare a Stopwatch::Handler here to allow for conditional initialization. + Stopwatch::Handler sw; if(detailedTimers) { + std::string actionNumberLabel; Tools::convert(iaction,actionNumberLabel); - actionNumberLabel="5A "+actionNumberLabel+" "+p->getLabel(); - stopwatch.start(actionNumberLabel); + sw=stopwatch.startStop("5A "+actionNumberLabel+" "+p->getLabel()); } p->apply(); @@ -729,22 +730,24 @@ void PlumedMain::backwardPropagate() { // still ActionAtomistic has a special treatment, since they may need to add forces on atoms if(a) a->applyForces(); - if(detailedTimers) stopwatch.stop(actionNumberLabel); } iaction++; } +// Stopwatch is stopped when sw goes out of scope. +// We explicitly declare a Stopwatch::Handler here to allow for conditional initialization. + Stopwatch::Handler sw1; + if(detailedTimers) sw1=stopwatch.startStop("5B Update forces"); // this is updating the MD copy of the forces - if(detailedTimers) stopwatch.start("5B Update forces"); if(atoms.getNatoms()>0) atoms.updateForces(); - if(detailedTimers) stopwatch.stop("5B Update forces"); - stopwatch.stop("5 Applying (backward loop)"); } void PlumedMain::update() { if(!active)return; - stopwatch.start("6 Update"); +// Stopwatch is stopped when sw goes out of scope + auto sw=stopwatch.startStop("6 Update"); + // update step (for statistics, etc) updateFlags.push(true); for(const auto & p : actionSet) { @@ -767,7 +770,6 @@ void PlumedMain::update() { log.flush(); for(const auto & p : actionSet) p->fflush(); } - stopwatch.stop("6 Update"); } void PlumedMain::load(const std::string& ss) { diff --git a/src/core/PlumedMain.h b/src/core/PlumedMain.h index d4f2d30e8..d3f350a90 100644 --- a/src/core/PlumedMain.h +++ b/src/core/PlumedMain.h @@ -100,10 +100,6 @@ private: std::unique_ptr<WithCmd> cltool; -/// Forward declaration. - ForwardDecl<Stopwatch> stopwatch_fwd; - Stopwatch& stopwatch=*stopwatch_fwd; - std::unique_ptr<WithCmd> grex; /// Flag to avoid double initialization bool initialized; @@ -115,6 +111,11 @@ private: /// Log stream Log& log=*log_fwd; +/// Forward declaration. +/// Should be placed after log since its constructor takes a log reference as an argument. + ForwardDecl<Stopwatch> stopwatch_fwd; + Stopwatch& stopwatch=*stopwatch_fwd; + /// Forward declaration. ForwardDecl<Citations> citations_fwd; /// tools/Citations.holder diff --git a/src/function/FuncSumHills.cpp b/src/function/FuncSumHills.cpp index 2d78b73c4..28d18ccc6 100644 --- a/src/function/FuncSumHills.cpp +++ b/src/function/FuncSumHills.cpp @@ -500,9 +500,11 @@ FuncSumHills::FuncSumHills(const ActionOptions&ao): if(integratehills) hillsHandler.reset(new FilesHandler(hillsFiles,parallelread,*this, log)); if(integratehisto) histoHandler.reset(new FilesHandler(histoFiles,parallelread,*this, log)); - Stopwatch sw; +// Stopwatch is logged when it goes out of scope + Stopwatch sw(log); - sw.start("0 Summing hills"); +// Stopwatch is stopped when swh goes out of scope + auto swh=sw.startStop("0 Summing hills"); // read a number of hills and put in the bias representation int nfiles=0; @@ -610,10 +612,6 @@ FuncSumHills::FuncSumHills(const ActionOptions&ao): nfiles++; } - sw.stop("0 Summing hills"); - - log<<sw; - return; } // just an initialization but you need to do something on the fly?: need to connect with a metad run and its grid representation diff --git a/src/tools/Stopwatch.cpp b/src/tools/Stopwatch.cpp index 9169e8640..e7e652aca 100644 --- a/src/tools/Stopwatch.cpp +++ b/src/tools/Stopwatch.cpp @@ -22,6 +22,7 @@ #include "Stopwatch.h" #include "Exception.h" +#include "Log.h" #include <cstdio> #include <iostream> @@ -37,41 +38,18 @@ std::ostream& operator<<(std::ostream&os,const Stopwatch&sw) { return sw.log(os); } -void Stopwatch::Watch::start() { - running++; - lastStart=std::chrono::high_resolution_clock::now(); -} - -void Stopwatch::Watch::stop() { - pause(); - cycles++; - total+=lap; - if(lap>max)max=lap; - if(min>lap || cycles==1)min=lap; - lap=0; -} - -void Stopwatch::Watch::pause() { - plumed_assert(running>0); - running--; - if(running!=0) return; - auto t=std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now()-lastStart); - lap+=t.count(); -} - -void Stopwatch::start(const std::string & name) { - watches[name].start(); -} - -void Stopwatch::stop(const std::string & name) { - watches[name].stop(); -} - -void Stopwatch::pause(const std::string & name) { - watches[name].pause(); +Stopwatch::~Stopwatch() { + if(mylog && mylog->isOpen()) { +// Make sure paused watches are stopped. +// this is necessary e.g. to make sure the main watch present in PlumedMain +// is stopped correctly. + for(auto & w : watches) { + if(w.second.state==Watch::State::paused) w.second.start().stop(); + } + *mylog << *this; + } } - std::ostream& Stopwatch::log(std::ostream&os)const { char buffer[1000]; buffer[0]=0; diff --git a/src/tools/Stopwatch.h b/src/tools/Stopwatch.h index 7c653e39b..453b20eb4 100644 --- a/src/tools/Stopwatch.h +++ b/src/tools/Stopwatch.h @@ -22,6 +22,7 @@ #ifndef __PLUMED_tools_Stopwatch_h #define __PLUMED_tools_Stopwatch_h +#include "Exception.h" #include <string> #include <unordered_map> #include <iosfwd> @@ -94,55 +95,299 @@ int main(){ \endverbatim +Notice that as of PLUMED 2.5 it is possible to use a slightly modified +interface that allow for exception safety. In pratice, +one can replace a pair of calls to Stopwatch::start() and Stopwatch::stop() +with a single call to Stopwatch::startStop(). This call will return an object +that, when goes out of scope, will stop the timer. + +\notice The exception safety interace is highly recommended since it allows +to make sure that stopwatches are started and stopped consistently. + +For instance the following +code +\verbatim + { + sw.start("A"); + // any code + sw.stop("A"); + } +\endverbatim +can be replaced with +\verbatim + { + auto sww=sw.startStop("A"); + // any code + + // stopwatch is stopped when sww goes out of scope + } +\endverbatim +Similarly, Stopwatch::startPause() can be used to replace a pair of +Stopwatch::start() and Stopwatch::pause(). + +The older syntax (explicitly calling `Stopwatch::start()` and `Stopwatch::pause()`) is still +allowed for backward compatibility. + +Notice that the returned object is of type `Stopwatch::Handler`. +You might be willing to explicitly declare a `Stopwatch::Handler` (instead of using `auto`) +when you want to conditionally start the stopwatch. For instance: +\verbatim + { + Stopwatch::Handler handler; + if(you_want_to_time_this) handler=sw.startStop(); + ... do something ... + } + // in case it was started, the stopwatch will stop here, at the end of the block + // in case it was not started, nothing will happen +\endverbatim + +A `Stopwatch::Handler` can not be copied but it can be moved (it behaves like a unique_ptr). +Moving it explicitly allows one to transfer it to another `Stopwatch::Handler` with a different scope. +For instance, in case you want to conditionally stop the stopwatch you might use something like this: +\verbatim + { + Stopwatch::Handler handler; + if(you_want_to_time_this) handler=sw.startStop(); + ... do something ... + if(you_want_to_stop_here) auto h2=std::move(handler); + // the previous instruction moves handler to h2 that is then destroyed, stopping the watch + // notice that if the stop was not started it will not stop. + ... do something else ... + } + // in case it is running, the stopwatch will stop here, at the end of the block +\endverbatim + +Finally, notice that in order to write the timers on an output file when the +Stopwatch is destroyed, one can store a reference to a PLMD::Log by passing it +to the Stopwatch constructor. +This will make sure timers are written also in case of a premature end. */ +class Log; + class Stopwatch { +/// Simple function returning an empty string. +/// Used to simplify Stopwatch interface. + static const std::string & emptyString() { + static std::string s; + return s; + } + +public: +/// Forward declaration + class Watch; +/// Auxiliary class for handling exception-safe start/pause and start/stop. + class Handler { + Watch* watch=nullptr; + /// stop (true) or pause (false). + /// might be changed to an enum if clearer. + bool stop=false; + /// Private constructor. + /// This is kept private to avoid misuse. Handler objects should + /// only be created using startPause() or startStop(). + /// stop is required to know if the destructor should stop or pause the watch. + Handler(Watch* watch,bool stop); + /// Allows usage of private constructor + friend class Stopwatch; + public: + /// Default constructor + Handler() = default; + /// Default copy constructor is deleted (not copyable) + Handler(const Handler & handler) = delete; + /// Default copy assignment is deleted (not copyable) + Handler & operator=(const Handler & handler) = delete; + /// Move constructor. + Handler(Handler && handler) noexcept; + /// Move assignemnt. + Handler & operator=(Handler && handler) noexcept; + /// Destructor either stops or pauses the watch + ~Handler(); + }; + /// Class to store a single stopwatch. /// Class Stopwatch contains a collection of them class Watch { - public: +/// Instant in time when Watch was started last time std::chrono::time_point<std::chrono::high_resolution_clock> lastStart; +/// Total accumulated time, in nanoseconds long long int total = 0; +/// Accumulated time for this lap, in nanoseconds long long int lap = 0; +/// Slowest lap so far, in nanoseconds long long int max = 0; +/// Fastest lap so far, in nanoseconds long long int min = 0; +/// Total number of cycles unsigned cycles = 0; +/// count how many times Watch was started (+1) or stopped/paused (-1). unsigned running = 0; - void start(); - void stop(); - void pause(); + enum class State {started, stopped, paused}; +/// keep track of state + State state = State::stopped; +/// Allows access to internal data + friend class Stopwatch; + public: +/// start the watch + Watch & start(); +/// stop the watch + Watch & stop(); +/// pause the watch + Watch & pause(); +/// returns a start-stop handler + Handler startStop(); +/// returns a start-pause handler + Handler startPause(); }; + +private: + +/// Pointer to a log file. +/// If set, the stopwatch is logged in its destructor. + Log*mylog=nullptr; + +/// List of watches. +/// Each watch is labeled with a string. std::unordered_map<std::string,Watch> watches; - std::ostream& log(std::ostream&)const; + +/// Log over stream os. + std::ostream& log(std::ostream& os)const; + public: +// Constructor. + Stopwatch() = default; +// Constructor. +// When destructing, stopwatch is logged. +// Make sure that log survives stopwatch. Typically, it should be declared earlier, in order +// to be destroyed later. + Stopwatch(Log&log): mylog(&log) {} +// Destructor. + ~Stopwatch(); /// Start timer named "name" - void start(const std::string&name); - void start(); + Stopwatch& start(const std::string&name=emptyString()); /// Stop timer named "name" - void stop(const std::string&name); - void stop(); + Stopwatch& stop(const std::string&name=emptyString()); /// Pause timer named "name" - void pause(const std::string&name); - void pause(); + Stopwatch& pause(const std::string&name=emptyString()); /// Dump all timers on an ostream friend std::ostream& operator<<(std::ostream&,const Stopwatch&); +/// Start with exception safety, then stop. +/// Starts the Stopwatch and returns an object that, when goes out of scope, +/// stops the watch. This allows Stopwatch to be started and stopped in +/// an exception safe manner. + Handler startStop(const std::string&name=emptyString()); +/// Start with exception safety, then pause. +/// Starts the Stopwatch and returns an object that, when goes out of scope, +/// pauses the watch. This allows Stopwatch to be started and paused in +/// an exception safe manner. + Handler startPause(const std::string&name=emptyString()); }; inline -void Stopwatch::start() { - start(""); +Stopwatch::Handler::Handler(Watch* watch,bool stop) : + watch(watch), + stop(stop) +{ + watch->start(); +} + +inline +Stopwatch::Handler::~Handler() { + if(watch) { + if(stop) watch->stop(); + else watch->pause(); + } +} + +inline +Stopwatch& Stopwatch::start(const std::string & name) { + watches[name].start(); + return *this; +} + +inline +Stopwatch& Stopwatch::stop(const std::string & name) { + watches[name].stop(); + return *this; +} + +inline +Stopwatch& Stopwatch::pause(const std::string & name) { + watches[name].pause(); + return *this; +} + +inline +Stopwatch::Handler Stopwatch::startStop(const std::string&name) { + return watches[name].startStop(); +} + +inline +Stopwatch::Handler Stopwatch::startPause(const std::string&name) { + return watches[name].startPause(); } inline -void Stopwatch::stop() { - stop(""); +Stopwatch::Handler::Handler(Handler && handler) noexcept : + watch(handler.watch), + stop(handler.stop) +{ + handler.watch=nullptr; } inline -void Stopwatch::pause() { - pause(""); +Stopwatch::Handler & Stopwatch::Handler::operator=(Handler && handler) noexcept { + std::swap(watch,handler.watch); + std::swap(stop,handler.stop); + return *this; } +inline +Stopwatch::Watch & Stopwatch::Watch::start() { + state=State::started; + running++; + lastStart=std::chrono::high_resolution_clock::now(); + return *this; +} + +inline +Stopwatch::Watch & Stopwatch::Watch::stop() { + pause(); + state=State::stopped; + cycles++; + total+=lap; + if(lap>max)max=lap; + if(min>lap || cycles==1)min=lap; + lap=0; + return *this; +} + +inline +Stopwatch::Watch & Stopwatch::Watch::pause() { + state=State::paused; +// In case of an internal bug (non matching start stop within the startStop or startPause interface) +// this assertion could fail in a destructor. +// If this happens, the program should crash immediately + plumed_assert(running>0) << "Non matching start/pause or start/stop commands in a Stopwatch"; + running--; +// notice: with exception safety the following might be converted to a plain error. +// I leave it like this for now: + if(running!=0) return *this; + auto t=std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now()-lastStart); + lap+=t.count(); + return *this; +} + +inline +Stopwatch::Handler Stopwatch::Watch::startStop() { + return Handler( this,true ); +} + +inline +Stopwatch::Handler Stopwatch::Watch::startPause() { + return Handler( this,false ); +} + + } -- GitLab