extend trace-summary +sumonly to be working when only partial log files are generated.
[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 #include "trace-summaryBOC.h"
15
16 #define DEBUGF(x)  // CmiPrintf x
17
18 #define VER   4.0
19
20 #define INVALIDEP     -2
21
22 CkpvStaticDeclare(TraceSummary*, _trace);
23 static int _numEvents = 0;
24 static int _threadMsg, _threadChare, _threadEP;
25 static int _packMsg, _packChare, _packEP;
26 static int _unpackMsg, _unpackChare, _unpackEP;
27 CkpvDeclare(double, binSize);
28 CkpvDeclare(double, version);
29
30 int sumonly = 0;
31
32 /**
33   For each TraceFoo module, _createTraceFoo() must be defined.
34   This function is called in _createTraces() generated in moduleInit.C
35 */
36 void _createTracesummary(char **argv)
37 {
38   DEBUGF(("%d createTraceSummary\n", CkMyPe()));
39   CkpvInitialize(TraceSummary*, _trace);
40   CkpvAccess(_trace) = new  TraceSummary(argv);
41   CkpvAccess(_traces)->addTrace(CkpvAccess(_trace));
42 }
43
44
45 /// function call for starting a phase in trace summary logs 
46 extern "C" 
47 void CkSummary_StartPhase(int phase)
48 {
49    CkpvAccess(_trace)->startPhase(phase);
50 }
51
52
53 /// function call for adding an event mark
54 extern "C" 
55 void CkSummary_MarkEvent(int eventType)
56 {
57    CkpvAccess(_trace)->addEventType(eventType);
58 }
59
60
61 PhaseEntry::PhaseEntry() 
62 {
63   for (int i=0; i<MAX_ENTRIES; i++) {
64     count[i] = 0;
65     times[i] = 0.0;
66     maxtimes[i] = 0.;
67   }
68 }
69
70 SumLogPool::~SumLogPool() 
71 {
72   if (!sumonly) {
73   write();
74   fclose(fp);
75   }
76   // free memory for mark
77   if (markcount > 0)
78   for (int i=0; i<MAX_MARKS; i++) {
79     for (int j=0; j<events[i].length(); j++)
80       delete events[i][j];
81   }
82   delete[] pool;
83   delete[] epInfo;
84 }
85
86 void SumLogPool::addEventType(int eventType, double time)
87 {
88    if (eventType <0 || eventType >= MAX_MARKS) {
89        CkPrintf("Invalid event type %d!\n", eventType);
90        return;
91    }
92    MarkEntry *e = new MarkEntry;
93    e->time = time;
94    events[eventType].push_back(e);
95    markcount ++;
96 }
97
98 SumLogPool::SumLogPool(char *pgm) : phaseTab(MAX_PHASES) 
99 {
100    if (TRACE_CHARM_PE() == 0) return;
101    int i;
102    poolSize = CkpvAccess(CtrLogBufSize);
103    if (poolSize % 2) poolSize++;        // make sure it is even
104    pool = new BinEntry[poolSize];
105    _MEMCHECK(pool);
106    numEntries = 0;
107    char pestr[10];
108    sprintf(pestr, "%d", CkMyPe());
109    int len = strlen(pgm) + strlen(".sum.") + strlen(pestr) + 1;
110    char *fname = new char[len+1];
111    sprintf(fname, "%s.%s.sum", pgm, pestr);
112    fp = NULL;
113    //CmiPrintf("TRACE: %s:%d\n", fname, errno);
114    if (!sumonly) {
115     do {
116       fp = fopen(fname, "w+");
117     } while (!fp && errno == EINTR);
118     delete[] fname;
119     if(!fp) {
120       CmiAbort("Cannot open Summary Trace File for writing...\n");
121     }
122    }
123
124    epSize = MAX_ENTRIES;
125    epInfo = new SumEntryInfo[epSize];
126    _MEMCHECK(epInfo);
127
128    // event
129    markcount = 0;
130
131    if (CkMyPe() == 0)
132    {
133     char *fname = new char[strlen(CkpvAccess(traceRoot))+strlen(".sum.sts")+1];
134     sprintf(fname, "%s.sum.sts", CkpvAccess(traceRoot));
135     stsfp = fopen(fname, "w+");
136     //CmiPrintf("File: %s \n", fname);
137     if(stsfp == 0)
138       CmiAbort("Cannot open summary sts file for writing.\n");
139     delete[] fname;
140    }
141 }
142
143 void SumLogPool::write(void) 
144 {
145   int i;
146   unsigned int j;
147
148   fprintf(fp, "ver:%3.1f %d/%d count:%d ep:%d interval:%e", CkpvAccess(version), CkMyPe(), CkNumPes(), numEntries, _numEntries, CkpvAccess(binSize));
149   if (CkpvAccess(version)>=3.0)
150   {
151     fprintf(fp, " phases:%d", phaseTab.numPhasesCalled());
152   }
153   fprintf(fp, "\n");
154
155   // write bin time
156 #if 1
157   int last=pool[0].getU();
158   pool[0].writeU(fp, last);
159   int count=1;
160   for(j=1; j<numEntries; j++) {
161     int u = pool[j].getU();
162     if (last == u) {
163       count++;
164     }
165     else {
166       if (count > 1) fprintf(fp, "+%d", count);
167       pool[j].writeU(fp, u);
168       last = u;
169       count = 1;
170     }
171   }
172   if (count > 1) fprintf(fp, "+%d", count);
173 #else
174   for(j=0; j<numEntries; j++) 
175       pool[j].write(fp);
176 #endif
177   fprintf(fp, "\n");
178
179   // write entry execution time
180   for (i=0; i<_numEntries; i++)
181     fprintf(fp, "%ld ", (long)(epInfo[i].epTime*1.0e6));
182   fprintf(fp, "\n");
183   // write entry function call times
184   for (i=0; i<_numEntries; i++)
185     fprintf(fp, "%d ", epInfo[i].epCount);
186   fprintf(fp, "\n");
187   // write max entry function execute times
188   fprintf(fp, "PE%d MaxEPTime: ", CkMyPe());
189   for (i=0; i<_numEntries; i++)
190     fprintf(fp, "%ld ", (long)(epInfo[i].epMaxTime*1.0e6));
191   fprintf(fp, "\n");
192   for (i=0; i<SumEntryInfo::HIST_SIZE; i++) {
193     for (j=0; j<_numEntries; j++) 
194       fprintf(fp, "%d ", epInfo[j].hist[i]);
195     fprintf(fp, "\n");
196   }
197   // write marks
198   if (CkpvAccess(version)>=2.0) 
199   {
200   fprintf(fp, "NumMarks: %d ", markcount);
201   for (i=0; i<MAX_MARKS; i++) {
202     for(int j=0; j<events[i].length(); j++)
203         fprintf(fp, "%d %f ", i, events[i][j]->time);
204   }
205   fprintf(fp, "\n");
206   }
207   // write phases
208   if (CkpvAccess(version)>=3.0)
209   {
210   phaseTab.write(fp);
211   }
212 }
213
214 void SumLogPool::writeSts(void)
215 {
216   fprintf(stsfp, "MACHINE %s\n",CMK_MACHINE_NAME);
217   fprintf(stsfp, "PROCESSORS %d\n", CkNumPes());
218   fprintf(stsfp, "TOTAL_CHARES %d\n", _numChares);
219   fprintf(stsfp, "TOTAL_EPS %d\n", _numEntries);
220   fprintf(stsfp, "TOTAL_MSGS %d\n", _numMsgs);
221   fprintf(stsfp, "TOTAL_PSEUDOS %d\n", 0);
222   fprintf(stsfp, "TOTAL_EVENTS %d\n", _numEvents);
223   int i;
224   for(i=0;i<_numChares;i++)
225     fprintf(stsfp, "CHARE %d %s\n", i, _chareTable[i]->name);
226   for(i=0;i<_numEntries;i++)
227     fprintf(stsfp, "ENTRY CHARE %d %s %d %d\n", i, _entryTable[i]->name,
228                  _entryTable[i]->chareIdx, _entryTable[i]->msgIdx);
229   for(i=0;i<_numMsgs;i++)
230     fprintf(stsfp, "MESSAGE %d %d\n", i, _msgTable[i]->size);
231   for(i=0;i<_numEvents;i++)
232     fprintf(stsfp, "EVENT %d Event%d\n", i, i);
233   fprintf(stsfp, "END\n");
234   fclose(stsfp);
235 }
236
237 void SumLogPool::add(double time, int pe) 
238 {
239   new (&pool[numEntries++]) BinEntry(time);
240   if(poolSize==numEntries) shrink();
241 }
242
243 void SumLogPool::setEp(int epidx, double time) 
244 {
245   if (epidx >= epSize) {
246         CmiAbort("Too many entry points!!\n");
247   }
248   //CmiPrintf("set EP: %d %e \n", epidx, time);
249   epInfo[epidx].setTime(time);
250   // set phase table counter
251   phaseTab.setEp(epidx, time);
252 }
253
254 void SumLogPool::shrink(void)
255 {
256 //  double t = CmiWallTimer();
257
258   int entries = numEntries/2;
259   for (int i=0; i<entries; i++)
260   {
261      pool[i].setTime(pool[i*2].getTime() + pool[i*2+1].getTime());
262   }
263   numEntries = entries;
264   CkpvAccess(binSize) *= 2;
265
266 //CkPrintf("Shrinked binsize: %f entries:%d takes %fs!!!!\n", CkpvAccess(binSize), numEntries, CmiWallTimer()-t);
267 }
268
269 int  BinEntry::getU() { 
270   return (int)(time * 100.0 / CkpvAccess(binSize)); 
271 }
272
273 void BinEntry::write(FILE* fp)
274 {
275   int per = (int)(time * 100.0 / CkpvAccess(binSize));
276   fprintf(fp, "%4d", per);
277 }
278
279 void BinEntry::writeU(FILE* fp, int u)
280 {
281   fprintf(fp, "%4d", u);
282 }
283
284 TraceSummary::TraceSummary(char **argv):curevent(0),binStart(0.0),bin(0.0),msgNum(0)
285 {
286   char *tmpStr;
287   CkpvInitialize(double, binSize);
288   CkpvInitialize(double, version);
289   CkpvAccess(binSize) = BIN_SIZE;
290   CkpvAccess(version) = VER;
291   if (CmiGetArgString(argv,"+binsize",&tmpStr))
292         sscanf(tmpStr,"%lf",&CkpvAccess(binSize));
293   if (CmiGetArgString(argv,"+version",&tmpStr))
294         sscanf(tmpStr,"%lf",&CkpvAccess(version));
295
296   epThreshold = 0.001; 
297   if (CmiGetArgString(argv,"+epThreshold",&tmpStr))
298         sscanf(tmpStr,"%lf",&epThreshold);
299   epInterval = 0.001; 
300   if (CmiGetArgString(argv,"+epInterval",&tmpStr))
301         sscanf(tmpStr,"%lf",&epInterval);
302
303   sumonly = CmiGetArgFlag(argv, "+sumonly");
304
305   _logPool = new SumLogPool(CkpvAccess(traceRoot));
306   execEp=INVALIDEP;
307 }
308
309 void TraceSummary::traceClearEps(void)
310 {
311   _logPool->clearEps();
312 }
313
314 void TraceSummary::traceWriteSts(void)
315 {
316   if(CkMyPe()==0)
317       _logPool->writeSts();
318 }
319
320 void TraceSummary::traceClose(void)
321 {
322   if(CkMyPe()==0)
323       _logPool->writeSts();
324   if (TRACE_CHARM_PE()) {
325     CkpvAccess(_trace)->endComputation();
326     // destructor call the write()
327     delete _logPool;
328   }
329 }
330
331 void TraceSummary::beginExecute(envelope *e)
332 {
333   // no message means thread execution
334   if (e==NULL) {
335     beginExecute(-1,-1,_threadEP,-1);
336   }
337   else {
338     beginExecute(-1,-1,e->getEpIdx(),-1);
339   }  
340 }
341
342 void TraceSummary::beginExecute(int event,int msgType,int ep,int srcPe, int mlen)
343 {
344   if (execEp != INVALIDEP) {
345     CmiPrintf("Warning: TraceSummary two consecutive BEGIN_PROCESSING!\n");
346     return;
347   }
348
349   execEp=ep;
350   double t = TraceTimer();
351 //CmiPrintf("start: %f \n", start);
352
353   start = t;
354   double ts = binStart;
355   // fill gaps
356   while ((ts = ts + CkpvAccess(binSize)) < t)
357   {
358      _logPool->add(bin, CkMyPe());
359      bin=0.0;
360      binStart = ts;
361   }
362 }
363
364 void TraceSummary::endExecute(void)
365 {
366 //  if (!flag) return;
367   double t = TraceTimer();
368   double ts = start;
369   double nts = binStart;
370
371   if (execEp == INVALIDEP) {
372     CmiPrintf("Warning: TraceSummary END_PROCESSING without BEGIN_PROCESSING!\n");
373     return;
374   }
375
376   if (execEp != -1)
377   {
378     _logPool->setEp(execEp, t-ts);
379   }
380
381   while ((nts = nts + CkpvAccess(binSize)) < t)
382   {
383      bin += nts-ts;
384      binStart  = nts;
385      _logPool->add(bin, CkMyPe());
386      bin = 0;
387      ts = nts;
388   }
389   bin += t - ts;
390   execEp = INVALIDEP;
391 }
392
393 void TraceSummary::beginPack(void)
394 {
395     packstart = CmiWallTimer();
396 }
397
398 void TraceSummary::endPack(void)
399 {
400     _logPool->setEp(_packEP, CmiWallTimer() - packstart);
401 }
402
403 void TraceSummary::beginUnpack(void)
404 {
405     unpackstart = CmiWallTimer();
406 }
407
408 void TraceSummary::endUnpack(void)
409 {
410     _logPool->setEp(_unpackEP, CmiWallTimer()-unpackstart);
411 }
412
413 void TraceSummary::beginComputation(void)
414 {
415   if(CkMyRank()==0) {
416     _threadMsg = CkRegisterMsg("dummy_thread_msg", 0, 0, 0, 0);
417     _threadChare = CkRegisterChare("dummy_thread_chare", 0);
418     _threadEP = CkRegisterEp("dummy_thread_ep", 0, _threadMsg,_threadChare);
419
420     _packMsg = CkRegisterMsg("dummy_pack_msg", 0, 0, 0, 0);
421     _packChare = CkRegisterChare("dummy_pack_chare", 0);
422     _packEP = CkRegisterEp("dummy_pack_ep", 0, _packMsg,_packChare);
423
424     _unpackMsg = CkRegisterMsg("dummy_unpack_msg", 0, 0, 0, 0);
425     _unpackChare = CkRegisterChare("dummy_unpack_chare", 0);
426     _unpackEP = CkRegisterEp("dummy_unpack_ep", 0, _unpackMsg,_unpackChare);
427   }
428 }
429
430 void TraceSummary::endComputation(void)
431 {
432   static int done = 0;
433   if (done) return;
434   done = 1;
435   if (msgNum==0) {
436 //CmiPrintf("Add at last: %d pe:%d time:%f msg:%d\n", index, CkMyPe(), bin, msgNum);
437      _logPool->add(bin, CkMyPe());
438      msgNum ++;
439
440      binStart  += CkpvAccess(binSize);
441      double t = TraceTimer();
442      double ts = binStart;
443      while (ts < t)
444      {
445        _logPool->add(bin, CkMyPe());
446        bin=0.0;
447        ts += CkpvAccess(binSize);
448      }
449   }
450 }
451
452 void TraceSummary::addEventType(int eventType)
453 {
454   _logPool->addEventType(eventType, TraceTimer());
455 }
456
457 void TraceSummary::startPhase(int phase)
458 {
459    _logPool->startPhase(phase);
460 }
461
462
463 /// for TraceSummaryBOC
464
465 CkGroupID traceSummaryGID;
466
467 void TraceSummaryBOC::askSummary()
468 {
469   if (CkpvAccess(_trace) == NULL) return;
470
471 #if 0
472 #if CMK_TRACE_IN_CHARM
473   TRACE_CHARM_PE() = 0;
474 #endif
475 #endif
476
477   int n=0;
478   BinEntry *bins = NULL;
479   int traced = TRACE_CHARM_PE();
480   if (traced) {
481   CkpvAccess(_trace)->endComputation();
482   n = CkpvAccess(_trace)->pool()->getNumEntries();
483   bins = CkpvAccess(_trace)->pool()->bins();
484 #if 1
485   CmiPrintf("askSummary on [%d] numEntried=%d\n", CkMyPe(), n);
486 #if 0
487   for (int i=0; i<n; i++) 
488     CmiPrintf("%4d", bins[i].getU());
489   CmiPrintf("\n");
490 #endif
491 #endif
492   }
493   CProxy_TraceSummaryBOC p(traceSummaryGID);
494   p[0].sendSummaryBOC(traced, n, bins);
495 }
496
497 extern "C" void _CkExit();
498
499 void TraceSummaryBOC::sendSummaryBOC(int traced, int n, BinEntry *b)
500 {
501   int i;
502   if (CkpvAccess(_trace) == NULL) return;
503
504   CkAssert(CkMyPe() == 0);
505
506 #if 0
507 #if CMK_TRACE_IN_CHARM
508   TRACE_CHARM_PE() = 0;
509 #endif
510 #endif
511
512   count ++;
513   if (bins == NULL) {
514     nBins = CkpvAccess(_trace)->pool()->getNumEntries();
515     bins = new BinEntry[nBins];
516   }
517   if (traced) {
518     nTracedPEs ++;
519     if (n>nBins) n = nBins;
520     for (i=0; i<n; i++) {
521       bins[i].Time() += b[i].Time();
522     }
523   }
524   if (count == CkNumPes()) {
525     write();
526     _CkExit();
527   }
528 }
529
530 void TraceSummaryBOC::write(void) 
531 {
532   int i;
533   unsigned int j;
534
535   char *fname = new char[strlen(CkpvAccess(traceRoot))+strlen(".sum")+1];
536   sprintf(fname, "%s.sum", CkpvAccess(traceRoot));
537   FILE *sumfp = fopen(fname, "w+");
538   //CmiPrintf("File: %s \n", fname);
539   if(sumfp == 0)
540       CmiAbort("Cannot open summary sts file for writing.\n");
541   delete[] fname;
542
543   fprintf(sumfp, "ver:%3.1f %d/%d count:%d ep:%d interval:%e numTracedPE:%d", CkpvAccess(version), CkMyPe(), CkNumPes(), nBins, _numEntries, CkpvAccess(binSize), nTracedPEs);
544   fprintf(sumfp, "\n");
545
546   // write bin time
547 #if 0
548   int last=pool[0].getU();
549   pool[0].writeU(fp, last);
550   int count=1;
551   for(j=1; j<numEntries; j++) {
552     int u = pool[j].getU();
553     if (last == u) {
554       count++;
555     }
556     else {
557       if (count > 1) fprintf(fp, "+%d", count);
558       pool[j].writeU(fp, u);
559       last = u;
560       count = 1;
561     }
562   }
563   if (count > 1) fprintf(fp, "+%d", count);
564 #else
565   for(j=0; j<nBins; j++) {
566     bins[j].Time() /= nTracedPEs;
567     bins[j].write(sumfp);
568   }
569 #endif
570   fprintf(sumfp, "\n");
571   fclose(sumfp);
572
573 }
574
575 extern "C" void CombineSummary()
576 {
577 CmiPrintf("[%d] CombineSummary called!\n", CkMyPe());
578   if (sumonly) CProxy_TraceSummaryBOC(traceSummaryGID).askSummary();
579   else CkExit();
580 }
581
582 void initTraceSummaryBOC()
583 {
584   if (CkMyRank() == 0) {
585     registerExitFn(CombineSummary);
586   }
587 }
588
589 #include "TraceSummary.def.h"
590
591
592 /*@}*/