From 87f505cae5ac1f560e34b6c81ca4738670a27909 Mon Sep 17 00:00:00 2001
From: Giovanni Bussi <giovanni.bussi@gmail.com>
Date: Mon, 25 Mar 2013 10:35:32 +0100
Subject: [PATCH] Added detailed timers for action

Can be activated with DEBUG DETAILED_TIMERS, and provide action by action
timing. Useful for optimization
---
 src/core/PlumedMain.cpp | 37 +++++++++++++++++++++++++++++++++----
 src/core/PlumedMain.h   |  2 ++
 src/generic/Debug.cpp   |  5 +++++
 3 files changed, 40 insertions(+), 4 deletions(-)

diff --git a/src/core/PlumedMain.cpp b/src/core/PlumedMain.cpp
index 05abd7a1d..6fa798ea0 100644
--- a/src/core/PlumedMain.cpp
+++ b/src/core/PlumedMain.cpp
@@ -66,7 +66,8 @@ PlumedMain::PlumedMain():
   restart(false),
   stopFlag(NULL),
   stopNow(false),
-  novirial(false)
+  novirial(false),
+  detailedTimers(false)
 {
   log.link(comm);
   log.setLinePrefix("PLUMED: ");
@@ -522,8 +523,15 @@ void PlumedMain::justCalculate(){
   stopwatch.start("4 Calculating (forward loop)");
   bias=0.0;
 
+  int iaction=0;
 // calculate the active actions in order (assuming *backward* dependence)
   for(ActionSet::iterator p=actionSet.begin();p!=actionSet.end();++p){
+    std::string actionNumberLabel;
+    if(detailedTimers){
+      Tools::convert(iaction,actionNumberLabel);
+      actionNumberLabel="4A "+actionNumberLabel+" "+(*p)->getLabel();
+      stopwatch.start(actionNumberLabel);
+    }
     ActionWithValue*av=dynamic_cast<ActionWithValue*>(*p);
     ActionAtomistic*aa=dynamic_cast<ActionAtomistic*>(*p);
     {
@@ -543,6 +551,9 @@ void PlumedMain::justCalculate(){
       ActionWithVirtualAtom*avv=dynamic_cast<ActionWithVirtualAtom*>(*p);
       if(avv)avv->setGradientsIfNeeded();	
     }
+
+    if(detailedTimers) stopwatch.stop(actionNumberLabel);
+    iaction++;
   }
   stopwatch.stop("4 Calculating (forward loop)");
 }
@@ -550,22 +561,40 @@ void PlumedMain::justCalculate(){
 void PlumedMain::justApply(){
   
   if(!active)return;
+  int iaction=0;
   stopwatch.start("5 Applying (backward loop)");
 // apply them in reverse order
   for(ActionSet::reverse_iterator p=actionSet.rbegin();p!=actionSet.rend();++p){
-    if((*p)->isActive()) (*p)->apply();
-    ActionAtomistic*a=dynamic_cast<ActionAtomistic*>(*p);
+    if((*p)->isActive()){
+
+      std::string actionNumberLabel;
+      if(detailedTimers){
+        Tools::convert(iaction,actionNumberLabel);
+        actionNumberLabel="5A "+actionNumberLabel+" "+(*p)->getLabel();
+        stopwatch.start(actionNumberLabel);
+      }
+
+      (*p)->apply();
+      ActionAtomistic*a=dynamic_cast<ActionAtomistic*>(*p);
 // still ActionAtomistic has a special treatment, since they may need to add forces on atoms
-    if(a) if(a->isActive()) a->applyForces();
+      if(a) a->applyForces();
+
+      if(detailedTimers) stopwatch.stop(actionNumberLabel);
+    }
+    iaction++;
   }
 
 // 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");
 
+  if(detailedTimers) stopwatch.start("5C Update");
 // update step (for statistics, etc)
   for(ActionSet::iterator p=actionSet.begin();p!=actionSet.end();++p){
     if((*p)->isActive()) (*p)->update();
   }
+  if(detailedTimers) stopwatch.stop("5C Update");
 // Check that no action has told the calculation to stop
   if(stopNow){
      if(stopFlag) (*stopFlag)=1;
diff --git a/src/core/PlumedMain.h b/src/core/PlumedMain.h
index a9177d05f..bd3c972d1 100644
--- a/src/core/PlumedMain.h
+++ b/src/core/PlumedMain.h
@@ -135,6 +135,8 @@ public:
 /// Flag to switch off virial calculation (for debug and MD codes with no barostat)
   bool novirial;
 
+/// Flag to switch on detailed timers
+  bool detailedTimers;
 
 /// Add a citation, returning a string containing the reference number, something like "[10]"
   std::string cite(const std::string&);
diff --git a/src/generic/Debug.cpp b/src/generic/Debug.cpp
index 2dd2964c4..5fdcfbc84 100644
--- a/src/generic/Debug.cpp
+++ b/src/generic/Debug.cpp
@@ -49,6 +49,7 @@ class Debug:
   bool logActivity;
   bool logRequestedAtoms;
   bool novirial;
+  bool detailedTimers;
 public:
   Debug(const ActionOptions&ao);
 /// Register all the relevant keywords for the action  
@@ -66,6 +67,7 @@ void Debug::registerKeywords( Keywords& keys ){
   keys.addFlag("logActivity",false,"write in the log which actions are inactive and which are inactive");
   keys.addFlag("logRequestedAtoms",false,"write in the log which atoms have been requested at a given time");
   keys.addFlag("NOVIRIAL",false,"switch off the virial contribution for the entirity of the simulation");
+  keys.addFlag("DETAILED_TIMERS",false,"switch on detailed timers");
 }
 
 Debug::Debug(const ActionOptions&ao):
@@ -81,6 +83,9 @@ novirial(false){
   parseFlag("NOVIRIAL",novirial);
   if(novirial) log.printf("  Switching off virial contribution\n");
   if(novirial) plumed.novirial=true;
+  parseFlag("DETAILED_TIMERS",detailedTimers);
+  if(detailedTimers) log.printf("  Detailed timing on\n");
+  plumed.detailedTimers=true;
   checkRead();
 }
 
-- 
GitLab