add API to pass application annotation time to tracing framework
authorYanhua Sun <sun51@illinois.edu>
Fri, 20 Sep 2013 18:45:27 +0000 (13:45 -0500)
committerYanhua Sun <sun51@illinois.edu>
Fri, 20 Sep 2013 18:45:27 +0000 (13:45 -0500)
src/ck-perf/trace-bluegene.C
src/ck-perf/trace-bluegene.h
src/ck-perf/trace-common.C
src/ck-perf/trace-projections.C
src/ck-perf/trace-projections.h
src/ck-perf/trace-simple.h
src/ck-perf/trace.h
src/ck-tune/trace-autoPerf.C
src/ck-tune/trace-autoPerf.h
src/ck-tune/trace-perf.C
src/conv-core/conv-trace.h

index eee9a564da303e5dd541ffa96840bcc4874d3e2d..3716f28cc8838a50ba780cbc4c06d36504fd23b7 100644 (file)
@@ -227,7 +227,6 @@ void TraceBluegene::userBracketEvent(const char* name, double bt, double et, voi
   tTIMELINEREC.logEntryInsert(newLog);
 }
 
-
 void TraceBluegene::userBracketEvent(const char* name, double bt, double et, void** parentLogPtr, CkVec<void*> bgLogList){
    
   if (!genTimeLog) return;
index 2f5c90ceba84cd7706a30e954c3943e58eecac37..63634bc7fc9e246e574978149c1e59a9e2e6c4b5 100644 (file)
@@ -34,6 +34,7 @@ class TraceBluegene : public Trace {
     virtual void beginExecute(int event,int msgType,int ep,int srcPe, int mlen,CmiObjId *idx);
     void addBackwardDep(void *log);
     void userBracketEvent(int eventID, double bt, double et) {}        // from trace.h
+    void appWork(int e, double bt, double et){}
     void userBracketEvent(const char* name, double bt, double et, void** parentLogPtr);
     void userBracketEvent(const char* name, double bt, double et, void** parentLogPtr, CkVec<void*> bgLogList);
     void bgPrint(const char* str);
index aef97798a548b8e396bbb62df6bdf7580e920ec1..94a0ba9ae46007a15773e97b53b34689991d9de3 100644 (file)
@@ -43,6 +43,7 @@ CkpvDeclare(char*, partitionRoot);
 CkpvDeclare(int, traceRootBaseLength);
 CkpvDeclare(char*, selective);
 CkpvDeclare(bool, verbose);
+CkpvDeclare(double, startUsefulWorkTimer);
 
 typedef void (*mTFP)();                   // function pointer for
 CpvStaticDeclare(mTFP, machineTraceFuncPtr);    // machine user event
@@ -62,6 +63,8 @@ static void traceCommonInit(char **argv)
   CkpvAccess(traceInitTime) = CmiStartTimer();
   CkpvInitialize(double, traceInitCpuTime);
   CkpvAccess(traceInitCpuTime) = TRACE_CPUTIMER();
+  CkpvInitialize(double, startUsefulWorkTimer);
+  CkpvAccess(startUsefulWorkTimer) = TRACE_CPUTIMER();
   CpvInitialize(int, traceOn);
   CpvAccess(traceOn) = 0;
   CpvInitialize(int, _traceCoreOn); //projector
@@ -70,7 +73,6 @@ static void traceCommonInit(char **argv)
   CpvAccess(machineTraceFuncPtr) = NULL;
   CkpvInitialize(int, traceOnPe);
   CkpvAccess(traceOnPe) = 1;
-
   CkpvInitialize(bool, verbose);
   if (CmiGetArgFlag(argv, "+traceWarn")) {
     CkpvAccess(verbose) = true;
@@ -475,6 +477,25 @@ void traceUserEvent(int e)
 #endif
 }
 
+extern "C" 
+void traceStartUsefulWork()
+{
+#if CMK_TRACE_ENABLED
+    CkpvAccess(startUsefulWorkTimer) = TraceTimer();
+#endif
+}
+
+extern "C" 
+void traceStopUsefulWork()
+{
+#if CMK_TRACE_ENABLED
+    if (CpvAccess(traceOn) && CkpvAccess(_traces))
+    {
+        CkpvAccess(_traces)->appWork(1, CkpvAccess(startUsefulWorkTimer), TraceTimer());
+    }
+#endif
+}
+
 extern "C"
 void traceUserBracketEvent(int e, double beginT, double endT)
 {
index 4e13616a7681d0274d57c876af926550bf93ffa7..8db601af862e9ccc07fe923a9cf082a8036db58b 100644 (file)
@@ -1332,6 +1332,10 @@ void TraceProjections::userBracketEvent(int e, double bt, double et)
   _logPool->add(USER_EVENT_PAIR, e, 0, TraceTimer(et), curevent++, CkMyPe());
 }
 
+void TraceProjections::appWork(int e, double bt, double et)
+{
+}
+
 void TraceProjections::userSuppliedData(int d)
 {
   if (!computationStarted) return;
index 14359e44b647cd532048d2f809b3f310aad82325..eae9bcf2e6fe48767ac8065d7789d2c5d3b18a64 100644 (file)
@@ -483,6 +483,7 @@ public:
     TraceProjections(char **argv);
     void userEvent(int e);
     void userBracketEvent(int e, double bt, double et);
+    void appWork(int e, double bt, double et);
     void userSuppliedBracketedNote(char*, int, double, double);
 
     void userSuppliedData(int e);
index 9188281ce73ea2b4e2c4948704cda6c0e7f92296..d6c0d1ab9b67ca5ede719b170d77cfb55723764c 100644 (file)
@@ -27,6 +27,7 @@ class TraceSimple : public Trace {
   // a pair of begin/end user event has just occured
   void userBracketEvent(int eventID, double bt, double et);
   
+  void appWork(int e, double bt, double et);
   // "creation" of message(s) - message Sends
   void creation(envelope *, int epIdx, int num=1);
   void creation(char *msg) {}
index 6d8e5d4b4e65f1e04d7a3ce152c0a43a1d4c3952..8f6ba0d2331da99ec519c2ddec8b4a83197b4853 100644 (file)
@@ -77,6 +77,8 @@ protected:
     virtual void userEvent(int eventID) {}
     // a pair of begin/end user event has just occured
     virtual void userBracketEvent(int eventID, double bt, double et) {}
+    //interact with application 
+    virtual void appWork(int eventID, double bt, double et) {}
 
     // a user supplied integer value(likely a timestep)
     virtual void userSuppliedData(int e) {}
@@ -205,6 +207,7 @@ public:
 
     inline void userEvent(int e) { ALLDO(userEvent(e));}
     inline void userBracketEvent(int e,double bt, double et) {ALLDO(userBracketEvent(e,bt,et));}
+    inline void appWork(int e,double bt, double et) {ALLDO(appWork(e,bt,et));}
     
        inline void userSuppliedData(int d) { ALLDO(userSuppliedData(d));}
 
@@ -314,6 +317,7 @@ extern "C" {
 
 #define _TRACE_USER_EVENT(x) _TRACE_ONLY(CkpvAccess(_traces)->userEvent(x))
 #define _TRACE_USER_EVENT_BRACKET(x,bt,et) _TRACE_ONLY(CkpvAccess(_traces)->userBracketEvent(x,bt,et))
+#define _TRACE_APPWORK(x,bt,et) _TRACE_ONLY(CkpvAccess(_traces)->appWork(x,bt,et))
 #define _TRACE_CREATION_1(env) _TRACE_ONLY(CkpvAccess(_traces)->creation(env,env->getEpIdx()))
 #define _TRACE_CREATION_DETAILED(env,ep) _TRACE_ONLY(CkpvAccess(_traces)->creation(env,ep))
 #define _TRACE_CREATION_N(env, num) _TRACE_ONLY(CkpvAccess(_traces)->creation(env, env->getEpIdx(), num))
index 59f6eb67cbf35de890fc0cc5ff5fdb55b5e1dd72..2233c46ab277b96def13738154b948922fddad3b 100644 (file)
@@ -54,6 +54,9 @@ CkReductionMsg *perfDataReduction(int nMsg,CkReductionMsg **msgs){
         ret->utilMin = min(ret->utilMin, m->utilMin);
         ret->utilTotalTime += m->utilTotalTime; 
         ret->utilMax = max(ret->utilMax, m->utilMax);
+        ret->appMin = min(ret->appMin, m->appMin);
+        ret->appTotalTime += m->appTotalTime; 
+        ret->appMax = max(ret->appMax, m->appMax);
         // mem usage (max)
         ret->mem =max(ret->mem,m->mem);
         // bytes per invocation for two types of entry methods
@@ -169,8 +172,10 @@ void TraceAutoPerfBOC::globalPerfAnalyze(CkReductionMsg *msg )
     double idlePercentage = data->idleTotalTime/totalTime;
     double overheadPercentage = data->overheadTotalTime/totalTime;
     double utilPercentage = data->utilTotalTime/totalTime;
+    double appPercentage = data->appTotalTime/totalTime;
     //DEBUG_PRINT ( 
     CkPrintf("Utilization(%):  \t(min:max:avg):(%.1f:\t  %.1f:\t  %.1f) time:%f\n", data->utilMin*100, data->utilMax*100, utilPercentage*100, data->utilTotalTime);
+    CkPrintf("Application time (%):  \t(min:max:avg):(%.1f:\t  %.1f:\t  %.1f) time:%f\n", data->appMin*100, data->appMax*100, appPercentage*100, data->appTotalTime);
     CkPrintf("Idle(%):         \t(min:max:avg):(%.1f:\t  %.1f:\t  %.1f) time:%f \n", data->idleMin*100,  data->idleMax*100, idlePercentage*100, data->idleTotalTime);
     CkPrintf("Overhead(%):     \t(min:max:avg):(%.1f:\t  %.1f:\t  %.1f) time:%f \n", data->overheadMin*100, data->overheadMax*100, overheadPercentage*100, data->overheadTotalTime);
     CkPrintf("Grainsize(ms):\t(avg:max)\t: (%.3f:    %.3f) \n", data->utilTotalTime/data->numInvocations*1000, data->grainsizeMax*1000);
index 44baad14d3c144a6b601dd224077865cbcba4705..d3653dade29557680fb2a307ead06b2433466bdc 100644 (file)
@@ -158,6 +158,10 @@ public:
     double utilTotalTime;
     double utilMax;
    
+    double appMin;
+    double appTotalTime;
+    double appMax;
+
     double overheadMin;
     double overheadTotalTime;
     double overheadMax;
@@ -268,6 +272,9 @@ public:
     /** The amount of time spent executing entry methods since we last reset the counters */
     double totalEntryMethodTime;
 
+    /** the amount of application useful work, need app knowledge */
+    double totalAppTime;
+
     /** The amount of time spent idle since we last reset the counters */
     double totalIdleTime;
 
@@ -308,6 +315,7 @@ public:
   void userEvent(int eventID);
   // a pair of begin/end user event has just occured
   void userBracketEvent(int eventID, double bt, double et);
+  void appWork(int eventID, double bt, double et);
   
   // "creation" of message(s) - message Sends
   void creation(envelope *, int epIdx, int num=1);
@@ -421,6 +429,14 @@ public:
           totalEntryMethodTime += (TraceTimer() - lastBeginExecuteTime);
       return totalEntryMethodTime; 
   }
+
+  inline double appRatio() {
+      return totalAppTime/ totalTraceTime(); 
+  }
+
+  inline double appTime() {
+      return totalAppTime; 
+  }
   /** Highest memory usage (in MB) value we've seen since resetting the counters */
   inline double memoryUsageMB(){
     return ((double)memUsage) / 1024.0 / 1024.0;
@@ -458,6 +474,8 @@ public:
       currentSummary->idleTotalTime = idleTime();
       currentSummary->utilMin = currentSummary->utilMax = utilRatio(); 
       currentSummary->utilTotalTime= utilTime();
+      currentSummary->appMin = currentSummary->appMax = appRatio(); 
+      currentSummary->appTotalTime= appTime();
       currentSummary->overheadMin = currentSummary->overheadMax = overheadRatio();
       currentSummary->overheadTotalTime = overheadTime();
       currentSummary->grainsizeAvg = grainSize();
index 38ce07bd878553317a9a761d904dd17884280036..9179c7b04d09749a531f3d09445174d10b709fb5 100644 (file)
@@ -24,6 +24,7 @@ TraceAutoPerf::TraceAutoPerf(char **argv)
 void TraceAutoPerf::resetTimings(){
     totalIdleTime = 0.0;
     totalEntryMethodTime = 0.0;
+    totalAppTime = 0.0;
     totalEntryMethodInvocations = 0;
     lastBeginIdle = lastBeginExecuteTime = lastResetTime = TraceTimer();
     totalUntracedTime = 0;
@@ -41,6 +42,7 @@ void TraceAutoPerf::resetTimings(){
 void TraceAutoPerf::resetAll(){
     totalIdleTime = 0.0;
     totalEntryMethodTime = 0.0;
+    totalAppTime = 0.0;
     memUsage = 0;
     totalEntryMethodInvocations = 0;
     lastBeginIdle = lastBeginExecuteTime = lastResetTime = TraceTimer();
@@ -70,6 +72,10 @@ void TraceAutoPerf::traceEnd(void){
 
 void TraceAutoPerf::userEvent(int eventID) { }
 void TraceAutoPerf::userBracketEvent(int eventID, double bt, double et) { }
+
+void TraceAutoPerf::appWork(int eventID, double bt, double et) { 
+    totalAppTime += (et-bt);
+}
 void TraceAutoPerf::creation(envelope *, int epIdx, int num) { } 
 void TraceAutoPerf::creationMulticast(envelope *, int epIdx, int num, int *pelist) { }
 void TraceAutoPerf::creationDone(int num) { }
index ea09f9257cdc2d5c7c35234448c1baf092bbcaa4..52863fa868785ee0020e1632b974f4b3d9e8bdf3 100644 (file)
@@ -17,6 +17,8 @@ void traceResume(CmiObjId *);
 void traceSuspend(void);
 void traceAwaken(CthThread t);
 void traceUserEvent(int);
+void traceStartUsefulWork();
+void traceStopUsefulWork();
 void traceUserBracketEvent(int, double, double);
 void traceUserSuppliedData(int);
 void traceUserSuppliedBracketedNote(char *note, int eventID, double bt, double et);