Changeset 22551 for issm/trunk-jpl/src/c/classes/Profiler.cpp

Timestamp:

03/16/18 15:48:35 (7 years ago)

Author:

Mathieu Morlighem

Message:

CHG: revised how profiling is done and added solver time to see how much time we spend solver linear systems

File:

• issm/trunk-jpl/src/c/classes/Profiler.cpp (modified) (6 diffs)

issm/trunk-jpl/src/c/classes/Profiler.cpp

@@ -3 +3 @@
  */
 
-/*Include files: {{{*/
+/*Include files*/
 #ifdef HAVE_CONFIG_H
         #include <config.h>
@@ -11 +11 @@
 
 #include "./Profiler.h"
-#include "./Params/DoubleParam.h"
 #include "../toolkits/toolkits.h"
-/*}}}*/
 
 /*Profiler constructors and destructors:*/
 Profiler::Profiler(){/*{{{*/
         for(int i=0;i<MAXIMUMSIZE;i++){
-                this->time[i]  =NAN;
-                this->flops[i] =NAN;
-                this->memory[i]=NAN;
+                this->time[i]          = 0.;
+                this->time_start[i]    = 0.;
+                this->flops[i]         = 0.;
+                this->flops_start[i]   = 0.;
+                this->memory[i]        = 0.;
+                this->memory_start[i]  = 0.;
+                this->running[i]       = false;
         }
 } /*}}}*/
@@ -42 +44 @@
 /*Object virtual functions definitions:*/
 void Profiler::DeepEcho(void){/*{{{*/
-
         this->Echo();
-
-}
-/*}}}*/
+}/*}}}*/
 void Profiler::Echo(void){/*{{{*/
 
@@ -52 +51 @@
         for(int i=0;i<MAXIMUMSIZE;i++){
                 _printf_("    Tag "<<i<<":\n");
-                _printf_("       flops:  "<<this->flops[i]<<"\n");
-                _printf_("       memory: "<<this->memory[i]<<"\n");
-                _printf_("       time:   "<<this->time[i]<<"\n");
-        }
-
-}
-/*}}}*/
-int  Profiler::Id(void){ return -1; }/*{{{*/
+                _printf_("       flops:   "<<this->flops[i]<<"\n");
+                _printf_("       memory:  "<<this->memory[i]<<"\n");
+                _printf_("       time:    "<<this->time[i]<<"\n");
+                _printf_("       running: "<<this->time[i]<<"\n");
+        }
+
+}
+/*}}}*/
+int  Profiler::Id(void){ /*{{{*/
+        return -1; 
+}
 /*}}}*/
 void Profiler::Marshall(char** pmarshalled_data,int* pmarshalled_data_size, int marshall_direction){ /*{{{*/
 
         IssmDouble* pointer = NULL;
+        bool*       bpointer = NULL;
 
         MARSHALLING_ENUM(ProfilerEnum);
         pointer = &this->time[0];
-        MARSHALLING_DYNAMIC(pointer,IssmDouble,MAXIMUMSIZE);
+        MARSHALLING_DYNAMIC(pointer,IssmPDouble,MAXIMUMSIZE);
         pointer = &this->flops[0];
-        MARSHALLING_DYNAMIC(pointer,IssmDouble,MAXIMUMSIZE);
+        MARSHALLING_DYNAMIC(pointer,IssmPDouble,MAXIMUMSIZE);
         pointer = &this->memory[0];
-        MARSHALLING_DYNAMIC(pointer,IssmDouble,MAXIMUMSIZE);
+        MARSHALLING_DYNAMIC(pointer,IssmPDouble,MAXIMUMSIZE);
+        bpointer = &this->running[0];
+        MARSHALLING_DYNAMIC(bpointer,bool,MAXIMUMSIZE);
 
 } /*}}}*/
 int  Profiler::ObjectEnum(void){/*{{{*/
-
         return ProfilerEnum;
-
-}
-/*}}}*/
+}/*}}}*/
 
 /*Profiler routines:*/
