4ab10b269ad2ce67009657ad8b7401ed0318d286
[charm.git] / src / ck-perf / trace-projections.C
1 /*****************************************************************************
2  * $Source$
3  * $Author$
4  * $Date$
5  * $Revision$
6  *****************************************************************************/
7
8
9 /**
10  * \addtogroup CkPerf
11 */
12 /*@{*/
13
14 #include <string.h>
15
16 #include "charm++.h"
17 #include "trace-projections.h"
18 #include "trace-projectionsBOC.h"
19
20 #define DEBUGF(x)           // CmiPrintf x
21
22 #define DefaultLogBufSize      1000000
23
24 // **CW** Simple delta encoding implementation
25 // delta encoding is on by default. It may be turned off later in
26 // the runtime.
27 int deltaLog;
28 int nonDeltaLog;
29
30 int checknested=0;              // check illegal nested begin/end execute 
31
32 CkGroupID traceProjectionsGID;
33
34 CkpvStaticDeclare(TraceProjections*, _trace);
35 CtvStaticDeclare(int,curThreadEvent);
36
37 CkpvDeclare(bool, useOutlierAnalysis);
38 CkpvDeclare(int, CtrLogBufSize);
39
40 typedef CkVec<char *>  usrEventVec;
41 CkpvStaticDeclare(usrEventVec, usrEventlist);
42 class UsrEvent {
43 public:
44   int e;
45   char *str;
46   UsrEvent(int _e, char* _s): e(_e),str(_s) {}
47 };
48 CkpvStaticDeclare(CkVec<UsrEvent *>*, usrEvents);
49
50
51
52 /// Disable the outputting of the trace logs
53 void disableTraceLogOutput()
54
55   CkpvAccess(_trace)->setWriteData(false);
56 }
57
58 /// Enable the outputting of the trace logs
59 void enableTraceLogOutput()
60 {
61   CkpvAccess(_trace)->setWriteData(true);
62 }
63
64
65
66 #ifdef CMK_OPTIMIZE
67 static int warned=0;
68 #define OPTIMIZED_VERSION       \
69         if (!warned) { warned=1;        \
70         CmiPrintf("\n\n!!!! Warning: traceUserEvent not available in optimized version!!!!\n\n\n"); }
71 #else
72 #define OPTIMIZED_VERSION /*empty*/
73 #endif
74
75 /*
76 On T3E, we need to have file number control by open/close files only when needed.
77 */
78 #if CMK_TRACE_LOGFILE_NUM_CONTROL
79   #define OPEN_LOG openLog("a");
80   #define CLOSE_LOG closeLog();
81 #else
82   #define OPEN_LOG
83   #define CLOSE_LOG
84 #endif
85
86 #if CMK_HAS_COUNTER_PAPI
87 int numPAPIEvents = 2;
88 int papiEvents[] = { PAPI_L3_DCM, PAPI_FP_OPS };
89 char *papiEventNames[] = {"PAPI_L3_DCM", "PAPI_FP_OPS"};
90 #endif
91
92 /**
93   For each TraceFoo module, _createTraceFoo() must be defined.
94   This function is called in _createTraces() generated in moduleInit.C
95 */
96 void _createTraceprojections(char **argv)
97 {
98   DEBUGF(("%d createTraceProjections\n", CkMyPe()));
99   CkpvInitialize(CkVec<char *>, usrEventlist);
100   CkpvInitialize(CkVec<UsrEvent *>*, usrEvents);
101   CkpvAccess(usrEvents) = new CkVec<UsrEvent *>();
102 #if CMK_BLUEGENE_CHARM
103   // CthRegister does not call the constructor
104 //  CkpvAccess(usrEvents) = CkVec<UsrEvent *>();
105 #endif
106   CkpvInitialize(TraceProjections*, _trace);
107   CkpvAccess(_trace) = new  TraceProjections(argv);
108   CkpvAccess(_traces)->addTrace(CkpvAccess(_trace));
109 }
110  
111 /* ****** CW TEMPORARY LOCATION ***** Support for thread listeners */
112
113 struct TraceThreadListener {
114   struct CthThreadListener base;
115   int event;
116   int msgType;
117   int ep;
118   int srcPe;
119   int ml;
120   CmiObjId idx;
121 };
122
123
124 extern "C"
125 void traceThreadListener_suspend(struct CthThreadListener *l)
126 {
127   TraceThreadListener *a=(TraceThreadListener *)l;
128   /* here, we activate the appropriate trace codes for the appropriate
129      registered modules */
130   traceSuspend();
131 }
132
133 extern "C"
134 void traceThreadListener_resume(struct CthThreadListener *l) 
135 {
136   TraceThreadListener *a=(TraceThreadListener *)l;
137   /* here, we activate the appropriate trace codes for the appropriate
138      registered modules */
139   _TRACE_BEGIN_EXECUTE_DETAILED(a->event,a->msgType,a->ep,a->srcPe,a->ml,
140                                 CthGetThreadID(a->base.thread));
141   a->event=-1;
142   a->srcPe=CkMyPe(); /* potential lie to migrated threads */
143   a->ml=0;
144 }
145
146 extern "C"
147 void traceThreadListener_free(struct CthThreadListener *l) 
148 {
149   TraceThreadListener *a=(TraceThreadListener *)l;
150   delete a;
151 }
152
153 void TraceProjections::traceAddThreadListeners(CthThread tid, envelope *e)
154 {
155 #ifndef CMK_OPTIMIZE
156   /* strip essential information from the envelope */
157   TraceThreadListener *a= new TraceThreadListener;
158   
159   a->base.suspend=traceThreadListener_suspend;
160   a->base.resume=traceThreadListener_resume;
161   a->base.free=traceThreadListener_free;
162   a->event=e->getEvent();
163   a->msgType=e->getMsgtype();
164   a->ep=e->getEpIdx();
165   a->srcPe=e->getSrcPe();
166   a->ml=e->getTotalsize();
167
168   CthAddListener(tid, (CthThreadListener *)a);
169 #endif
170 }
171
172 void LogPool::openLog(const char *mode)
173 {
174 #if CMK_PROJECTIONS_USE_ZLIB
175   if(compressed) {
176     if (nonDeltaLog) {
177       do {
178         zfp = gzopen(fname, mode);
179       } while (!zfp && (errno == EINTR || errno == EMFILE));
180       if(!zfp) CmiAbort("Cannot open Projections Compressed Non Delta Trace File for writing...\n");
181     }
182     if (deltaLog) {
183       do {
184         deltazfp = gzopen(dfname, mode);
185       } while (!deltazfp && (errno == EINTR || errno == EMFILE));
186       if (!deltazfp) 
187         CmiAbort("Cannot open Projections Compressed Delta Trace File for writing...\n");
188     }
189   } else {
190     if (nonDeltaLog) {
191       do {
192         fp = fopen(fname, mode);
193       } while (!fp && (errno == EINTR || errno == EMFILE));
194       if (!fp) {
195         CkPrintf("[%d] Attempting to open file [%s]\n",CkMyPe(),fname);
196         CmiAbort("Cannot open Projections Non Delta Trace File for writing...\n");
197       }
198     }
199     if (deltaLog) {
200       do {
201         deltafp = fopen(dfname, mode);
202       } while (!deltafp && (errno == EINTR || errno == EMFILE));
203       if (!deltafp) 
204         CmiAbort("Cannot open Projections Delta Trace File for writing...\n");
205     }
206   }
207 #else
208   if (nonDeltaLog) {
209     do {
210       fp = fopen(fname, mode);
211     } while (!fp && (errno == EINTR || errno == EMFILE));
212     if (!fp) {
213       CkPrintf("[%d] Attempting to open file [%s]\n",CkMyPe(),fname);
214       CmiAbort("Cannot open Projections Non Delta Trace File for writing...\n");
215     }
216   }
217   if (deltaLog) {
218     do {
219       deltafp = fopen(dfname, mode);
220     } while (!deltafp && (errno == EINTR || errno == EMFILE));
221     if(!deltafp) 
222       CmiAbort("Cannot open Projections Delta Trace File for writing...\n");
223   }
224 #endif
225 }
226
227 void LogPool::closeLog(void)
228 {
229 #if CMK_PROJECTIONS_USE_ZLIB
230   if(compressed) {
231     if (nonDeltaLog) gzclose(zfp);
232     if (deltaLog) gzclose(deltazfp);
233     return;
234   }
235 #endif
236   if (nonDeltaLog) { 
237 #if !defined(_WIN32) || defined(__CYGWIN__)
238     fsync(fileno(fp)); 
239 #endif
240     fclose(fp); 
241   }
242   if (deltaLog)  { 
243 #if !defined(_WIN32) || defined(__CYGWIN__)
244     fsync(fileno(deltafp)); 
245 #endif
246     fclose(deltafp);  
247   }
248 }
249
250 LogPool::LogPool(char *pgm) {
251   pool = new LogEntry[CkpvAccess(CtrLogBufSize)];
252   // defaults to writing data (no outlier changes)
253   writeData = true;
254   numEntries = 0;
255   // **CW** for simple delta encoding
256   prevTime = 0.0;
257   timeErr = 0.0;
258   globalEndTime = 0.0;
259   headerWritten = 0;
260   fileCreated = false;
261   poolSize = CkpvAccess(CtrLogBufSize);
262   pgmname = new char[strlen(pgm)+1];
263   strcpy(pgmname, pgm);
264 }
265
266 void LogPool::createFile(const char *fix)
267 {
268   if (fileCreated) {
269     return;
270   }
271   char pestr[10];
272   sprintf(pestr, "%d", CkMyPe());
273 #if CMK_PROJECTIONS_USE_ZLIB
274   int len;
275   if(compressed)
276     len = strlen(pgmname)+strlen(fix)+strlen(".logold")+strlen(pestr)+strlen(".gz")+3;
277   else
278     len = strlen(pgmname)+strlen(fix)+strlen(".logold")+strlen(pestr)+3;
279 #else
280   int len = strlen(pgmname)+strlen(fix)+strlen(".logold")+strlen(pestr)+3;
281 #endif
282   if (nonDeltaLog) {
283     fname = new char[len];
284   }
285   if (deltaLog) {
286     dfname = new char[len];
287   }
288 #if CMK_PROJECTIONS_USE_ZLIB
289   if(compressed) {
290     if (deltaLog && nonDeltaLog) {
291       sprintf(fname, "%s%s.%s.logold.gz", pgmname, fix, pestr);
292       sprintf(dfname, "%s%s.%s.log.gz", pgmname, fix, pestr);
293     } else {
294       if (nonDeltaLog) {
295         sprintf(fname, "%s%s.%s.log.gz", pgmname, fix, pestr);
296       } else {
297         sprintf(dfname, "%s%s.%s.log.gz", pgmname, fix, pestr);
298       }
299     }
300   } else {
301     if (deltaLog && nonDeltaLog) {
302       sprintf(fname, "%s%s.%s.logold", pgmname, fix, pestr);
303       sprintf(dfname, "%s%s.%s.log", pgmname, fix, pestr);
304     } else {
305       if (nonDeltaLog) {
306         sprintf(fname, "%s%s.%s.log", pgmname, fix, pestr);
307       } else {
308         sprintf(dfname, "%s%s.%s.log", pgmname, fix, pestr);
309       }
310     }
311   }
312 #else
313   if (deltaLog && nonDeltaLog) {
314     sprintf(fname, "%s%s.%s.logold", pgmname, fix, pestr);
315     sprintf(dfname, "%s%s.%s.log", pgmname, fix, pestr);
316   } else {
317     if (nonDeltaLog) {
318       sprintf(fname, "%s%s.%s.log", pgmname, fix, pestr);
319     } else {
320       sprintf(dfname, "%s%s.%s.log", pgmname, fix, pestr);
321     }
322   }
323 #endif
324   fileCreated = true;
325   openLog("w+");
326   CLOSE_LOG 
327 }
328
329 void LogPool::createSts(const char *fix)
330 {
331   CkAssert(CkMyPe() == 0);
332   // create the sts file
333   char *fname = new char[strlen(CkpvAccess(traceRoot))+strlen(fix)+strlen(".sts")+2];
334   sprintf(fname, "%s%s.sts", CkpvAccess(traceRoot), fix);
335   do
336     {
337       stsfp = fopen(fname, "w");
338     } while (!stsfp && (errno == EINTR || errno == EMFILE));
339   if(stsfp==0)
340     CmiAbort("Cannot open projections sts file for writing.\n");
341   delete[] fname;
342 }  
343
344 void LogPool::createRC()
345 {
346   // create the projections rc file.
347   fname = 
348     new char[strlen(CkpvAccess(traceRoot))+strlen(".projrc")+1];
349   sprintf(fname, "%s.projrc", CkpvAccess(traceRoot));
350   do {
351     rcfp = fopen(fname, "w");
352   } while (!rcfp && (errno == EINTR || errno == EMFILE));
353   if (rcfp==0) {
354     CmiAbort("Cannot open projections configuration file for writing.\n");
355   }
356   delete[] fname;
357 }
358
359 LogPool::~LogPool() 
360 {
361   if (writeData) {
362     writeLog();
363 #if !CMK_TRACE_LOGFILE_NUM_CONTROL
364     closeLog();
365 #endif
366   }
367
368 #if CMK_BLUEGENE_CHARM
369   extern int correctTimeLog;
370   if (correctTimeLog) {
371     createFile("-bg");
372     if (CkMyPe() == 0) {
373       createSts("-bg");
374     }
375     writeHeader();
376     if (CkMyPe() == 0) writeSts(NULL);
377     postProcessLog();
378   }
379 #endif
380
381   delete[] pool;
382   delete [] fname;
383 }
384
385 void LogPool::writeHeader()
386 {
387   if (headerWritten) return;
388   headerWritten = 1;
389   if(!binary) {
390 #if CMK_PROJECTIONS_USE_ZLIB
391     if(compressed) {
392       if (nonDeltaLog) {
393         gzprintf(zfp, "PROJECTIONS-RECORD %d\n", numEntries);
394       }
395       if (deltaLog) {
396         gzprintf(deltazfp, "PROJECTIONS-RECORD %d DELTA\n", numEntries);
397       }
398     } 
399     else /* else clause is below... */
400 #endif
401     /*... may hang over from else above */ {
402       if (nonDeltaLog) {
403         fprintf(fp, "PROJECTIONS-RECORD %d\n", numEntries);
404       }
405       if (deltaLog) {
406         fprintf(deltafp, "PROJECTIONS-RECORD %d DELTA\n", numEntries);
407       }
408     }
409   }
410   else { // binary
411       if (nonDeltaLog) {
412         fwrite(&numEntries,sizeof(numEntries),1,fp);
413       }
414       if (deltaLog) {
415         fwrite(&numEntries,sizeof(numEntries),1,deltafp);
416       }
417   }
418 }
419
420 void LogPool::writeLog(void)
421 {
422   createFile();
423   OPEN_LOG
424   writeHeader();
425   if (nonDeltaLog) write(0);
426   if (deltaLog) write(1);
427   CLOSE_LOG
428 }
429
430 void LogPool::write(int writedelta) 
431 {
432   // **CW** Simple delta encoding implementation
433   // prevTime has to be maintained as an object variable because
434   // LogPool::write may be called several times depending on the
435   // +logsize value.
436   PUP::er *p = NULL;
437   if (binary) {
438     p = new PUP::toDisk(writedelta?deltafp:fp);
439   }
440 #if CMK_PROJECTIONS_USE_ZLIB
441   else if (compressed) {
442     p = new toProjectionsGZFile(writedelta?deltazfp:zfp);
443   }
444 #endif
445   else {
446     p = new toProjectionsFile(writedelta?deltafp:fp);
447   }
448   CmiAssert(p);
449   for(UInt i=0; i<numEntries; i++) {
450     if (!writedelta) {
451       pool[i].pup(*p);
452     }
453     else {      // delta
454       double time = pool[i].time;
455       if (pool[i].type != BEGIN_COMPUTATION && pool[i].type != END_COMPUTATION)
456       {
457         double timeDiff = (time-prevTime)*1.0e6;
458         UInt intTimeDiff = (UInt)timeDiff;
459         timeErr += timeDiff - intTimeDiff; /* timeErr is never >= 2.0 */
460         if (timeErr > 1.0) {
461           timeErr -= 1.0;
462           intTimeDiff++;
463         }
464         pool[i].time = intTimeDiff/1.0e6;
465       }
466       pool[i].pup(*p);
467       pool[i].time = time;      // restore time value
468       prevTime = time;
469     }
470   }
471   delete p;
472 }
473
474 void LogPool::writeSts(void)
475 {
476   // for whining compilers
477   int i;
478   char name[30];
479   // generate an automatic unique ID for each log
480   fprintf(stsfp, "PROJECTIONS_ID %s\n", "");
481   fprintf(stsfp, "VERSION %s\n", PROJECTION_VERSION);
482 #if CMK_HAS_COUNTER_PAPI
483   fprintf(stsfp, "TOTAL_PAPI_EVENTS %d\n", numPAPIEvents);
484   // for now, use i, next time use papiEvents[i].
485   // **CW** papi event names is a hack.
486   for (i=0;i<numPAPIEvents;i++) {
487     fprintf(stsfp, "PAPI_EVENT %d %s\n", i, papiEventNames[i]);
488   }
489 #endif
490   traceWriteSTS(stsfp,CkpvAccess(usrEvents)->length());
491   for(i=0;i<CkpvAccess(usrEvents)->length();i++){
492     fprintf(stsfp, "EVENT %d %s\n", (*CkpvAccess(usrEvents))[i]->e, (*CkpvAccess(usrEvents))[i]->str);
493   }     
494 }
495
496 void LogPool::writeSts(TraceProjections *traceProj){
497   writeSts();
498   if (traceProj != NULL) {
499     CkHashtableIterator  *funcIter = traceProj->getfuncIterator();
500     funcIter->seekStart();
501     int numFuncs = traceProj->getFuncNumber();
502     fprintf(stsfp,"TOTAL_FUNCTIONS %d \n",numFuncs);
503     while(funcIter->hasNext()) {
504       StrKey *key;
505       int *obj = (int *)funcIter->next((void **)&key);
506       fprintf(stsfp,"FUNCTION %d %s \n",*obj,key->getStr());
507     }
508   }
509   fprintf(stsfp, "END\n");
510   fclose(stsfp);
511 }
512
513 void LogPool::writeRC(void)
514 {
515   CkAssert(CkMyPe() == 0);
516   fprintf(rcfp,"RC_GLOBAL_END_TIME %lld\n",
517           (CMK_TYPEDEF_UINT8)(1.0e6*globalEndTime));
518   if (CkpvAccess(useOutlierAnalysis)) {
519     fprintf(rcfp,"RC_OUTLIER_FILTERED true\n");
520   } else {
521     fprintf(rcfp,"RC_OUTLIER_FILTERED false\n");
522   }       
523   fclose(rcfp);
524 }
525
526
527 #if CMK_BLUEGENE_CHARM
528 static void updateProjLog(void *data, double t, double recvT, void *ptr)
529 {
530   LogEntry *log = (LogEntry *)data;
531   FILE *fp = *(FILE **)ptr;
532   log->time = t;
533   log->recvTime = recvT<0.0?0:recvT;
534 //  log->write(fp);
535   toProjectionsFile p(fp);
536   log->pup(p);
537 }
538 #endif
539
540 // flush log entries to disk
541 void LogPool::flushLogBuffer()
542 {
543   if (numEntries) {
544     double writeTime = TraceTimer();
545     writeLog();
546     numEntries = 0;
547     new (&pool[numEntries++]) LogEntry(writeTime, BEGIN_INTERRUPT);
548     new (&pool[numEntries++]) LogEntry(TraceTimer(), END_INTERRUPT);
549   }
550 }
551
552 void LogPool::add(UChar type, UShort mIdx, UShort eIdx,
553                   double time, int event, int pe, int ml, CmiObjId *id, 
554                   double recvT, double cpuT, int numPe)
555 {
556   new (&pool[numEntries++])
557     LogEntry(time, type, mIdx, eIdx, event, pe, ml, id, recvT, cpuT, numPe);
558   if(poolSize==numEntries) {
559     flushLogBuffer();
560 #if CMK_BLUEGENE_CHARM
561     extern int correctTimeLog;
562     if (correctTimeLog) CmiAbort("I/O interrupt!\n");
563 #endif
564   }
565 #if CMK_BLUEGENE_CHARM
566   switch (type) {
567     case BEGIN_PROCESSING:
568       pool[numEntries-1].recvTime = BgGetRecvTime();
569     case END_PROCESSING:
570     case BEGIN_COMPUTATION:
571     case END_COMPUTATION:
572     case CREATION:
573     case BEGIN_PACK:
574     case END_PACK:
575     case BEGIN_UNPACK:
576     case END_UNPACK:
577     case USER_EVENT_PAIR:
578       bgAddProjEvent(&pool[numEntries-1], numEntries-1, time, updateProjLog, &fp, BG_EVENT_PROJ);
579   }
580 #endif
581 }
582
583 void LogPool::add(UChar type,double time,UShort funcID,int lineNum,char *fileName){
584 #ifndef CMK_BLUEGENE_CHARM
585   new (&pool[numEntries++])
586         LogEntry(time,type,funcID,lineNum,fileName);
587   if(poolSize == numEntries){
588     flushLogBuffer();
589   }
590 #endif  
591 }
592
593
594   
595 void LogPool::addMemoryUsage(unsigned char type,double time,double memUsage){
596 #ifndef CMK_BLUEGENE_CHARM
597   new (&pool[numEntries++])
598         LogEntry(type,time,memUsage);
599   if(poolSize == numEntries){
600     flushLogBuffer();
601   }
602 #endif  
603         
604 }  
605
606
607
608 void LogPool::addUserSupplied(int data){
609         // add an event
610         add(USER_SUPPLIED, 0, 0, TraceTimer(), -1, -1, 0, 0, 0, 0, 0 );
611
612         // set the user supplied value for the previously created event 
613         pool[numEntries-1].setUserSuppliedData(data);
614   }
615
616
617 void LogPool::addUserSuppliedNote(char *note){
618         // add an event
619         add(USER_SUPPLIED_NOTE, 0, 0, TraceTimer(), -1, -1, 0, 0, 0, 0, 0 );
620
621         // set the user supplied note for the previously created event 
622         pool[numEntries-1].setUserSuppliedNote(note);
623   }
624
625 void LogPool::addUserSuppliedBracketedNote(char *note, int eventID, double bt, double et){
626   //CkPrintf("LogPool::addUserSuppliedBracketedNote eventID=%d\n", eventID);
627 #ifndef CMK_BLUEGENE_CHARM
628   new (&pool[numEntries++])
629         LogEntry(bt, et, USER_SUPPLIED_BRACKETED_NOTE, note, eventID);
630   if(poolSize == numEntries){
631     flushLogBuffer();
632   }
633 #endif  
634 }
635
636
637 /* **CW** Not sure if this is the right thing to do. Feels more like
638    a hack than a solution to Sameer's request to add the destination
639    processor information to multicasts and broadcasts.
640
641    In the unlikely event this method is used for Broadcasts as well,
642    pelist == NULL will be used to indicate a global broadcast with 
643    num PEs.
644 */
645 void LogPool::addCreationMulticast(UShort mIdx, UShort eIdx, double time,
646                                    int event, int pe, int ml, CmiObjId *id,
647                                    double recvT, int numPe, int *pelist)
648 {
649   new (&pool[numEntries++])
650     LogEntry(time, mIdx, eIdx, event, pe, ml, id, recvT, numPe, pelist);
651   if(poolSize==numEntries) {
652     flushLogBuffer();
653   }
654 }
655
656 void LogPool::postProcessLog()
657 {
658 #if CMK_BLUEGENE_CHARM
659   bgUpdateProj(1);   // event type
660 #endif
661 }
662
663 // /** Constructor for a multicast log entry */
664 // 
665 //  THIS WAS MOVED TO trace-projections.h with the other constructors
666 // 
667 // LogEntry::LogEntry(double tm, unsigned short m, unsigned short e, int ev, int p,
668 //           int ml, CmiObjId *d, double rt, int numPe, int *pelist) 
669 // {
670 //     type = CREATION_MULTICAST; mIdx = m; eIdx = e; event = ev; pe = p; time = tm; msglen = ml;
671 //     if (d) id = *d; else {id.id[0]=id.id[1]=id.id[2]=id.id[3]=-1; };
672 //     recvTime = rt; 
673 //     numpes = numPe;
674 //     userSuppliedNote = NULL;
675 //     if (pelist != NULL) {
676 //      pes = new int[numPe];
677 //      for (int i=0; i<numPe; i++) {
678 //        pes[i] = pelist[i];
679 //      }
680 //     } else {
681 //      pes= NULL;
682 //     }
683 // }
684
685 void LogEntry::addPapi(int numPapiEvts, int *papi_ids, LONG_LONG_PAPI *papiVals)
686 {
687 #if CMK_HAS_COUNTER_PAPI
688   numPapiEvents = numPapiEvts;
689   if (papiVals != NULL) {
690     papiIDs = new int[numPapiEvents];
691     papiValues = new LONG_LONG_PAPI[numPapiEvents];
692     for (int i=0; i<numPapiEvents; i++) {
693       papiIDs[i] = papi_ids[i];
694       papiValues[i] = papiVals[i];
695     }
696   }
697 #endif
698 }
699
700
701
702 void LogEntry::pup(PUP::er &p)
703 {
704   int i;
705   CMK_TYPEDEF_UINT8 itime, iEndTime, irecvtime, icputime;
706   char ret = '\n';
707
708   p|type;
709   if (p.isPacking()) itime = (CMK_TYPEDEF_UINT8)(1.0e6*time);
710   if (p.isPacking()) iEndTime = (CMK_TYPEDEF_UINT8)(1.0e6*endTime);
711
712   switch (type) {
713     case USER_EVENT:
714     case USER_EVENT_PAIR:
715       p|mIdx; p|itime; p|event; p|pe;
716       break;
717     case BEGIN_IDLE:
718     case END_IDLE:
719     case BEGIN_PACK:
720     case END_PACK:
721     case BEGIN_UNPACK:
722     case END_UNPACK:
723       p|itime; p|pe; 
724       break;
725     case BEGIN_PROCESSING:
726       if (p.isPacking()) {
727         irecvtime = (CMK_TYPEDEF_UINT8)(recvTime==-1?-1:1.0e6*recvTime);
728         icputime = (CMK_TYPEDEF_UINT8)(1.0e6*cputime);
729       }
730       p|mIdx; p|eIdx; p|itime; p|event; p|pe; 
731       p|msglen; p|irecvtime; 
732       p|id.id[0]; p|id.id[1]; p|id.id[2]; p|id.id[3];
733       p|icputime;
734 #if CMK_HAS_COUNTER_PAPI
735       p|numPapiEvents;
736       for (i=0; i<numPapiEvents; i++) {
737         // not yet!!!
738         //      p|papiIDs[i]; 
739         p|papiValues[i];
740         
741       }
742 #else
743       p|numPapiEvents;     // non papi version has value 0
744 #endif
745       if (p.isUnpacking()) {
746         recvTime = irecvtime/1.0e6;
747         cputime = icputime/1.0e6;
748       }
749       break;
750     case END_PROCESSING:
751       if (p.isPacking()) icputime = (CMK_TYPEDEF_UINT8)(1.0e6*cputime);
752       p|mIdx; p|eIdx; p|itime; p|event; p|pe; p|msglen; p|icputime;
753 #if CMK_HAS_COUNTER_PAPI
754       p|numPapiEvents;
755       for (i=0; i<numPapiEvents; i++) {
756         // not yet!!!
757         //      p|papiIDs[i];
758         p|papiValues[i];
759       }
760 #else
761       p|numPapiEvents;  // non papi version has value 0
762 #endif
763       if (p.isUnpacking()) cputime = icputime/1.0e6;
764       break;
765     case USER_SUPPLIED:
766           p|userSuppliedData;
767           p|itime;
768         break;
769     case USER_SUPPLIED_NOTE:
770           p|itime;
771           int length;
772           if (p.isPacking()) length = strlen(userSuppliedNote);
773           p | length;
774           char space;
775           space = ' ';
776           p | space;
777           if (p.isUnpacking()) {
778             userSuppliedNote = new char[length+1];
779             userSuppliedNote[length] = '\0';
780           }
781           PUParray(p,userSuppliedNote, length);
782           break;
783     case USER_SUPPLIED_BRACKETED_NOTE:
784       //CkPrintf("Writting out a USER_SUPPLIED_BRACKETED_NOTE\n");
785           p|itime;
786           p|iEndTime;
787           p|event;
788           int length2;
789           if (p.isPacking()) length2 = strlen(userSuppliedNote);
790           p | length2;
791           char space2;
792           space2 = ' ';
793           p | space2;
794           if (p.isUnpacking()) {
795             userSuppliedNote = new char[length+1];
796             userSuppliedNote[length] = '\0';
797           }
798           PUParray(p,userSuppliedNote, length2);
799           break;
800     case MEMORY_USAGE_CURRENT:
801       p | memUsage;
802       p | itime;
803         break;
804     case CREATION:
805       if (p.isPacking()) irecvtime = (CMK_TYPEDEF_UINT8)(1.0e6*recvTime);
806       p|mIdx; p|eIdx; p|itime;
807       p|event; p|pe; p|msglen; p|irecvtime;
808       if (p.isUnpacking()) recvTime = irecvtime/1.0e6;
809       break;
810     case CREATION_BCAST:
811       if (p.isPacking()) irecvtime = (CMK_TYPEDEF_UINT8)(1.0e6*recvTime);
812       p|mIdx; p|eIdx; p|itime;
813       p|event; p|pe; p|msglen; p|irecvtime; p|numpes;
814       if (p.isUnpacking()) recvTime = irecvtime/1.0e6;
815       break;
816     case CREATION_MULTICAST:
817       if (p.isPacking()) irecvtime = (CMK_TYPEDEF_UINT8)(1.0e6*recvTime);
818       p|mIdx; p|eIdx; p|itime;
819       p|event; p|pe; p|msglen; p|irecvtime; p|numpes;
820       if (p.isUnpacking()) pes = numpes?new int[numpes]:NULL;
821       for (i=0; i<numpes; i++) p|pes[i];
822       if (p.isUnpacking()) recvTime = irecvtime/1.0e6;
823       break;
824     case MESSAGE_RECV:
825       p|mIdx; p|eIdx; p|itime; p|event; p|pe; p|msglen;
826       break;
827
828     case ENQUEUE:
829     case DEQUEUE:
830       p|mIdx; p|itime; p|event; p|pe;
831       break;
832
833     case BEGIN_INTERRUPT:
834     case END_INTERRUPT:
835       p|itime; p|event; p|pe;
836       break;
837
838       // **CW** absolute timestamps are used here to support a quick
839       // way of determining the total time of a run in projections
840       // visualization.
841     case BEGIN_COMPUTATION:
842     case END_COMPUTATION:
843     case BEGIN_TRACE:
844     case END_TRACE:
845       p|itime;
846       break;
847     case BEGIN_FUNC:
848         p | itime;
849         p | mIdx;
850         p | event;
851         if(!p.isUnpacking()){
852                 p(fName,flen-1);
853         }
854         break;
855     case END_FUNC:
856         p | itime;
857         p | mIdx;
858         break;
859     default:
860       CmiError("***Internal Error*** Wierd Event %d.\n", type);
861       break;
862   }
863   if (p.isUnpacking()) time = itime/1.0e6;
864   p|ret;
865 }
866
867 TraceProjections::TraceProjections(char **argv): 
868   curevent(0), inEntry(0), computationStarted(0), 
869   converseExit(0), endTime(0.0), traceNestedEvents(0)
870 {
871   //  CkPrintf("Trace projections dummy constructor called on %d\n",CkMyPe());
872
873   if (CkpvAccess(traceOnPe) == 0) return;
874
875   CtvInitialize(int,curThreadEvent);
876   CkpvInitialize(int, CtrLogBufSize);
877   CkpvInitialize(bool, useOutlierAnalysis);
878   CkpvAccess(CtrLogBufSize) = DefaultLogBufSize;
879   CtvAccess(curThreadEvent)=0;
880   CkpvAccess(useOutlierAnalysis) =
881     CmiGetArgFlagDesc(argv, "+outlier", "Perform Outlier Analysis");
882   if (CmiGetArgIntDesc(argv,"+logsize",&CkpvAccess(CtrLogBufSize), 
883                        "Log entries to buffer per I/O")) {
884     if (CkMyPe() == 0) {
885       CmiPrintf("Trace: logsize: %d\n", CkpvAccess(CtrLogBufSize));
886     }
887   }
888   checknested = 
889     CmiGetArgFlagDesc(argv,"+checknested",
890                       "check projections nest begin end execute events");
891   traceNestedEvents = 
892     CmiGetArgFlagDesc(argv,"+tracenested",
893               "trace projections nest begin/end execute events");
894   int binary = 
895     CmiGetArgFlagDesc(argv,"+binary-trace",
896                       "Write log files in binary format");
897 #if CMK_PROJECTIONS_USE_ZLIB
898   int compressed = CmiGetArgFlagDesc(argv,"+gz-trace","Write log files pre-compressed with gzip");
899 #else
900   // consume the flag so there's no confusing
901   CmiGetArgFlagDesc(argv,"+gz-trace",
902                     "Write log files pre-compressed with gzip");
903   if(CkMyPe() == 0) CkPrintf("Warning> gz-trace is not supported on this machine!\n");
904 #endif
905
906   // **CW** default to non delta log encoding. The user may choose to do
907   // create both logs (for debugging) or just the old log timestamping
908   // (for compatibility).
909   // Generating just the non delta log takes precedence over generating
910   // both logs (if both arguments appear on the command line).
911
912   // switch to OLD log format until everything works // Gengbin
913   nonDeltaLog = 1;
914   deltaLog = 0;
915   deltaLog = CmiGetArgFlagDesc(argv, "+logDelta",
916                                   "Generate Delta encoded and simple timestamped log files");
917
918   _logPool = new LogPool(CkpvAccess(traceRoot));
919   _logPool->setBinary(binary);
920 #if CMK_PROJECTIONS_USE_ZLIB
921   _logPool->setCompressed(compressed);
922 #endif
923   if (CkMyPe() == 0) {
924     _logPool->createSts();
925     _logPool->createRC();
926   }
927   funcCount=1;
928
929 #if CMK_HAS_COUNTER_PAPI
930   // We initialize and create the event sets for use with PAPI here.
931   int papiRetValue = PAPI_library_init(PAPI_VER_CURRENT);
932   if (papiRetValue != PAPI_VER_CURRENT) {
933     CmiAbort("PAPI Library initialization failure!\n");
934   }
935   // PAPI 3 mandates the initialization of the set to PAPI_NULL
936   papiEventSet = PAPI_NULL; 
937   if (PAPI_create_eventset(&papiEventSet) != PAPI_OK) {
938     CmiAbort("PAPI failed to create event set!\n");
939   }
940   papiRetValue = PAPI_add_events(papiEventSet, papiEvents, numPAPIEvents);
941   if (papiRetValue != PAPI_OK) {
942     if (papiRetValue == PAPI_ECNFLCT) {
943       CmiAbort("PAPI events conflict! Please re-assign event types!\n");
944     } else {
945       CmiAbort("PAPI failed to add designated events!\n");
946     }
947   }
948   papiValues = new long_long[numPAPIEvents];
949   memset(papiValues, 0, numPAPIEvents*sizeof(long_long));
950 #endif
951 }
952
953 int TraceProjections::traceRegisterUserEvent(const char* evt, int e)
954 {
955   OPTIMIZED_VERSION
956   CkAssert(e==-1 || e>=0);
957   CkAssert(evt != NULL);
958   int event;
959   int biggest = -1;
960   for (int i=0; i<CkpvAccess(usrEvents)->length(); i++) {
961     int cur = (*CkpvAccess(usrEvents))[i]->e;
962     if (cur == e) {
963       //CmiPrintf("%s %s\n", (*CkpvAccess(usrEvents))[i]->str, evt);
964       if (strcmp((*CkpvAccess(usrEvents))[i]->str, evt) == 0) 
965         return e;
966       else
967         CmiAbort("UserEvent double registered!");
968     }
969     if (cur > biggest) biggest = cur;
970   }
971   // if no user events have so far been registered. biggest will be -1
972   // and hence newly assigned event numbers will begin from 0.
973   if (e==-1) event = biggest+1;  // automatically assign new event number
974   else event = e;
975   CkpvAccess(usrEvents)->push_back(new UsrEvent(event,(char *)evt));
976   return event;
977 }
978
979 void TraceProjections::traceClearEps(void)
980 {
981   // In trace-summary, this zeros out the EP bins, to eliminate noise
982   // from startup.  Here, this isn't useful, since we can do that in
983   // post-processing
984 }
985
986 void TraceProjections::traceWriteSts(void)
987 {
988   if(CkMyPe()==0)
989     _logPool->writeSts(this);
990 }
991
992 // This is called when Converse closes during ConverseCommonExit()
993 // 
994 // Some programs bypass 
995 // CkExit (like NAMD, which eventually calls ConverseExit), modules
996 // like traces will have to pretend to shutdown as if CkExit was called
997 // but at the same time avoid making subsequent CkExit calls (which is
998 // usually required for allowing other modules to shutdown).
999 //
1000 // Note that we can only get here if CkExit was not called, since the
1001 // trace module will un-register itself from TraceArray if it did.
1002 void TraceProjections::traceClose(void)
1003 {
1004 #ifdef PROJ_ANALYSIS
1005   // CkPrintf("CkExit was not called on shutdown on [%d]\n", CkMyPe());
1006   // sets the flag that tells the code not to make the CkExit call later
1007   converseExit = 1;
1008   if (CkMyPe() == 0) {
1009     CProxy_TraceProjectionsBOC bocProxy(traceProjectionsGID);
1010     bocProxy.shutdownAnalysis();
1011   }
1012 #else
1013   // we've already deleted the logpool, so multiple calls to traceClose
1014   // are tolerated.
1015   if (_logPool == NULL) {
1016     return;
1017   }
1018   if(CkMyPe()==0){
1019     _logPool->writeSts(this);
1020   }
1021   CkpvAccess(_trace)->endComputation();
1022   delete _logPool;              // will write
1023   // remove myself from traceArray so that no tracing will be called.
1024   CkpvAccess(_traces)->removeTrace(this);
1025 #endif
1026 }
1027
1028 // This is meant to be called internally rather than by converse.
1029 void TraceProjections::closeTrace() {
1030   //  CkPrintf("Close Trace called on [%d]\n", CkMyPe());
1031   if (CkMyPe() == 0) {
1032     // CkPrintf("Pe 0 will now write sts and projrc files\n");
1033     _logPool->writeSts(this);
1034     _logPool->writeRC();
1035     // CkPrintf("Pe 0 has now written sts and projrc files\n");
1036   }
1037   delete _logPool;       // will write logs to file
1038 }
1039
1040 void TraceProjections::traceBegin(void)
1041 {
1042   if (!computationStarted) return;
1043   _logPool->add(BEGIN_TRACE, 0, 0, TraceTimer(), curevent++, CkMyPe());
1044 }
1045
1046 void TraceProjections::traceEnd(void)
1047 {
1048   _logPool->add(END_TRACE, 0, 0, TraceTimer(), curevent++, CkMyPe());
1049 }
1050
1051 void TraceProjections::userEvent(int e)
1052 {
1053   if (!computationStarted) return;
1054   _logPool->add(USER_EVENT, e, 0, TraceTimer(),curevent++,CkMyPe());
1055 }
1056
1057 void TraceProjections::userBracketEvent(int e, double bt, double et)
1058 {
1059   if (!computationStarted) return;
1060   // two events record Begin/End of event e.
1061   _logPool->add(USER_EVENT_PAIR, e, 0, TraceTimer(bt), curevent, CkMyPe());
1062   _logPool->add(USER_EVENT_PAIR, e, 0, TraceTimer(et), curevent++, CkMyPe());
1063 }
1064
1065 void TraceProjections::userSuppliedData(int d)
1066 {
1067   if (!computationStarted) return;
1068   _logPool->addUserSupplied(d);
1069 }
1070
1071 void TraceProjections::userSuppliedNote(char *note)
1072 {
1073   if (!computationStarted) return;
1074   _logPool->addUserSuppliedNote(note);
1075 }
1076
1077
1078 void TraceProjections::userSuppliedBracketedNote(char *note, int eventID, double bt, double et)
1079 {
1080   if (!computationStarted) return;
1081   _logPool->addUserSuppliedBracketedNote(note,  eventID,  bt, et);
1082 }
1083
1084 void TraceProjections::memoryUsage(double m)
1085 {
1086   if (!computationStarted) return;
1087   _logPool->addMemoryUsage(MEMORY_USAGE_CURRENT, TraceTimer(), m );
1088   
1089 }
1090
1091
1092 void TraceProjections::creation(envelope *e, int ep, int num)
1093 {
1094   double curTime = TraceTimer();
1095   if (e == 0) {
1096     CtvAccess(curThreadEvent) = curevent;
1097     _logPool->add(CREATION, ForChareMsg, ep, curTime,
1098                   curevent++, CkMyPe(), 0, NULL, 0, 0.0);
1099   } else {
1100     int type=e->getMsgtype();
1101     e->setEvent(curevent);
1102     if (num > 1) {
1103       _logPool->add(CREATION_BCAST, type, ep, curTime,
1104                     curevent++, CkMyPe(), e->getTotalsize(), 
1105                     NULL, 0, 0.0, num);
1106     } else {
1107       _logPool->add(CREATION, type, ep, curTime,
1108                     curevent++, CkMyPe(), e->getTotalsize(), 
1109                     NULL, 0, 0.0);
1110     }
1111   }
1112 }
1113
1114 /* **CW** Non-disruptive attempt to add destination PE knowledge to
1115    Communication Library-specific Multicasts via new event 
1116    CREATION_MULTICAST.
1117 */
1118
1119 void TraceProjections::creationMulticast(envelope *e, int ep, int num,
1120                                          int *pelist)
1121 {
1122   double curTime = TraceTimer();
1123   if (e==0) {
1124     CtvAccess(curThreadEvent)=curevent;
1125     _logPool->addCreationMulticast(ForChareMsg, ep, curTime, curevent++,
1126                                    CkMyPe(), 0, 0, 0.0, num, pelist);
1127   } else {
1128     int type=e->getMsgtype();
1129     e->setEvent(curevent);
1130     _logPool->addCreationMulticast(type, ep, curTime, curevent++, CkMyPe(),
1131                                    e->getTotalsize(), 0, 0.0, num, pelist);
1132   }
1133 }
1134
1135 void TraceProjections::creationDone(int num)
1136 {
1137   // modified the creation done time of the last num log entries
1138   // FIXME: totally a hack
1139   double curTime = TraceTimer();
1140   int idx = _logPool->numEntries-1;
1141   while (idx >=0 && num >0 ) {
1142     LogEntry &log = _logPool->pool[idx];
1143     if ((log.type == CREATION) ||
1144         (log.type == CREATION_BCAST) ||
1145         (log.type == CREATION_MULTICAST)) {
1146       log.recvTime = curTime - log.time;
1147       num --;
1148     }
1149     idx--;
1150   }
1151 }
1152
1153 void TraceProjections::beginExecute(CmiObjId *tid)
1154 {
1155 #if CMK_HAS_COUNTER_PAPI
1156   if (PAPI_read(papiEventSet, papiValues) != PAPI_OK) {
1157     CmiAbort("PAPI failed to read at begin execute!\n");
1158   }
1159 #endif
1160   if (checknested && inEntry) CmiAbort("Nested Begin Execute!\n");
1161   execEvent = CtvAccess(curThreadEvent);
1162   execEp = (-1);
1163   _logPool->add(BEGIN_PROCESSING,ForChareMsg,_threadEP,TraceTimer(),
1164                 execEvent,CkMyPe(), 0, tid);
1165 #if CMK_HAS_COUNTER_PAPI
1166   _logPool->addPapi(numPAPIEvents, papiEvents, papiValues);
1167 #endif
1168   inEntry = 1;
1169 }
1170
1171 void TraceProjections::beginExecute(envelope *e)
1172 {
1173   if(e==0) {
1174 #if CMK_HAS_COUNTER_PAPI
1175     if (PAPI_read(papiEventSet, papiValues) != PAPI_OK) {
1176       CmiAbort("PAPI failed to read at begin execute!\n");
1177     }
1178 #endif
1179     if (checknested && inEntry) CmiAbort("Nested Begin Execute!\n");
1180     execEvent = CtvAccess(curThreadEvent);
1181     execEp = (-1);
1182     _logPool->add(BEGIN_PROCESSING,ForChareMsg,_threadEP,TraceTimer(),
1183                   execEvent,CkMyPe(), 0, NULL, 0.0, TraceCpuTimer());
1184 #if CMK_HAS_COUNTER_PAPI
1185     _logPool->addPapi(numPAPIEvents, papiEvents, papiValues);
1186 #endif
1187     inEntry = 1;
1188   } else {
1189     beginExecute(e->getEvent(),e->getMsgtype(),e->getEpIdx(),
1190                  e->getSrcPe(),e->getTotalsize());
1191   }
1192 }
1193
1194 void TraceProjections::beginExecute(int event, int msgType, int ep, int srcPe,
1195                                     int mlen, CmiObjId *idx)
1196 {
1197   if (traceNestedEvents) {
1198     if (! nestedEvents.isEmpty()) {
1199       endExecuteLocal();
1200     }
1201     nestedEvents.enq(NestedEvent(event, msgType, ep, srcPe, mlen, idx));
1202   }
1203   beginExecuteLocal(event, msgType, ep, srcPe, mlen, idx);
1204 }
1205
1206 void TraceProjections::beginExecuteLocal(int event, int msgType, int ep, int srcPe,
1207                                     int mlen, CmiObjId *idx)
1208 {
1209 #if CMK_HAS_COUNTER_PAPI
1210   if (PAPI_read(papiEventSet, papiValues) != PAPI_OK) {
1211     CmiAbort("PAPI failed to read at begin execute!\n");
1212   }
1213 #endif
1214   if (checknested && inEntry) CmiAbort("Nested Begin Execute!\n");
1215   execEvent=event;
1216   execEp=ep;
1217   execPe=srcPe;
1218   _logPool->add(BEGIN_PROCESSING,msgType,ep,TraceTimer(),event,
1219                 srcPe, mlen, idx, 0.0, TraceCpuTimer());
1220 #if CMK_HAS_COUNTER_PAPI
1221   _logPool->addPapi(numPAPIEvents, papiEvents, papiValues);
1222 #endif
1223   inEntry = 1;
1224 }
1225
1226 void TraceProjections::endExecute(void)
1227 {
1228   if (traceNestedEvents) nestedEvents.deq();
1229   endExecuteLocal();
1230   if (traceNestedEvents) {
1231     if (! nestedEvents.isEmpty()) {
1232       NestedEvent &ne = nestedEvents.peek();
1233       beginExecuteLocal(ne.event, ne.msgType, ne.ep, ne.srcPe, ne.ml, ne.idx);
1234     }
1235   }
1236 }
1237
1238 void TraceProjections::endExecuteLocal(void)
1239 {
1240 #if CMK_HAS_COUNTER_PAPI
1241   if (PAPI_read(papiEventSet, papiValues) != PAPI_OK) {
1242     CmiAbort("PAPI failed to read at end execute!\n");
1243   }
1244 #endif
1245   if (checknested && !inEntry) CmiAbort("Nested EndExecute!\n");
1246   double cputime = TraceCpuTimer();
1247   if(execEp == (-1)) {
1248     _logPool->add(END_PROCESSING, 0, _threadEP, TraceTimer(),
1249                   execEvent, CkMyPe(), 0, NULL, 0.0, cputime);
1250   } else {
1251     _logPool->add(END_PROCESSING, 0, execEp, TraceTimer(),
1252                   execEvent, execPe, 0, NULL, 0.0, cputime);
1253   }
1254 #if CMK_HAS_COUNTER_PAPI
1255   _logPool->addPapi(numPAPIEvents, papiEvents, papiValues);
1256 #endif
1257   inEntry = 0;
1258 }
1259
1260 void TraceProjections::messageRecv(char *env, int pe)
1261 {
1262 #if 0
1263   envelope *e = (envelope *)env;
1264   int msgType = e->getMsgtype();
1265   int ep = e->getEpIdx();
1266 #if 0
1267   if (msgType==NewChareMsg || msgType==NewVChareMsg
1268           || msgType==ForChareMsg || msgType==ForVidMsg
1269           || msgType==BocInitMsg || msgType==NodeBocInitMsg
1270           || msgType==ForBocMsg || msgType==ForNodeBocMsg)
1271     ep = e->getEpIdx();
1272   else
1273     ep = _threadEP;
1274 #endif
1275   _logPool->add(MESSAGE_RECV, msgType, ep, TraceTimer(),
1276                 curevent++, e->getSrcPe(), e->getTotalsize());
1277 #endif
1278 }
1279
1280 void TraceProjections::beginIdle(double curWallTime)
1281 {
1282   _logPool->add(BEGIN_IDLE, 0, 0, TraceTimer(curWallTime), 0, CkMyPe());
1283 }
1284
1285 void TraceProjections::endIdle(double curWallTime)
1286 {
1287   _logPool->add(END_IDLE, 0, 0, TraceTimer(curWallTime), 0, CkMyPe());
1288 }
1289
1290 void TraceProjections::beginPack(void)
1291 {
1292   _logPool->add(BEGIN_PACK, 0, 0, TraceTimer(), 0, CkMyPe());
1293 }
1294
1295 void TraceProjections::endPack(void)
1296 {
1297   _logPool->add(END_PACK, 0, 0, TraceTimer(), 0, CkMyPe());
1298 }
1299
1300 void TraceProjections::beginUnpack(void)
1301 {
1302   _logPool->add(BEGIN_UNPACK, 0, 0, TraceTimer(), 0, CkMyPe());
1303 }
1304
1305 void TraceProjections::endUnpack(void)
1306 {
1307   _logPool->add(END_UNPACK, 0, 0, TraceTimer(), 0, CkMyPe());
1308 }
1309
1310 void TraceProjections::enqueue(envelope *) {}
1311
1312 void TraceProjections::dequeue(envelope *) {}
1313
1314 void TraceProjections::beginComputation(void)
1315 {
1316   computationStarted = 1;
1317
1318   // Executes the callback function provided by the machine
1319   // layer. This is the proper method to register user events in a
1320   // machine layer because projections is a charm++ module.
1321   if (CkpvAccess(traceOnPe) != 0) {
1322     void (*ptr)() = registerMachineUserEvents();
1323     if (ptr != NULL) {
1324       ptr();
1325     }
1326   }
1327 //  CkpvAccess(traceInitTime) = TRACE_TIMER();
1328 //  CkpvAccess(traceInitCpuTime) = TRACE_CPUTIMER();
1329   _logPool->add(BEGIN_COMPUTATION, 0, 0, TraceTimer(), -1, -1);
1330 #if CMK_HAS_COUNTER_PAPI
1331   // we start the counters here
1332   if (PAPI_start(papiEventSet) != PAPI_OK) {
1333     CmiAbort("PAPI failed to start designated counters!\n");
1334   }
1335 #endif
1336 }
1337
1338 void TraceProjections::endComputation(void)
1339 {
1340 #if CMK_HAS_COUNTER_PAPI
1341   // we stop the counters here. A silent failure is alright since we
1342   // are already at the end of the program.
1343   if (PAPI_stop(papiEventSet, papiValues) != PAPI_OK) {
1344     CkPrintf("Warning: PAPI failed to stop correctly!\n");
1345   }
1346   // NOTE: We should not do a complete close of PAPI until after the
1347   // sts writer is done.
1348 #endif
1349   endTime = TraceTimer();
1350   _logPool->add(END_COMPUTATION, 0, 0, endTime, -1, -1);
1351   /*
1352   CkPrintf("End Computation [%d] records time as %lf\n", CkMyPe(), 
1353            endTime*1e06);
1354   */
1355 }
1356
1357 int TraceProjections::idxRegistered(int idx)
1358 {
1359     int idxVecLen = idxVec.size();
1360     for(int i=0; i<idxVecLen; i++)
1361     {
1362         if(idx == idxVec[i])
1363             return 1;
1364     }
1365     return 0;
1366 }
1367
1368 void TraceProjections::regFunc(const char *name, int &idx, int idxSpecifiedByUser){
1369     StrKey k((char*)name,strlen(name));
1370     int num = funcHashtable.get(k);
1371     
1372     if(num!=0) {
1373         return;
1374         //as for mpi programs, the same function may be registered for several times
1375         //CmiError("\"%s has been already registered! Please change the name!\"\n", name);
1376     }
1377     
1378     int isIdxExisting=0;
1379     if(idxSpecifiedByUser)
1380         isIdxExisting=idxRegistered(idx);
1381     if(isIdxExisting){
1382         return;
1383         //same reason with num!=0
1384         //CmiError("The identifier %d for the trace function has been already registered!", idx);
1385     }
1386
1387     if(idxSpecifiedByUser) {
1388         char *st = new char[strlen(name)+1];
1389         memcpy(st,name,strlen(name)+1);
1390         StrKey *newKey = new StrKey(st,strlen(st));
1391         int &ref = funcHashtable.put(*newKey);
1392         ref=idx;
1393         funcCount++;
1394         idxVec.push_back(idx);  
1395     } else {
1396         char *st = new char[strlen(name)+1];
1397         memcpy(st,name,strlen(name)+1);
1398         StrKey *newKey = new StrKey(st,strlen(st));
1399         int &ref = funcHashtable.put(*newKey);
1400         ref=funcCount;
1401         num = funcCount;
1402         funcCount++;
1403         idx = num;
1404         idxVec.push_back(idx);
1405     }
1406 }
1407
1408 void TraceProjections::beginFunc(char *name,char *file,int line){
1409         StrKey k(name,strlen(name));    
1410         unsigned short  num = (unsigned short)funcHashtable.get(k);
1411         beginFunc(num,file,line);
1412 }
1413
1414 void TraceProjections::beginFunc(int idx,char *file,int line){
1415         if(idx <= 0){
1416                 CmiError("Unregistered function id %d being used in %s:%d \n",idx,file,line);
1417         }       
1418         _logPool->add(BEGIN_FUNC,TraceTimer(),idx,line,file);
1419 }
1420
1421 void TraceProjections::endFunc(char *name){
1422         StrKey k(name,strlen(name));    
1423         int num = funcHashtable.get(k);
1424         endFunc(num);   
1425 }
1426
1427 void TraceProjections::endFunc(int num){
1428         if(num <= 0){
1429                 printf("endFunc without start :O\n");
1430         }
1431         _logPool->add(END_FUNC,TraceTimer(),num,0,NULL);
1432 }
1433
1434 // specialized PUP:ers for handling trace projections logs
1435 void toProjectionsFile::bytes(void *p,int n,size_t itemSize,dataType t)
1436 {
1437   for (int i=0;i<n;i++) 
1438     switch(t) {
1439     case Tchar: CheckAndFPrintF(f,"%c",((char *)p)[i]); break;
1440     case Tuchar:
1441     case Tbyte: CheckAndFPrintF(f,"%d",((unsigned char *)p)[i]); break;
1442     case Tshort: CheckAndFPrintF(f," %d",((short *)p)[i]); break;
1443     case Tushort: CheckAndFPrintF(f," %u",((unsigned short *)p)[i]); break;
1444     case Tint: CheckAndFPrintF(f," %d",((int *)p)[i]); break;
1445     case Tuint: CheckAndFPrintF(f," %u",((unsigned int *)p)[i]); break;
1446     case Tlong: CheckAndFPrintF(f," %ld",((long *)p)[i]); break;
1447     case Tulong: CheckAndFPrintF(f," %lu",((unsigned long *)p)[i]); break;
1448     case Tfloat: CheckAndFPrintF(f," %.7g",((float *)p)[i]); break;
1449     case Tdouble: CheckAndFPrintF(f," %.15g",((double *)p)[i]); break;
1450 #ifdef CMK_PUP_LONG_LONG
1451     case Tlonglong: CheckAndFPrintF(f," %lld",((CMK_TYPEDEF_INT8 *)p)[i]); break;
1452     case Tulonglong: CheckAndFPrintF(f," %llu",((CMK_TYPEDEF_UINT8 *)p)[i]); break;
1453 #endif
1454     default: CmiAbort("Unrecognized pup type code!");
1455     };
1456 }
1457
1458 void fromProjectionsFile::bytes(void *p,int n,size_t itemSize,dataType t)
1459 {
1460   for (int i=0;i<n;i++) 
1461     switch(t) {
1462     case Tchar: { 
1463       char c = fgetc(f);
1464       if (c==EOF)
1465         parseError("Could not match character");
1466       else
1467         ((char *)p)[i] = c;
1468       break;
1469     }
1470     case Tuchar:
1471     case Tbyte: ((unsigned char *)p)[i]=(unsigned char)readInt("%d"); break;
1472     case Tshort:((short *)p)[i]=(short)readInt(); break;
1473     case Tushort: ((unsigned short *)p)[i]=(unsigned short)readUint(); break;
1474     case Tint:  ((int *)p)[i]=readInt(); break;
1475     case Tuint: ((unsigned int *)p)[i]=readUint(); break;
1476     case Tlong: ((long *)p)[i]=readInt(); break;
1477     case Tulong:((unsigned long *)p)[i]=readUint(); break;
1478     case Tfloat: ((float *)p)[i]=(float)readDouble(); break;
1479     case Tdouble:((double *)p)[i]=readDouble(); break;
1480 #ifdef CMK_PUP_LONG_LONG
1481     case Tlonglong: ((CMK_TYPEDEF_INT8 *)p)[i]=readLongInt(); break;
1482     case Tulonglong: ((CMK_TYPEDEF_UINT8 *)p)[i]=readLongInt(); break;
1483 #endif
1484     default: CmiAbort("Unrecognized pup type code!");
1485     };
1486 }
1487
1488 #if CMK_PROJECTIONS_USE_ZLIB
1489 void toProjectionsGZFile::bytes(void *p,int n,size_t itemSize,dataType t)
1490 {
1491   for (int i=0;i<n;i++) 
1492     switch(t) {
1493     case Tchar: gzprintf(f,"%c",((char *)p)[i]); break;
1494     case Tuchar:
1495     case Tbyte: gzprintf(f,"%d",((unsigned char *)p)[i]); break;
1496     case Tshort: gzprintf(f," %d",((short *)p)[i]); break;
1497     case Tushort: gzprintf(f," %u",((unsigned short *)p)[i]); break;
1498     case Tint: gzprintf(f," %d",((int *)p)[i]); break;
1499     case Tuint: gzprintf(f," %u",((unsigned int *)p)[i]); break;
1500     case Tlong: gzprintf(f," %ld",((long *)p)[i]); break;
1501     case Tulong: gzprintf(f," %lu",((unsigned long *)p)[i]); break;
1502     case Tfloat: gzprintf(f," %.7g",((float *)p)[i]); break;
1503     case Tdouble: gzprintf(f," %.15g",((double *)p)[i]); break;
1504 #ifdef CMK_PUP_LONG_LONG
1505     case Tlonglong: gzprintf(f," %lld",((CMK_TYPEDEF_INT8 *)p)[i]); break;
1506     case Tulonglong: gzprintf(f," %llu",((CMK_TYPEDEF_UINT8 *)p)[i]); break;
1507 #endif
1508     default: CmiAbort("Unrecognized pup type code!");
1509     };
1510 }
1511 #endif
1512
1513 #ifdef PROJ_ANALYSIS
1514 void TraceProjectionsBOC::shutdownAnalysis() {
1515   if (CkMyPe() == 0) {
1516     analysisStartTime = CmiWallTimer();
1517   }
1518   //  CkPrintf("Shutdown analysis called on [%d]\n",CkMyPe());
1519   CkpvAccess(_trace)->endComputation();
1520   // no more tracing for projections on this processor after this point. 
1521   // Note that clear must be called after remove, or bad things will happen.
1522   CkpvAccess(_traces)->removeTrace(CkpvAccess(_trace));
1523   CkpvAccess(_traces)->clearTrace();
1524
1525   // From this point, we start a chain of reductions and broadcasts to
1526   // perform final online analysis activities, ending with endTimeReduction
1527   if (CkpvAccess(useOutlierAnalysis)) {
1528     thisProxy[CkMyPe()].startOutlierAnalysis();
1529   } else {
1530     thisProxy[CkMyPe()].startEndTimeAnalysis();
1531   }
1532 }
1533
1534 void TraceProjectionsBOC::startOutlierAnalysis() {
1535   // assumes the presence of the complete logs on this processor.
1536   LogPool *pool = CkpvAccess(_trace)->_logPool;
1537
1538   // this array stores entry method and idle times (hence +1) and 
1539   // is twice as long to store their squares for statistical analysis
1540   // when the reduction is performed.
1541   int numEvents = _entryTable.size()+1;
1542   execTimes = new double[numEvents*2];
1543   for (int i=0; i<numEvents*2; i++) {
1544     execTimes[i] = 0.0;
1545   }
1546
1547   bool markedBegin = false;
1548   bool markedIdle = false;
1549   double beginBlockTime = 0.0;
1550   double beginIdleBlockTime = 0.0;
1551
1552   for (int i=0; i<pool->numEntries; i++) {
1553     if (pool->pool[i].type == BEGIN_PROCESSING) {
1554       // check pairing
1555       if (!markedBegin) {
1556         markedBegin = true;
1557       }
1558       beginBlockTime = pool->pool[i].time;
1559     } else if (pool->pool[i].type == END_PROCESSING) {
1560       // check pairing
1561       // if End without a begin, just ignore
1562       // this event.
1563       if (markedBegin) {
1564         markedBegin = false;
1565         if (pool->pool[i].event < 0)
1566         {
1567           // ignore dummy events
1568           break;
1569         }
1570         execTimes[pool->pool[i].eIdx] +=
1571           pool->pool[i].time - beginBlockTime;
1572       }
1573     } else if (pool->pool[i].type == BEGIN_IDLE) {
1574       // check pairing
1575       if (!markedIdle) {
1576         markedIdle = true;
1577       }
1578       beginIdleBlockTime = pool->pool[i].time;
1579     } else if (pool->pool[i].type == END_IDLE) {
1580       // check pairing
1581       if (markedIdle) {
1582         markedIdle = false;
1583         execTimes[numEvents] +=
1584           pool->pool[i].time - beginIdleBlockTime;
1585       }
1586     }
1587   }
1588   // convert all values to milliseconds first (else values would be too small
1589   // or too big)
1590   for (int i=0; i<numEvents; i++) {
1591     execTimes[i] *= 1.0e3;
1592   }
1593
1594   // compute squares
1595   for (int i=0; i<numEvents; i++) {
1596     execTimes[i+numEvents] = execTimes[i]*execTimes[i];
1597   }
1598
1599   CkCallback cb(CkIndex_TraceProjectionsBOC::outlierAverageReduction(NULL), 
1600                 0, thisProxy);
1601   contribute(numEvents*2*sizeof(double), execTimes, 
1602              CkReduction::sum_double, cb);  
1603 }
1604
1605 void TraceProjectionsBOC::outlierAverageReduction(CkReductionMsg *msg) {
1606   CkAssert(CkMyPe() == 0);
1607   // kinda wierd place to initialize a variable, but ...
1608   encounteredWeights = 0;
1609   weightArray = new double[CkNumPes()];
1610   mapArray = new int[CkNumPes()];
1611
1612   // calculate statistics
1613   int numEvents = _entryTable.size()+1;
1614   OutlierStatsMessage *outmsg = new (numEvents*2) OutlierStatsMessage;
1615
1616   double *execTimes = (double *)msg->getData();
1617   /*
1618   for (int i=0; i<numEvents; i++) {
1619     CkPrintf("EP: %d has Data: %lf and sum of squares %lf\n",
1620              i,execTimes[i],execTimes[i+numEvents]);
1621   }
1622   */
1623   for (int i=0; i<numEvents; i++) {
1624     // calculate mean
1625     outmsg->stats[i] = execTimes[i]/CkNumPes();
1626     // calculate stddev (using biased variance)
1627     outmsg->stats[i+numEvents] = 
1628       sqrt((execTimes[i+numEvents]-2*(outmsg->stats[i])*execTimes[i]+
1629             (outmsg->stats[i])*(outmsg->stats[i])*CkNumPes())/
1630            CkNumPes());
1631     // CkPrintf("EP:%d Mean:%lf Stddev:%lf\n",i,outmsg->stats[i],
1632     //       outmsg->stats[i+numEvents]);
1633   }
1634   delete msg;
1635
1636   // output averages to a file in microseconds. File handle to be kept
1637   // open so we can write more stats to it.
1638   char *fname = new char[strlen(CkpvAccess(traceRoot))+strlen(".outlier")+1];
1639   sprintf(fname, "%s.outlier", CkpvAccess(traceRoot));
1640   do {
1641     outlierfp = fopen(fname, "w");
1642   } while (!outlierfp && (errno == EINTR || errno == EMFILE));
1643   for (int i=0; i<numEvents; i++) {
1644     fprintf(outlierfp,"%lld ",(CMK_TYPEDEF_UINT8)(outmsg->stats[i]*1.0e3));
1645   }
1646   fprintf(outlierfp,"\n");
1647
1648   // broadcast statistical values to all processors for weight calculations
1649   thisProxy.calculateWeights(outmsg);
1650 }
1651
1652 void TraceProjectionsBOC::calculateWeights(OutlierStatsMessage *msg) {
1653   // calculate outlier "weights"
1654   int numEvents = _entryTable.size()+1;
1655
1656   // this is silly, but do it for now. First pass for computing total
1657   // time. It is also a misnomer, since this total will not include
1658   // any overhead time.
1659   OutlierWeightMessage *outmsg = new OutlierWeightMessage;
1660   weight = 0.0;
1661   outmsg->sourcePe = CkMyPe();
1662   outmsg->weight = 0.0;
1663   double total = 0.0;
1664   for (int i=0; i<numEvents; i++) {
1665     total += execTimes[i];
1666   }
1667   for (int i=0; i<numEvents; i++) {
1668     if ((total > 0.0) &&
1669         (msg->stats[i+numEvents] > 0.0)) {
1670       outmsg->weight += 
1671         (fabs(execTimes[i]-msg->stats[i])/msg->stats[i+numEvents]) *
1672         (msg->stats[i]/total);
1673     }
1674     // CkPrintf("[%d] EP:%d Weight:%lf\n",CkMyPe(),i,outmsg->weight);
1675   }
1676   weight = outmsg->weight;
1677   delete msg;
1678   
1679   thisProxy[0].determineOutliers(outmsg);
1680 }
1681
1682 void TraceProjectionsBOC::determineOutliers(OutlierWeightMessage *msg) {
1683   CkAssert(CkMyPe() == 0);
1684   encounteredWeights++;
1685
1686   // For now, implement a full array for sorting later. For better scaling
1687   // it should really be a sorted list of maximum k entries.
1688   weightArray[msg->sourcePe] = msg->weight;
1689
1690   if (encounteredWeights == CkNumPes()) {
1691     OutlierThresholdMessage *outmsg = new OutlierThresholdMessage;
1692     outmsg->threshold = 0.0;
1693
1694     // initialize the map array
1695     for (int i=0; i<CkNumPes(); i++) {
1696       mapArray[i] = i;
1697     }
1698     
1699     // bubble sort the array
1700     for (int p=CkNumPes()-1; p>0; p--) {
1701       for (int i=0; i<p; i++) {
1702         if (weightArray[i+1] < weightArray[i]) {
1703           int tempI;
1704           double temp = weightArray[i+1];
1705           weightArray[i+1] = weightArray[i];
1706           weightArray[i] = temp;
1707           tempI = mapArray[i+1];
1708           mapArray[i+1] = mapArray[i];
1709           mapArray[i] = tempI;
1710         }
1711       }
1712     }    
1713
1714     // default threshold is applied.
1715     //
1716     // **CW** This needs to be changed to accept a runtime parameter
1717     // so the default can be overridden. Default value considers the
1718     // top 10% "different" processors as outliers.
1719     int thresholdIndex;
1720     thresholdIndex = (int)(CkNumPes()*0.9);
1721     if (thresholdIndex == CkNumPes()) {
1722       thresholdIndex--;
1723     }
1724
1725     // output the sorted processor list to stats file
1726     for (int i=thresholdIndex; i<CkNumPes(); i++) {
1727       fprintf(outlierfp,"%d ",mapArray[i]);
1728     }
1729     fprintf(outlierfp,"\n");
1730     fflush(outlierfp);
1731     fclose(outlierfp);
1732
1733     // CkPrintf("Outlier Index determined to be %d with value %lf\n",
1734     //       thresholdIndex, weightArray[thresholdIndex]);
1735     outmsg->threshold = weightArray[thresholdIndex];
1736     
1737     delete msg;
1738     thisProxy.setOutliers(outmsg);
1739   } else {
1740     delete msg;
1741   }
1742 }
1743
1744 void TraceProjectionsBOC::setOutliers(OutlierThresholdMessage *msg)
1745 {
1746   LogPool *pool = CkpvAccess(_trace)->_logPool;
1747   // CkPrintf("[%d] My weight is %lf, threshold is %lf\n",CkMyPe(),weight,
1748   //   msg->threshold);
1749   if (weight < msg->threshold) {
1750     // CkPrintf("[%d] Removing myself from output list\n");
1751     pool->writeData = false;
1752   }
1753
1754   delete msg;
1755   thisProxy[CkMyPe()].startEndTimeAnalysis();
1756 }
1757
1758 void TraceProjectionsBOC::startEndTimeAnalysis()
1759 {
1760   endTime = CkpvAccess(_trace)->endTime;
1761   // CkPrintf("[%d] End time is %lf us\n", CkMyPe(), endTime*1e06);
1762
1763   CkCallback cb(CkIndex_TraceProjectionsBOC::endTimeReduction(NULL), 
1764                 0, thisProxy);
1765   contribute(sizeof(double), &endTime, CkReduction::max_double, cb);  
1766 }
1767
1768 void TraceProjectionsBOC::endTimeReduction(CkReductionMsg *msg)
1769 {
1770   CkAssert(CkMyPe() == 0);
1771   if (CkpvAccess(_trace) != NULL) {
1772     CkpvAccess(_trace)->_logPool->globalEndTime = *(double *)msg->getData();
1773     // CkPrintf("End time determined to be %lf us\n",
1774     //       (CkpvAccess(_trace)->_logPool->globalEndTime)*1e06);
1775   }
1776   delete msg;  
1777   CkPrintf("Total Analysis Time = %lf\n", CmiWallTimer()-analysisStartTime);
1778   thisProxy.closeTrace();
1779 }
1780
1781 void TraceProjectionsBOC::finalReduction(CkReductionMsg *msg)
1782 {
1783   CkAssert(CkMyPe() == 0);
1784   // CkPrintf("Final Reduction called\n");
1785   delete msg;
1786   CkExit();
1787 }
1788
1789 void TraceProjectionsBOC::closeTrace()
1790 {
1791   if (CkpvAccess(_trace) == NULL) {
1792     return;
1793   }
1794   CkpvAccess(_trace)->closeTrace();
1795   // the following section is only excuted if CkExit is called, since
1796   // closing-progress is required for other modules.
1797   if (!CkpvAccess(_trace)->converseExit) {
1798     // this is a dummy reduction to make sure that all the output
1799     // is completed before other modules are allowed to do stuff
1800     // and finally _CkExit is called.
1801     CkCallback cb(CkIndex_TraceProjectionsBOC::finalReduction(NULL), 
1802                   0, thisProxy);
1803     contribute(sizeof(double), &dummy, CkReduction::max_double, cb);
1804   }
1805 }
1806
1807 // This is the C++ code that is registered to be activated at module
1808 // shutdown. This is called exactly once on processor 0.
1809 // 
1810 extern "C" void CombineProjections()
1811 {
1812 #ifndef CMK_OPTIMIZE
1813   // CkPrintf("[%d] CombineProjections called!\n", CkMyPe());
1814   CProxy_TraceProjectionsBOC bocProxy(traceProjectionsGID);
1815   bocProxy.shutdownAnalysis();
1816 #else
1817   CkExit();
1818 #endif
1819 }
1820
1821 // This method is called by module initialization to register the exit
1822 // function. This exit function must ultimately call CkExit() again to
1823 // so that other module exit functions may proceed after this module is
1824 // done.
1825 //
1826 // This is called once on each processor but the idiom of use appears
1827 // to be to only have processor 0 register the function.
1828 void initTraceProjectionsBOC()
1829 {
1830   // CkPrintf("[%d] Trace Projections initialization called!\n", CkMyPe());
1831 #ifdef __BLUEGENE__
1832   if (BgNodeRank() == 0) {
1833 #else
1834     if (CkMyRank() == 0) {
1835 #endif
1836       registerExitFn(CombineProjections);
1837     }
1838   }
1839
1840 #include "TraceProjections.def.h"
1841 #endif
1842
1843 /*@}*/