33ebbe01e0fbd6972e1c2965d203b523a83a9a6f
[charm.git] / src / ck-perf / trace-summary.C
1 /*****************************************************************************
2  * $Source$
3  * $Author$
4  * $Date$
5  * $Revision$
6  *****************************************************************************/
7
8 /**
9  * \addtogroup CkPerf
10 */
11 /*@{*/
12
13 #include "trace-summary.h"
14
15 #define DEBUGF(x)  // CmiPrintf x
16
17 #define VER   4.0
18
19 #define INVALIDEP     -2
20
21 CkpvStaticDeclare(TraceSummary*, _trace);
22 static int _numEvents = 0;
23 static int _threadMsg, _threadChare, _threadEP;
24 static int _packMsg, _packChare, _packEP;
25 static int _unpackMsg, _unpackChare, _unpackEP;
26 CkpvDeclare(double, binSize);
27 CkpvDeclare(double, version);
28
29 /**
30   For each TraceFoo module, _createTraceFoo() must be defined.
31   This function is called in _createTraces() generated in moduleInit.C
32 */
33 void _createTracesummary(char **argv)
34 {
35   DEBUGF(("%d createTraceSummary\n", CkMyPe()));
36   CkpvInitialize(TraceSummary*, _trace);
37   CkpvAccess(_trace) = new  TraceSummary(argv);
38   CkpvAccess(_traces)->addTrace(CkpvAccess(_trace));
39 }
40
41
42 /// function call for starting a phase in trace summary logs 
43 extern "C" 
44 void CkSummary_StartPhase(int phase)
45 {
46    CkpvAccess(_trace)->startPhase(phase);
47 }
48
49
50 /// function call for adding an event mark
51 extern "C" 
52 void CkSummary_MarkEvent(int eventType)
53 {
54    CkpvAccess(_trace)->addEventType(eventType);
55 }
56
57
58 PhaseEntry::PhaseEntry() 
59 {
60   for (int i=0; i<MAX_ENTRIES; i++) {
61     count[i] = 0;
62     times[i] = 0.0;
63     maxtimes[i] = 0.;
64   }
65 }
66
67 SumLogPool::~SumLogPool() 
68 {
69   write();
70   fclose(fp);
71   // free memory for mark
72   if (markcount > 0)
73   for (int i=0; i<MAX_MARKS; i++) {
74     for (int j=0; j<events[i].length(); j++)
75       delete events[i][j];
76   }
77   delete[] pool;
78   delete[] epInfo;
79 }
80
81 void SumLogPool::addEventType(int eventType, double time)
82 {
83    if (eventType <0 || eventType >= MAX_MARKS) {
84        CkPrintf("Invalid event type %d!\n", eventType);
85        return;
86    }
87    MarkEntry *e = new MarkEntry;
88    e->time = time;
89    events[eventType].push_back(e);
90    markcount ++;
91 }
92
93 SumLogPool::SumLogPool(char *pgm) : phaseTab(MAX_PHASES) 
94 {
95    if (TRACE_CHARM_PE() == 0) return;
96    int i;
97    poolSize = CkpvAccess(CtrLogBufSize);
98    if (poolSize % 2) poolSize++;        // make sure it is even
99    pool = new BinEntry[poolSize];
100    _MEMCHECK(pool);
101    numEntries = 0;
102    char pestr[10];
103    sprintf(pestr, "%d", CkMyPe());
104    int len = strlen(pgm) + strlen(".sum.") + strlen(pestr) + 1;
105    char *fname = new char[len+1];
106    sprintf(fname, "%s.%s.sum", pgm, pestr);
107    fp = NULL;
108    //CmiPrintf("TRACE: %s:%d\n", fname, errno);
109    do {
110     fp = fopen(fname, "w+");
111     } while (!fp && errno == EINTR);
112     delete[] fname;
113     if(!fp) {
114       CmiAbort("Cannot open Summary Trace File for writing...\n");
115    }
116
117    epSize = MAX_ENTRIES;
118    epInfo = new SumEntryInfo[epSize];
119    _MEMCHECK(epInfo);
120
121    // event
122    markcount = 0;
123
124    if (CkMyPe() == 0)
125    {
126     char *fname = new char[strlen(CkpvAccess(traceRoot))+strlen(".sum.sts")+1];
127     sprintf(fname, "%s.sum.sts", CkpvAccess(traceRoot));
128     stsfp = fopen(fname, "w+");
129     //CmiPrintf("File: %s \n", fname);
130     if(stsfp == 0)
131       CmiAbort("Cannot open summary sts file for writing.\n");
132     delete[] fname;
133    }
134 }
135
136 void SumLogPool::write(void) 
137 {
138   int i;
139   unsigned int j;
140   fprintf(fp, "ver:%3.1f %d/%d count:%d ep:%d interval:%e", CkpvAccess(version), CkMyPe(), CkNumPes(), numEntries, _numEntries, CkpvAccess(binSize));
141   if (CkpvAccess(version)>=3.0)
142   {
143     fprintf(fp, " phases:%d", phaseTab.numPhasesCalled());
144   }
145   fprintf(fp, "\n");
146
147   // write bin time
148 #if 1
149   int last=pool[0].getU();
150   pool[0].writeU(fp, last);
151   int count=1;
152   for(j=1; j<numEntries; j++) {
153     int u = pool[j].getU();
154     if (last == u) {
155       count++;
156     }
157     else {
158       if (count > 1) fprintf(fp, "+%d", count);
159       pool[j].writeU(fp, u);
160       last = u;
161       count = 1;
162     }
163   }
164   if (count > 1) fprintf(fp, "+%d", count);
165 #else
166   for(j=0; j<numEntries; j++) 
167       pool[j].write(fp);
168 #endif
169   fprintf(fp, "\n");
170
171   // write entry execution time
172   for (i=0; i<_numEntries; i++)
173     fprintf(fp, "%ld ", (long)(epInfo[i].epTime*1.0e6));
174   fprintf(fp, "\n");
175   // write entry function call times
176   for (i=0; i<_numEntries; i++)
177     fprintf(fp, "%d ", epInfo[i].epCount);
178   fprintf(fp, "\n");
179   // write max entry function execute times
180   fprintf(fp, "PE%d MaxEPTime: ", CkMyPe());
181   for (i=0; i<_numEntries; i++)
182     fprintf(fp, "%ld ", (long)(epInfo[i].epMaxTime*1.0e6));
183   fprintf(fp, "\n");
184   for (i=0; i<SumEntryInfo::HIST_SIZE; i++) {
185     for (j=0; j<_numEntries; j++) 
186       fprintf(fp, "%d ", epInfo[j].hist[i]);
187     fprintf(fp, "\n");
188   }
189   // write marks
190   if (CkpvAccess(version)>=2.0) 
191   {
192   fprintf(fp, "NumMarks: %d ", markcount);
193   for (i=0; i<MAX_MARKS; i++) {
194     for(int j=0; j<events[i].length(); j++)
195         fprintf(fp, "%d %f ", i, events[i][j]->time);
196   }
197   fprintf(fp, "\n");
198   }
199   // write phases
200   if (CkpvAccess(version)>=3.0)
201   {
202   phaseTab.write(fp);
203   }
204 }
205
206 void SumLogPool::writeSts(void)
207 {
208   fprintf(stsfp, "MACHINE %s\n",CMK_MACHINE_NAME);
209   fprintf(stsfp, "PROCESSORS %d\n", CkNumPes());
210   fprintf(stsfp, "TOTAL_CHARES %d\n", _numChares);
211   fprintf(stsfp, "TOTAL_EPS %d\n", _numEntries);
212   fprintf(stsfp, "TOTAL_MSGS %d\n", _numMsgs);
213   fprintf(stsfp, "TOTAL_PSEUDOS %d\n", 0);
214   fprintf(stsfp, "TOTAL_EVENTS %d\n", _numEvents);
215   int i;
216   for(i=0;i<_numChares;i++)
217     fprintf(stsfp, "CHARE %d %s\n", i, _chareTable[i]->name);
218   for(i=0;i<_numEntries;i++)
219     fprintf(stsfp, "ENTRY CHARE %d %s %d %d\n", i, _entryTable[i]->name,
220                  _entryTable[i]->chareIdx, _entryTable[i]->msgIdx);
221   for(i=0;i<_numMsgs;i++)
222     fprintf(stsfp, "MESSAGE %d %d\n", i, _msgTable[i]->size);
223   for(i=0;i<_numEvents;i++)
224     fprintf(stsfp, "EVENT %d Event%d\n", i, i);
225   fprintf(stsfp, "END\n");
226   fclose(stsfp);
227 }
228
229 void SumLogPool::add(double time, int pe) 
230 {
231   new (&pool[numEntries++]) BinEntry(time);
232   if(poolSize==numEntries) shrink();
233 }
234
235 void SumLogPool::setEp(int epidx, double time) 
236 {
237   if (epidx >= epSize) {
238         CmiAbort("Too many entry points!!\n");
239   }
240   //CmiPrintf("set EP: %d %e \n", epidx, time);
241   epInfo[epidx].setTime(time);
242   // set phase table counter
243   phaseTab.setEp(epidx, time);
244 }
245
246 void SumLogPool::shrink(void)
247 {
248 //  double t = CmiWallTimer();
249
250   int entries = numEntries/2;
251   for (int i=0; i<entries; i++)
252   {
253      pool[i].setTime(pool[i*2].getTime() + pool[i*2+1].getTime());
254   }
255   numEntries = entries;
256   CkpvAccess(binSize) *= 2;
257
258 //CkPrintf("Shrinked binsize: %f entries:%d takes %fs!!!!\n", CkpvAccess(binSize), numEntries, CmiWallTimer()-t);
259 }
260
261 int  BinEntry::getU() { 
262   return (int)(time * 100.0 / CkpvAccess(binSize)); 
263 }
264
265 void BinEntry::write(FILE* fp)
266 {
267   int per = (int)(time * 100.0 / CkpvAccess(binSize));
268   fprintf(fp, "%4d", per);
269 }
270
271 void BinEntry::writeU(FILE* fp, int u)
272 {
273   fprintf(fp, "%4d", u);
274 }
275
276 TraceSummary::TraceSummary(char **argv):curevent(0),binStart(0.0),bin(0.0),msgNum(0)
277 {
278   char *tmpStr;
279   CkpvInitialize(double, binSize);
280   CkpvInitialize(double, version);
281   CkpvAccess(binSize) = BIN_SIZE;
282   CkpvAccess(version) = VER;
283   if (CmiGetArgString(argv,"+binsize",&tmpStr))
284         sscanf(tmpStr,"%lf",&CkpvAccess(binSize));
285   if (CmiGetArgString(argv,"+version",&tmpStr))
286         sscanf(tmpStr,"%lf",&CkpvAccess(version));
287   _logPool = new SumLogPool(CkpvAccess(traceRoot));
288   execEp=INVALIDEP;
289
290   epThreshold = 0.001; 
291   if (CmiGetArgString(argv,"+epThreshold",&tmpStr))
292         sscanf(tmpStr,"%lf",&epThreshold);
293   epInterval = 0.001; 
294   if (CmiGetArgString(argv,"+epInterval",&tmpStr))
295         sscanf(tmpStr,"%lf",&epInterval);
296 }
297
298 void TraceSummary::traceClearEps(void)
299 {
300   _logPool->clearEps();
301 }
302
303 void TraceSummary::traceWriteSts(void)
304 {
305   if(CkMyPe()==0)
306       _logPool->writeSts();
307 }
308
309 void TraceSummary::traceClose(void)
310 {
311   if(CkMyPe()==0)
312       _logPool->writeSts();
313   if (TRACE_CHARM_PE()) {
314     CkpvAccess(_trace)->endComputation();
315     // destructor call the write()
316     delete _logPool;
317   }
318 }
319
320 void TraceSummary::beginExecute(envelope *e)
321 {
322   // no message means thread execution
323   if (e==NULL) {
324     beginExecute(-1,-1,_threadEP,-1);
325   }
326   else {
327     beginExecute(-1,-1,e->getEpIdx(),-1);
328   }  
329 }
330
331 void TraceSummary::beginExecute(int event,int msgType,int ep,int srcPe, int mlen)
332 {
333   if (execEp != INVALIDEP) {
334     CmiPrintf("Warning: TraceSummary two consecutive BEGIN_PROCESSING!\n");
335     return;
336   }
337
338   execEp=ep;
339   double t = TraceTimer();
340 //CmiPrintf("start: %f \n", start);
341
342   start = t;
343   double ts = binStart;
344   // fill gaps
345   while ((ts = ts + CkpvAccess(binSize)) < t)
346   {
347      _logPool->add(bin, CkMyPe());
348      bin=0.0;
349      binStart = ts;
350   }
351 }
352
353 void TraceSummary::endExecute(void)
354 {
355 //  if (!flag) return;
356   double t = TraceTimer();
357   double ts = start;
358   double nts = binStart;
359
360   if (execEp == INVALIDEP) {
361     CmiPrintf("Warning: TraceSummary END_PROCESSING without BEGIN_PROCESSING!\n");
362     return;
363   }
364
365   if (execEp != -1)
366   {
367     _logPool->setEp(execEp, t-ts);
368   }
369
370   while ((nts = nts + CkpvAccess(binSize)) < t)
371   {
372      bin += nts-ts;
373      binStart  = nts;
374      _logPool->add(bin, CkMyPe());
375      bin = 0;
376      ts = nts;
377   }
378   bin += t - ts;
379   execEp = INVALIDEP;
380 }
381
382 void TraceSummary::beginPack(void)
383 {
384     packstart = CmiWallTimer();
385 }
386
387 void TraceSummary::endPack(void)
388 {
389     _logPool->setEp(_packEP, CmiWallTimer() - packstart);
390 }
391
392 void TraceSummary::beginUnpack(void)
393 {
394     unpackstart = CmiWallTimer();
395 }
396
397 void TraceSummary::endUnpack(void)
398 {
399     _logPool->setEp(_unpackEP, CmiWallTimer()-unpackstart);
400 }
401
402 void TraceSummary::beginComputation(void)
403 {
404   if(CkMyRank()==0) {
405     _threadMsg = CkRegisterMsg("dummy_thread_msg", 0, 0, 0, 0);
406     _threadChare = CkRegisterChare("dummy_thread_chare", 0);
407     _threadEP = CkRegisterEp("dummy_thread_ep", 0, _threadMsg,_threadChare);
408
409     _packMsg = CkRegisterMsg("dummy_pack_msg", 0, 0, 0, 0);
410     _packChare = CkRegisterChare("dummy_pack_chare", 0);
411     _packEP = CkRegisterEp("dummy_pack_ep", 0, _packMsg,_packChare);
412
413     _unpackMsg = CkRegisterMsg("dummy_unpack_msg", 0, 0, 0, 0);
414     _unpackChare = CkRegisterChare("dummy_unpack_chare", 0);
415     _unpackEP = CkRegisterEp("dummy_unpack_ep", 0, _unpackMsg,_unpackChare);
416   }
417 }
418
419 void TraceSummary::endComputation(void)
420 {
421   if (msgNum==0) {
422 //CmiPrintf("Add at last: %d pe:%d time:%f msg:%d\n", index, CkMyPe(), bin, msgNum);
423      _logPool->add(bin, CkMyPe());
424      msgNum ++;
425
426      binStart  += CkpvAccess(binSize);
427      double t = TraceTimer();
428      double ts = binStart;
429      while (ts < t)
430      {
431        _logPool->add(bin, CkMyPe());
432        bin=0.0;
433        ts += CkpvAccess(binSize);
434      }
435   }
436 }
437
438 void TraceSummary::addEventType(int eventType)
439 {
440   _logPool->addEventType(eventType, TraceTimer());
441 }
442
443 void TraceSummary::startPhase(int phase)
444 {
445    _logPool->startPhase(phase);
446 }
447
448
449
450 /*@}*/