Improving performance data gathering & recording for control point framework.
authorIsaac Dooley <isaacdooley@hope.cs.uiuc.edu>
Tue, 26 Jan 2010 17:46:28 +0000 (11:46 -0600)
committerIsaac Dooley <isaacdooley@hope.cs.uiuc.edu>
Tue, 26 Jan 2010 17:46:28 +0000 (11:46 -0600)
src/ck-cp/controlPoints.C
src/ck-cp/controlPoints.h
src/ck-perf/trace-controlPoints.C
src/ck-perf/trace-controlPoints.h

index 4c85b792c9c9fb1fda7407a0e52051747a8608e8..2dd0ce32aafa520695075763e4eddb94e2f04915 100644 (file)
@@ -110,21 +110,16 @@ CkReductionMsg *idleTimeReduction(int nMsg,CkReductionMsg **msgs){
 /// A reduction type that combines idle, overhead, and memory measurements
 CkReduction::reducerType allMeasuresReductionType;
 /// A reducer that combines idle, overhead, and memory measurements
+#define ALL_REDUCTION_SIZE 12
 CkReductionMsg *allMeasuresReduction(int nMsg,CkReductionMsg **msgs){
-  double ret[7];
+  double ret[ALL_REDUCTION_SIZE];
   if(nMsg > 0){
-    CkAssert(msgs[0]->getSize()==7*sizeof(double));
+    CkAssert(msgs[0]->getSize()==ALL_REDUCTION_SIZE*sizeof(double));
     double *m=(double *)msgs[0]->getData();
-    ret[0]=m[0];
-    ret[1]=m[1];
-    ret[2]=m[2];
-    ret[3]=m[3];
-    ret[4]=m[4];
-    ret[5]=m[5];
-    ret[6]=m[6];
+    memcpy(ret, m, ALL_REDUCTION_SIZE*sizeof(double) );
   }
   for (int i=1;i<nMsg;i++) {
-    CkAssert(msgs[i]->getSize()==7*sizeof(double));
+    CkAssert(msgs[i]->getSize()==ALL_REDUCTION_SIZE*sizeof(double));
     double *m=(double *)msgs[i]->getData();
     // idle time (min/sum/max)
     ret[0]=min(ret[0],m[0]);
@@ -136,8 +131,15 @@ CkReductionMsg *allMeasuresReduction(int nMsg,CkReductionMsg **msgs){
     ret[5]=max(ret[5],m[5]);
     // mem usage (max)
     ret[6]=max(ret[6],m[6]);
+    // bytes per invocation for two types of entry methods
+    ret[7]+=m[7];
+    ret[8]+=m[8];
+    ret[9]+=m[9];
+    ret[10]+=m[10];
+    // Grain size (avg)
+    ret[11]+=m[11];
   }  
-  return CkReductionMsg::buildNew(7*sizeof(double),ret);   
+  return CkReductionMsg::buildNew(ALL_REDUCTION_SIZE*sizeof(double),ret);   
 }
 
 
@@ -276,10 +278,17 @@ controlPointManager::controlPointManager(){
       iss >> ips->memoryUsageMB;
       //     CkPrintf("Memory usage loaded from file: %d\n", ips.memoryUsageMB);
 
+      // Read idle time
       iss >> ips->idleTime.min;
       iss >> ips->idleTime.avg;
       iss >> ips->idleTime.max;
 
+      // read bytePerInvoke
+      iss >> ips->bytesPerInvoke;
+
+      // read grain size
+      iss >> ips->grainSize;
+
       // Read control point values
       for(int cp=0;cp<numControlPointNames;cp++){
        int cpvalue;
@@ -287,6 +296,12 @@ controlPointManager::controlPointManager(){
        ips->controlPoints.insert(make_pair(names[cp],cpvalue));
       }
 
+      // ignore median time
+      double mt;
+      iss >> mt;
+
+      // Read all times
+
       double time;
 
       while(iss >> time){
@@ -714,40 +729,53 @@ controlPointManager::controlPointManager(){
 
   /// Entry method called on all PEs to request CPU utilization statistics and memory usage
   void controlPointManager::requestAll(CkCallback cb){
-    const double i = localControlPointTracingInstance()->idleRatio();
-    const double o = localControlPointTracingInstance()->overheadRatio();
-    const double m = localControlPointTracingInstance()->memoryUsageMB();
-    
-    double data[3+3+1];
+    TraceControlPoints *t = localControlPointTracingInstance();
+
+    double data[ALL_REDUCTION_SIZE];
 
     double *idle = data;
     double *over = data+3;
     double *mem = data+6;
+    double *msgBytes = data+7;  
+    double *grainsize = data+11;  
 
+    const double i = t->idleRatio();
     idle[0] = i;
     idle[1] = i;
     idle[2] = i;
 
+    const double o = t->overheadRatio();
     over[0] = o;
     over[1] = o;
     over[2] = o;
 
+    const double m = t->memoryUsageMB();
     mem[0] = m;
+
+    msgBytes[0] = t->b2;
+    msgBytes[1] = t->b3;
+    msgBytes[2] = t->b2mlen;
+    msgBytes[3] = t->b3mlen;
+
+    grainsize[0] = t->grainSize();
     
     localControlPointTracingInstance()->resetAll();
 
-    contribute(7*sizeof(double),data,allMeasuresReductionType, cb);
+    contribute(ALL_REDUCTION_SIZE*sizeof(double),data,allMeasuresReductionType, cb);
   }
   
   /// All processors reduce their memory usages in requestIdleTime() to this method
   void controlPointManager::gatherAll(CkReductionMsg *msg){
+    CkAssert(msg->getSize()==ALL_REDUCTION_SIZE*sizeof(double));
     int size=msg->getSize() / sizeof(double);
-    CkAssert(size==7);
     double *data=(double *) msg->getData();
         
     double *idle = data;
     double *over = data+3;
     double *mem = data+6;
+    double *msgBytes = data+7;
+    double *granularity = data+11;
+
 
     //    std::string b = allData.toString();
 
@@ -761,6 +789,23 @@ controlPointManager::controlPointManager(){
       
       CkPrintf("Stored idle time min=%lf, mem=%lf in prevPhase=%p\n", (double)prevPhase->idleTime.min, (double)prevPhase->memoryUsageMB, prevPhase);
 
+      double bytesPerInvoke2 = msgBytes[2] / msgBytes[0];
+      double bytesPerInvoke3 = msgBytes[3] / msgBytes[1];
+
+      /** The average of the grain sizes on all PEs in us */
+      prevPhase->grainSize = (granularity[0] / (double)CkNumPes());
+
+      CkPrintf("Bytes Per Invokation 2 = %f\n", bytesPerInvoke2);
+      CkPrintf("Bytes Per Invokation 3 = %f\n", bytesPerInvoke3);
+
+      CkPrintf("Bytes Per us of work 2 = %f\n", bytesPerInvoke2/prevPhase->grainSize);
+      CkPrintf("Bytes Per us of work 3 = %f\n", bytesPerInvoke3/prevPhase->grainSize);
+
+      if(bytesPerInvoke2 > bytesPerInvoke3)
+       prevPhase->bytesPerInvoke = bytesPerInvoke2;
+      else
+       prevPhase->bytesPerInvoke = bytesPerInvoke3;
+
       //      prevPhase->print();
       // CkPrintf("prevPhase=%p number of timings=%d\n", prevPhase, prevPhase->times.size() );
 
index 6879e090f837a4dac12f30b9ee07acaa1ff0afd2..6641e138144c9bbdf999c586e1a7fbe00c05d934 100644 (file)
@@ -18,6 +18,7 @@
 #include <cmath>
 #include <math.h>
 #include <iostream>
+#include <iomanip>
 #include <fstream>
 #include <string>
 #include <sstream>
@@ -149,14 +150,25 @@ public:
 
   idleTimeContainer idleTime;
 
+  /** Approximately records the average message size for an entry method. */
+  double bytesPerInvoke;
+
+  /** Records the average grain size (might be off a bit due to non application entry methods), in seconds */
+  double grainSize;
+
+
   instrumentedPhase(){
     memoryUsageMB = -1.0;
+    grainSize = -1.0;
+    bytesPerInvoke = -1.0;
   }
   
   void clear(){
     controlPoints.clear();
     times.clear();
     memoryUsageMB = -1.0;
+    grainSize = -1.0;
+    bytesPerInvoke = -1.0;
     //    criticalPaths.clear();
   }
 
@@ -295,7 +307,14 @@ public:
     } 
     
   }
-  
+
+  /** Determine the median time for this phase */
+  double medianTime(){
+    std::vector<double> sortedTimes = times;
+    std::sort(sortedTimes.begin(), sortedTimes.end());
+    return sortedTimes[sortedTimes.size() / 2];
+  }
+
   
 };
 
@@ -379,30 +398,43 @@ public:
       // SCHEMA:
       s << "# SCHEMA:\n";
       s << "# number of named control points:\n";
-      s << ps.size() << "\n";
-      
+      s << ps.size() << "\n";    
       for(cpiter = ps.begin(); cpiter != ps.end(); cpiter++){
        s << cpiter->first << "\n";
       }
       
       // DATA:
       s << "# DATA:\n";
-      s << "# first field is memory usage (MB). Then there are the " << ps.size()  << " control points values, followed by one or more timings" << "\n";
-      s << "# number of control point sets: " << phases.size() << "\n";
+      s << "# There are " << ps.size()  << " control points\n";
+      s << "# number of recorded phases: " << phases.size() << "\n";
+      
+      s << "# Memory (MB)\tIdle Min\tIdle Avg\tIdle Max\tByte Per Invoke\tGrain Size\t";
+      for(cpiter = ps.begin(); cpiter != ps.end(); cpiter++){
+       s << cpiter->first << "\t";
+      }
+      s << "Median Timing\tTimings\n";
+      
+   
       std::vector<instrumentedPhase*>::iterator runiter;
       for(runiter=phases.begin();runiter!=phases.end();runiter++){
        
        // Print the memory usage
-       s << (*runiter)->memoryUsageMB << "    "; 
+       s << (*runiter)->memoryUsageMB << "\t"; 
+
+       s << (*runiter)->idleTime.min << "\t" << (*runiter)->idleTime.avg << "\t" << (*runiter)->idleTime.max << "\t";
+
+       s << (*runiter)->bytesPerInvoke << "\t";
+
+       s << (*runiter)->grainSize << "\t";
 
-       s << (*runiter)->idleTime.min << " " << (*runiter)->idleTime.avg << " " << (*runiter)->idleTime.max << "   ";
 
        // Print the control point values
        for(cpiter = (*runiter)->controlPoints.begin(); cpiter != (*runiter)->controlPoints.end(); cpiter++){ 
-         s << cpiter->second << " "; 
+         s << cpiter->second << "\t"; 
        }
 
-       s << "     ";
+       // Print the median time
+       s << (*runiter)->medianTime() << "\t";
 
        // Print the times
        std::vector<double>::iterator titer;
index 30565738f0bf3d63739c68dfe814c615dc20a6ce..ea317b772869eb40d4d9c194bd45356dc292c559 100644 (file)
@@ -30,9 +30,12 @@ void _createTracecontrolPoints(char **argv)
 
 TraceControlPoints::TraceControlPoints(char **argv)
 {
-
   resetTimings();
 
+  b1=0;
+  b2=0;
+  b3=0;
+
   if (CkpvAccess(traceOnPe) == 0) return;
 
   // Process runtime arguments intended for the module
@@ -70,7 +73,7 @@ void TraceControlPoints::beginExecute(CmiObjId *tid)
   // CmiObjId is a 4-integer tuple uniquely identifying a migratable
   //   Charm++ object. Note that there are other non-migratable Charm++
   //   objects that CmiObjId will not identify.
-
+  b1++;
   lastBeginExecuteTime = CmiWallTimer();
   lastbeginMessageSize = -1;
 
@@ -81,7 +84,8 @@ void TraceControlPoints::beginExecute(envelope *e)
 {
   lastBeginExecuteTime = CmiWallTimer();
   lastbeginMessageSize = e->getTotalsize();
-
+  b2++;
+  b2mlen += lastbeginMessageSize;
   //  CkPrintf("[%d] WARNING ignoring TraceControlPoints::beginExecute(envelope *e)\n", CkMyPe());
 
   // no message means thread execution
@@ -93,10 +97,12 @@ void TraceControlPoints::beginExecute(envelope *e)
   //  CkPrintf("[%d] TraceControlPoints::beginExecute(envelope *e=%p)\n", CkMyPe(), e);
 
 }
-
 void TraceControlPoints::beginExecute(int event,int msgType,int ep,int srcPe, 
                               int mlen, CmiObjId *idx)
 {
+  b3++;
+  b3mlen += mlen;
   lastBeginExecuteTime = CmiWallTimer();
   lastbeginMessageSize = mlen;
   //  CkPrintf("[%d] TraceControlPoints::beginExecute event=%d, msgType=%d, ep=%d, srcPe=%d, mlen=%d CmiObjId is also avaliable\n", CkMyPe(), event, msgType, ep, srcPe, mlen);
@@ -108,7 +114,8 @@ void TraceControlPoints::endExecute(void)
 {
   double executionTime = CmiWallTimer() - lastBeginExecuteTime;
   totalEntryMethodTime += executionTime;
-  
+  totalEntryMethodInvocations ++;
+
   double m = (double)CmiMemoryUsage();
   if(memUsage < m){
     memUsage = m;
@@ -183,6 +190,7 @@ void TraceControlPointsBOC::printBGP_UPC_CountersBOC(void) {
 void TraceControlPoints::resetTimings(){
   totalIdleTime = 0.0;
   totalEntryMethodTime = 0.0;
+  totalEntryMethodInvocations = 0;
   lastResetTime = CmiWallTimer();
 }
 
@@ -190,6 +198,11 @@ void TraceControlPoints::resetAll(){
   totalIdleTime = 0.0;
   totalEntryMethodTime = 0.0;
   memUsage = 0;
+  totalEntryMethodInvocations = 0;
+  b2mlen=0;
+  b3mlen=0;
+  b2=0;
+  b3=0;
   lastResetTime = CmiWallTimer();
 }
 
index 7614a2a807cc36e3c188bf60efba38a53a284330..4e0b654de376e25f486ba26d2de1502555d065d9 100644 (file)
@@ -28,23 +28,29 @@ class TraceControlPoints : public Trace {
   double lastBeginExecuteTime;
   int lastbeginMessageSize;
 
-  /** The amount of time spent executing entry methods */
-  double totalEntryMethodTime;
-
-
   /** The start of the idle region */
   double lastBeginIdle;
   
-  /** The amount of time spent idle */
+  /** The amount of time spent executing entry methods since we last reset the counters */
+  double totalEntryMethodTime;
+
+  /** The amount of time spent idle since we last reset the counters */
   double totalIdleTime;
-  
-  /** The time we last rest the idle/entry totals */
-  double lastResetTime;
 
-  /** The highest seen memory usage */
+  /** The highest seen memory usage  since we last reset the counters */
   double memUsage;
 
-  
+  /** The number of entry method invocations since we last reset the counters */
+  long totalEntryMethodInvocations;
+
+    
+  /** The time we last rest the counters */
+  double lastResetTime;
+
+ public: 
+  int b1, b2, b3;
+  long b2mlen;
+  long b3mlen;
 
  public:
   TraceControlPoints(char **argv);
@@ -101,23 +107,31 @@ class TraceControlPoints : public Trace {
   /** Reset the idle, overhead, and memory measurements */
   void resetAll();
 
-  /** Fraction of the time spent idle */
+  /** Fraction of the time spent idle since resetting the counters */
   double idleRatio(){
     double t = CmiWallTimer() - lastResetTime;
     return (totalIdleTime) / t;
   }
 
-  /** Fraction of time spent as overhead */
+  /** Fraction of time spent as overhead since resetting the counters */
   double overheadRatio(){
     double t = CmiWallTimer() - lastResetTime;
     return (t - totalIdleTime - totalEntryMethodTime) / t;
   }
 
-  /** Highest memory usage (in MB) value we've seen since last time */
+  /** Highest memory usage (in MB) value we've seen since resetting the counters */
   double memoryUsageMB(){
     return ((double)memUsage) / 1024.0 / 1024.0;
   }
 
+  /** Determine the average grain size since last reset of counters */
+  double grainSize(){
+    return (double)totalEntryMethodTime / totalEntryMethodInvocations;
+  }
+
+  double bytesPerEntry() {
+    return (double)(b2mlen + b3mlen) / (double)(b2+b3);
+  }
 
 
 };