-IssmDouble  Profiler::DeltaFlops(int inittag, int finaltag){/*{{{*/
+IssmPDouble  Profiler::TotalFlops(int tag){/*{{{*/
+
+        /*Get tag*/
+        _assert_(tag>=0); 
+        _assert_(tag<MAXIMUMSIZE); 
+        if(this->running[tag]) _error_("Tag "<<tag<<" has not been stopped");
+
+        return this->flops[tag];
+}/*}}}*/
+IssmPDouble  Profiler::TotalTime(int tag){/*{{{*/
+
+        /*Get tag*/
+        _assert_(tag>=0); 
+        _assert_(tag<MAXIMUMSIZE); 
+        if(this->running[tag]) _error_("Tag "<<tag<<" has not been stopped");
+
+
+        #ifdef _HAVE_MPI_
+        return this->time[tag];
+        #else
+        return this->time[tag]/CLOCKS_PER_SEC;
+        #endif
+}
+/*}}}*/
+int Profiler::TotalTimeModHour(int tag){/*{{{*/
+
+        IssmPDouble delta = this->TotalTime(tag);
+        return int((reCast<int,IssmPDouble>(delta))/3600);
+
+}
+/*}}}*/
+int Profiler::TotalTimeModMin(int tag){/*{{{*/
+
+        IssmPDouble delta = this->TotalTime(tag);
+        return int(int(reCast<int,IssmPDouble>(delta))%3600/60);
+}
+/*}}}*/
+int Profiler::TotalTimeModSec(int tag){/*{{{*/
+
+        IssmPDouble delta = this->TotalTime(tag);
+        return int(reCast<int,IssmPDouble>(delta)%60);
+}
+/*}}}*/
+IssmDouble  Profiler::Memory(int tag){/*{{{*/
 
         /*Get initial flops*/
-        _assert_(inittag>=0); 
-        _assert_(inittag<MAXIMUMSIZE); 
-        if(xIsNan<IssmDouble>(this->flops[inittag])) _error_("Tag not set");
-        IssmDouble init = this->flops[inittag];
-
-        /*Get final flops*/
-        _assert_(finaltag>=0); 
-        _assert_(finaltag<MAXIMUMSIZE); 
-        if(xIsNan<IssmDouble>(this->flops[finaltag])) _error_("Tag not set");
-        IssmDouble final = this->flops[finaltag];
-
-        return final-init;
-}
-/*}}}*/
-IssmDouble  Profiler::DeltaTime(int inittag, int finaltag){/*{{{*/
-
-        /*Get initial time*/
-        _assert_(inittag>=0); 
-        _assert_(inittag<MAXIMUMSIZE); 
-        if(xIsNan<IssmDouble>(this->time[inittag])) _error_("Tag "<<inittag<<" not set");
-        IssmDouble init = this->time[inittag];
-
-        /*Get final time*/
-        _assert_(finaltag>=0); 
-        _assert_(finaltag<MAXIMUMSIZE); 
-        if(xIsNan<IssmDouble>(this->time[finaltag])) _error_("Tag "<<finaltag<<" not set");
-        IssmDouble final = this->time[finaltag];
-
-        #ifdef _HAVE_MPI_
-        return final-init;
-        #else
-        return (final-init)/CLOCKS_PER_SEC;
-        #endif
-}
-/*}}}*/
-int Profiler::DeltaTimeModHour(int inittag, int finishtag){/*{{{*/
-
-        IssmDouble delta = this->DeltaTime(inittag,finishtag);
-        return int((reCast<int,IssmDouble>(delta))/3600);
-
-}
-/*}}}*/
-int Profiler::DeltaTimeModMin(int inittag, int finishtag){/*{{{*/
-
-        IssmDouble delta = this->DeltaTime(inittag,finishtag);
-        return int(int(reCast<int,IssmDouble>(delta))%3600/60);
-}
-/*}}}*/
-int Profiler::DeltaTimeModSec(int inittag, int finishtag){/*{{{*/
-
-        IssmDouble delta = this->DeltaTime(inittag,finishtag);
-        return int(reCast<int,IssmDouble>(delta)%60);
-}
-/*}}}*/
-IssmDouble  Profiler::Memory(int tag){/*{{{*/
-
-        /*Get initial flops*/
-        _assert_(tag>=0); 
-        _assert_(tag<MAXIMUMSIZE); 
-        if(xIsNan<IssmDouble>(this->flops[tag])) _error_("Tag not set");
+        _assert_(tag>=0); 
+        _assert_(tag<MAXIMUMSIZE); 
+        if(this->running[tag]) _error_("Tag "<<tag<<" has not been stopped");
+
         return this->memory[tag];
 }
 /*}}}*/
-void  Profiler::Tag(int tagenum,bool dontmpisync){/*{{{*/
-
-        IssmDouble t;
-        IssmDouble f;
-        IssmDouble m;
-
-        /*If mpisync requested, make sure all the cpus are at the same point 
-         *in the execution: */
+void  Profiler::Start(int tag,bool dontmpisync){/*{{{*/
+
+        /*Check tag*/
+        _assert_(tag>=0); 
+        _assert_(tag<MAXIMUMSIZE); 
+        if(this->running[tag]) _error_("Tag "<<tag<<" is already running");
+
+
+        /*If mpisync requested, make sure all the cpus are at the same point in the execution: */
         if(!dontmpisync){
                 ISSM_MPI_Barrier(IssmComm::GetComm()); 
@@ -162 +152 @@
         /*Capture time: */
         #ifdef _HAVE_MPI_
-        t=ISSM_MPI_Wtime();
-        #else
-        t=(IssmPDouble)clock();
+        IssmPDouble t=ISSM_MPI_Wtime();
+        #else
+        IssmPDouble t=(IssmPDouble)clock();
         #endif
 
         /*Capture flops: */
+        IssmPDouble f = 0.;
+        IssmPDouble m = 0.;
         #ifdef _HAVE_PETSC_
                 PetscGetFlops(&f);
@@ -176 +168 @@
 
         /*Plug into this->time: */
-        _assert_(tagenum>=0); 
-        _assert_(tagenum<MAXIMUMSIZE); 
-        if(!xIsNan<IssmDouble>(this->time[tagenum])) _error_("Tag already exists");
-        this->time[tagenum]  = t;
-        if(!xIsNan<IssmDouble>(this->flops[tagenum])) _error_("Tag already exists");
-        this->flops[tagenum] = f;
-        if(!xIsNan<IssmDouble>(this->memory[tagenum])) _error_("Tag already exists");
-        this->memory[tagenum]= m;
-
-}
-/*}}}*/
+        _assert_(tag>=0); 
+        _assert_(tag<MAXIMUMSIZE); 
+        this->time_start[tag]   = t;
+        this->flops_start[tag]  = f;
+        this->memory_start[tag] = m;
+
+        /*turn on running*/
+        this->running[tag] = true;
+}/*}}}*/
+void  Profiler::Stop(int tag,bool dontmpisync){/*{{{*/
+
+        /*Check tag*/
+        _assert_(tag>=0); 
+        _assert_(tag<MAXIMUMSIZE); 
+        if(!this->running[tag]) _error_("Tag "<<tag<<" is not running");
+
+
+        /*If mpisync requested, make sure all the cpus are at the same point in the execution: */
+        if(!dontmpisync){
+                ISSM_MPI_Barrier(IssmComm::GetComm()); 
+        }
+
+        /*Capture time: */
+        #ifdef _HAVE_MPI_
+        IssmPDouble t=ISSM_MPI_Wtime();
+        #else
+        IssmPDouble t=(IssmPDouble)clock();
+        #endif
+
+        /*Capture flops: */
+        IssmPDouble f = 0.;
+        IssmPDouble m = 0.;
+        #ifdef _HAVE_PETSC_
+        PetscGetFlops(&f);
+        PetscMemoryGetCurrentUsage(&m);
+        #else
+        /*do nothing for now:*/
+        #endif
+
+        /*Plug into this->time: */
+        _assert_(tag>=0); 
+        _assert_(tag<MAXIMUMSIZE); 
+        this->time[tag]   += t - this->time_start[tag];
+        this->flops[tag]  += f - this->flops_start[tag];
+        this->memory[tag] += m - this->memory_start[tag];
+
+        /*turn off running*/
+        this->running[tag] = false;
+}/*}}}*/