changed a few things in order to link with application.
[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 #include "charm++.h"
16 #include "envelope.h"
17 #include "trace-common.h"
18 #include "trace-projections.h"
19
20 #define DEBUGF(x)           // CmiPrintf x
21
22 // **CW** Simple delta encoding implementation
23 // delta encoding is on by default. It may be turned off later in
24 // the runtime.
25 int deltaLog;
26 int nonDeltaLog;
27
28 int checknested=0;              // check illegal nested begin/end execute 
29
30 CkpvStaticDeclare(Trace*, _trace);
31 CtvStaticDeclare(int,curThreadEvent);
32
33 typedef CkVec<char *>  usrEventVec;
34 CkpvStaticDeclare(usrEventVec, usrEventlist);
35 class UsrEvent {
36 public:
37   int e;
38   char *str;
39   UsrEvent(int _e, char* _s): e(_e),str(_s) {}
40 };
41 CkpvStaticDeclare(CkVec<UsrEvent *>*, usrEvents);
42
43 #ifdef CMK_OPTIMIZE
44 static int warned=0;
45 #define OPTIMIZED_VERSION       \
46         if (!warned) { warned=1;        \
47         CmiPrintf("\n\n!!!! Warning: traceUserEvent not available in optimized version!!!!\n\n\n"); }
48 #else
49 #define OPTIMIZED_VERSION /*empty*/
50 #endif
51
52 /*
53 On T3E, we need to have file number control by open/close files only when needed.
54 */
55 #if CMK_TRACE_LOGFILE_NUM_CONTROL
56   #define OPEN_LOG openLog("a");
57   #define CLOSE_LOG closeLog();
58 #else
59   #define OPEN_LOG
60   #define CLOSE_LOG
61 #endif
62
63 #if CMK_HAS_COUNTER_PAPI
64 // For now, we trace only two events - # Floating Point Instructions &
65 // # of L2 Cache Misses.
66 int numPAPIEvents = 2;
67 int papiEvents[] = {PAPI_TOT_INS, PAPI_L1_DCM};
68 char *papiEventNames[] = {"PAPI_TOT_INS", "PAPI_L1_DCM"};
69 #endif
70  
71 /* ****** CW TEMPORARY LOCATION ***** Support for thread listeners */
72
73 struct TraceThreadListener {
74   struct CthThreadListener base;
75   int event;
76   int msgType;
77   int ep;
78   int srcPe;
79   int ml;
80   CmiObjId idx;
81 };
82
83
84 extern "C"
85 void traceThreadListener_suspend(struct CthThreadListener *l)
86 {
87   TraceThreadListener *a=(TraceThreadListener *)l;
88   /* here, we activate the appropriate trace codes for the appropriate
89      registered modules */
90   traceSuspend();
91 }
92
93 extern "C"
94 void traceThreadListener_resume(struct CthThreadListener *l) 
95 {
96   TraceThreadListener *a=(TraceThreadListener *)l;
97   /* here, we activate the appropriate trace codes for the appropriate
98      registered modules */
99   _TRACE_BEGIN_EXECUTE_DETAILED(a->event,a->msgType,a->ep,a->srcPe,a->ml,
100                                 CthGetThreadID(a->base.thread));
101   a->event=-1;
102   a->srcPe=CkMyPe(); /* potential lie to migrated threads */
103   a->ml=0;
104 }
105
106 extern "C"
107 void traceThreadListener_free(struct CthThreadListener *l) 
108 {
109   TraceThreadListener *a=(TraceThreadListener *)l;
110   delete a;
111 }
112
113 void TraceProjections::traceAddThreadListeners(CthThread tid, envelope *e)
114 {
115 #ifndef CMK_OPTIMIZE
116   /* strip essential information from the envelope */
117   TraceThreadListener *a= new TraceThreadListener;
118   
119   a->base.suspend=traceThreadListener_suspend;
120   a->base.resume=traceThreadListener_resume;
121   a->base.free=traceThreadListener_free;
122   a->event=e->getEvent();
123   a->msgType=e->getMsgtype();
124   a->ep=e->getEpIdx();
125   a->srcPe=e->getSrcPe();
126   a->ml=e->getTotalsize();
127
128   CthAddListener(tid, (CthThreadListener *)a);
129 #endif
130 }
131
132 void LogPool::openLog(const char *mode)
133 {
134 #if CMK_PROJECTIONS_USE_ZLIB
135   if(compressed) {
136     if (nonDeltaLog) {
137       do {
138         zfp = gzopen(fname, mode);
139       } while (!zfp && (errno == EINTR || errno == EMFILE));
140       if(!zfp) CmiAbort("Cannot open Projections Compressed Non Delta Trace File for writing...\n");
141     }
142     if (deltaLog) {
143       do {
144         deltazfp = gzopen(dfname, mode);
145       } while (!deltazfp && (errno == EINTR || errno == EMFILE));
146       if (!deltazfp) 
147         CmiAbort("Cannot open Projections Compressed Delta Trace File for writing...\n");
148     }
149   } else {
150     if (nonDeltaLog) {
151       do {
152         fp = fopen(fname, mode);
153       } while (!fp && (errno == EINTR || errno == EMFILE));
154       if(!fp) CmiAbort("Cannot open Projections Non Delta Trace File for writing...\n");
155     }
156     if (deltaLog) {
157       do {
158         deltafp = fopen(dfname, mode);
159       } while (!deltafp && (errno == EINTR || errno == EMFILE));
160       if (!deltafp) 
161         CmiAbort("Cannot open Projections Delta Trace File for writing...\n");
162     }
163   }
164 #else
165   if (nonDeltaLog) {
166     do {
167       fp = fopen(fname, mode);
168     } while (!fp && (errno == EINTR || errno == EMFILE));
169     if(!fp) CmiAbort("Cannot open Projections Non Delta Trace File for writing...\n");
170   }
171   if (deltaLog) {
172     do {
173       deltafp = fopen(dfname, mode);
174     } while (!deltafp && (errno == EINTR || errno == EMFILE));
175     if(!deltafp) 
176       CmiAbort("Cannot open Projections Delta Trace File for writing...\n");
177   }
178 #endif
179 }
180
181 void LogPool::closeLog(void)
182 {
183 #if CMK_PROJECTIONS_USE_ZLIB
184   if(compressed) {
185     if (nonDeltaLog) gzclose(zfp);
186     if (deltaLog) gzclose(deltazfp);
187     return;
188   }
189 #endif
190   if (nonDeltaLog) { 
191 #if !defined(_WIN32) || defined(__CYGWIN__)
192     fsync(fileno(fp)); 
193 #endif
194     fclose(fp); 
195   }
196   if (deltaLog)  { 
197 #if !defined(_WIN32) || defined(__CYGWIN__)
198     fsync(fileno(deltafp)); 
199 #endif
200     fclose(deltafp);  
201   }
202 }
203
204 /**
205   For each TraceFoo module, _createTraceFoo() must be defined.
206   This function is called in _createTraces() generated in moduleInit.C
207 */
208 void _createTraceprojections(char **argv)
209 {
210   DEBUGF(("%d createTraceProjections\n", CkMyPe()));
211   CkpvInitialize(CkVec<char *>, usrEventlist);
212   CkpvInitialize(CkVec<UsrEvent *>*, usrEvents);
213   CkpvAccess(usrEvents) = new CkVec<UsrEvent *>();
214 #if CMK_BLUEGENE_CHARM
215   // CthRegister does not call the constructor
216 //  CkpvAccess(usrEvents) = CkVec<UsrEvent *>();
217 #endif
218   CkpvInitialize(Trace*, _trace);
219   CkpvAccess(_trace) = new  TraceProjections(argv);
220   CkpvAccess(_traces)->addTrace(CkpvAccess(_trace));
221 }
222
223 LogPool::LogPool(char *pgm) {
224   pool = new LogEntry[CkpvAccess(CtrLogBufSize)];
225   numEntries = 0;
226   // **CW** for simple delta encoding
227   prevTime = 0.0;
228   timeErr = 0.0;
229   poolSize = CkpvAccess(CtrLogBufSize);
230   pgmname = new char[strlen(pgm)+1];
231   strcpy(pgmname, pgm);
232 }
233
234 void LogPool::creatFiles(char *fix)
235 {
236   char pestr[10];
237   sprintf(pestr, "%d", CkMyPe());
238 #if CMK_PROJECTIONS_USE_ZLIB
239   int len;
240   if(compressed)
241     len = strlen(pgmname)+strlen(fix)+strlen(".logold")+strlen(pestr)+strlen(".gz")+3;
242   else
243     len = strlen(pgmname)+strlen(fix)+strlen(".logold")+strlen(pestr)+3;
244 #else
245   int len = strlen(pgmname)+strlen(fix)+strlen(".logold")+strlen(pestr)+3;
246 #endif
247   if (nonDeltaLog) {
248     fname = new char[len];
249   }
250   if (deltaLog) {
251     dfname = new char[len];
252   }
253 #if CMK_PROJECTIONS_USE_ZLIB
254   if(compressed) {
255     if (deltaLog && nonDeltaLog) {
256       sprintf(fname, "%s%s.%s.logold.gz", pgmname, fix, pestr);
257       sprintf(dfname, "%s%s.%s.log.gz", pgmname, fix, pestr);
258     } else {
259       if (nonDeltaLog) {
260         sprintf(fname, "%s%s.%s.log.gz", pgmname, fix, pestr);
261       } else {
262         sprintf(dfname, "%s%s.%s.log.gz", pgmname, fix, pestr);
263       }
264     }
265   } else {
266     if (deltaLog && nonDeltaLog) {
267       sprintf(fname, "%s%s.%s.logold", pgmname, fix, pestr);
268       sprintf(dfname, "%s%s.%s.log", pgmname, fix, pestr);
269     } else {
270       if (nonDeltaLog) {
271         sprintf(fname, "%s%s.%s.log", pgmname, fix, pestr);
272       } else {
273         sprintf(dfname, "%s%s.%s.log", pgmname, fix, pestr);
274       }
275     }
276   }
277 #else
278   if (deltaLog && nonDeltaLog) {
279     sprintf(fname, "%s%s.%s.logold", pgmname, fix, pestr);
280     sprintf(dfname, "%s%s.%s.log", pgmname, fix, pestr);
281   } else {
282     if (nonDeltaLog) {
283       sprintf(fname, "%s%s.%s.log", pgmname, fix, pestr);
284     } else {
285       sprintf(dfname, "%s%s.%s.log", pgmname, fix, pestr);
286     }
287   }
288 #endif
289   openLog("w+");
290   CLOSE_LOG 
291
292   if (CkMyPe() == 0) 
293   {
294     char *fname = new char[strlen(CkpvAccess(traceRoot))+strlen(fix)+strlen(".sts")+2];
295     sprintf(fname, "%s%s.sts", CkpvAccess(traceRoot), fix);
296     do
297     {
298       stsfp = fopen(fname, "w");
299     } while (!stsfp && (errno == EINTR || errno == EMFILE));
300     if(stsfp==0)
301       CmiAbort("Cannot open projections sts file for writing.\n");
302     delete[] fname;
303   }
304   headerWritten = 0;
305 }
306
307 LogPool::~LogPool() 
308 {
309   writeLog();
310
311 #if CMK_BLUEGENE_CHARM
312   extern int correctTimeLog;
313   if (correctTimeLog) {
314     closeLog();
315     creatFiles("-bg");
316     writeHeader();
317     if (CkMyPe() == 0) writeSts(NULL);
318     postProcessLog();
319   }
320 #endif
321
322 #if !CMK_TRACE_LOGFILE_NUM_CONTROL
323   closeLog();
324 #endif
325   delete[] pool;
326   delete [] fname;
327 }
328
329 void LogPool::writeHeader()
330 {
331   if (headerWritten) return;
332   headerWritten = 1;
333   if(!binary) {
334 #if CMK_PROJECTIONS_USE_ZLIB
335     if(compressed) {
336       if (nonDeltaLog) {
337         gzprintf(zfp, "PROJECTIONS-RECORD %d\n", numEntries);
338       }
339       if (deltaLog) {
340         gzprintf(deltazfp, "PROJECTIONS-RECORD %d DELTA\n", numEntries);
341       }
342     } 
343     else /* else clause is below... */
344 #endif
345     /*... may hang over from else above */ {
346       if (nonDeltaLog) {
347         fprintf(fp, "PROJECTIONS-RECORD %d\n", numEntries);
348       }
349       if (deltaLog) {
350         fprintf(deltafp, "PROJECTIONS-RECORD %d DELTA\n", numEntries);
351       }
352     }
353   }
354   else { // binary
355       if (nonDeltaLog) {
356         fwrite(&numEntries,sizeof(numEntries),1,fp);
357       }
358       if (deltaLog) {
359         fwrite(&numEntries,sizeof(numEntries),1,deltafp);
360       }
361   }
362 }
363
364 void LogPool::writeLog(void)
365 {
366   OPEN_LOG
367   writeHeader();
368   if (nonDeltaLog) write(0);
369   if (deltaLog) write(1);
370   CLOSE_LOG
371 }
372
373 void LogPool::write(int writedelta) 
374 {
375   // **CW** Simple delta encoding implementation
376   // prevTime has to be maintained as an object variable because
377   // LogPool::write may be called several times depending on the
378   // +logsize value.
379   PUP::er *p = NULL;
380   if (binary) {
381     p = new PUP::toDisk(writedelta?deltafp:fp);
382   }
383 #if CMK_PROJECTIONS_USE_ZLIB
384   else if (compressed) {
385     p = new toProjectionsGZFile(writedelta?deltazfp:zfp);
386   }
387 #endif
388   else {
389     p = new toProjectionsFile(writedelta?deltafp:fp);
390   }
391   CmiAssert(p);
392   for(UInt i=0; i<numEntries; i++) {
393     if (!writedelta) {
394       pool[i].pup(*p);
395     }
396     else {      // delta
397       double time = pool[i].time;
398       if (pool[i].type != BEGIN_COMPUTATION && pool[i].type != END_COMPUTATION)
399       {
400         double timeDiff = (time-prevTime)*1.0e6;
401         UInt intTimeDiff = (UInt)timeDiff;
402         timeErr += timeDiff - intTimeDiff; /* timeErr is never >= 2.0 */
403         if (timeErr > 1.0) {
404           timeErr -= 1.0;
405           intTimeDiff++;
406         }
407         pool[i].time = intTimeDiff/1.0e6;
408       }
409       pool[i].pup(*p);
410       pool[i].time = time;      // restore time value
411       prevTime = time;
412     }
413   }
414   delete p;
415 }
416
417 void LogPool::writeSts(void)
418 {
419   // for whining compilers
420   int i;
421   char name[30];
422   // generate an automatic unique ID for each log
423   fprintf(stsfp, "PROJECTIONS_ID %s\n", "");
424   fprintf(stsfp, "VERSION %s\n", PROJECTION_VERSION);
425 #if CMK_HAS_COUNTER_PAPI
426   fprintf(stsfp, "TOTAL_PAPI_EVENTS %d\n", numPAPIEvents);
427   // for now, use i, next time use papiEvents[i].
428   // **CW** papi event names is a hack.
429   for (i=0;i<numPAPIEvents;i++) {
430     fprintf(stsfp, "PAPI_EVENT %d %s\n", i, papiEventNames[i]);
431   }
432 #endif
433   traceWriteSTS(stsfp,CkpvAccess(usrEvents)->length());
434   for(i=0;i<CkpvAccess(usrEvents)->length();i++){
435     fprintf(stsfp, "EVENT %d %s\n", (*CkpvAccess(usrEvents))[i]->e, (*CkpvAccess(usrEvents))[i]->str);
436   }     
437 }
438
439 void LogPool::writeSts(TraceProjections *traceProj){
440   writeSts();
441   if (traceProj != NULL) {
442     CkHashtableIterator  *funcIter = traceProj->getfuncIterator();
443     funcIter->seekStart();
444     int numFuncs = traceProj->getFuncNumber();
445     fprintf(stsfp,"TOTAL_FUNCTIONS %d \n",numFuncs);
446     while(funcIter->hasNext()) {
447       StrKey *key;
448       int *obj = (int *)funcIter->next((void **)&key);
449       fprintf(stsfp,"FUNCTION %d %s \n",*obj,key->getStr());
450     }
451   }
452   fprintf(stsfp, "END\n");
453   fclose(stsfp);
454 }
455
456
457 #if CMK_BLUEGENE_CHARM
458 static void updateProjLog(void *data, double t, double recvT, void *ptr)
459 {
460   LogEntry *log = (LogEntry *)data;
461   FILE *fp = *(FILE **)ptr;
462   log->time = t;
463   log->recvTime = recvT<0.0?0:recvT;
464 //  log->write(fp);
465   toProjectionsFile p(fp);
466   log->pup(p);
467 }
468 #endif
469
470 // flush log entries to disk
471 void LogPool::flushLogBuffer()
472 {
473   if (numEntries) {
474     double writeTime = TraceTimer();
475     writeLog();
476     numEntries = 0;
477     new (&pool[numEntries++]) LogEntry(writeTime, BEGIN_INTERRUPT);
478     new (&pool[numEntries++]) LogEntry(TraceTimer(), END_INTERRUPT);
479   }
480 }
481
482 void LogPool::add(UChar type,UShort mIdx,UShort eIdx,double time,int event,
483                   int pe, int ml, CmiObjId *id, double recvT, double cpuT)
484 {
485   new (&pool[numEntries++])
486     LogEntry(time, type, mIdx, eIdx, event, pe, ml, id, recvT, cpuT);
487   if(poolSize==numEntries) {
488     flushLogBuffer();
489 #if CMK_BLUEGENE_CHARM
490     extern int correctTimeLog;
491     if (correctTimeLog) CmiAbort("I/O interrupt!\n");
492 #endif
493   }
494 #if CMK_BLUEGENE_CHARM
495   switch (type) {
496     case BEGIN_PROCESSING:
497       pool[numEntries-1].recvTime = BgGetRecvTime();
498     case END_PROCESSING:
499     case BEGIN_COMPUTATION:
500     case END_COMPUTATION:
501     case CREATION:
502     case BEGIN_PACK:
503     case END_PACK:
504     case BEGIN_UNPACK:
505     case END_UNPACK:
506     case USER_EVENT_PAIR:
507       bgAddProjEvent(&pool[numEntries-1], numEntries-1, time, updateProjLog, &fp, BG_EVENT_PROJ);
508   }
509 #endif
510 }
511
512 void LogPool::add(UChar type,double time,UShort funcID,int lineNum,char *fileName){
513 #ifndef CMK_BLUEGENE_CHARM
514   new (&pool[numEntries++])
515         LogEntry(time,type,funcID,lineNum,fileName);
516   if(poolSize == numEntries){
517     flushLogBuffer();
518   }
519 #endif  
520 }
521
522 /* **CW** Not sure if this is the right thing to do. Feels more like
523    a hack than a solution to Sameer's request to add the destination
524    processor information to multicasts and broadcasts.
525
526    In the unlikely event this method is used for Broadcasts as well,
527    pelist == NULL will be used to indicate a global broadcast with 
528    num PEs.
529 */
530 void LogPool::addCreationMulticast(UShort mIdx, UShort eIdx, double time,
531                                    int event, int pe, int ml, CmiObjId *id,
532                                    double recvT, int num, int *pelist)
533 {
534   new (&pool[numEntries++])
535     LogEntry(time, mIdx, eIdx, event, pe, ml, id, recvT, num, pelist);
536   if(poolSize==numEntries) {
537     flushLogBuffer();
538   }
539 }
540
541 void LogPool::postProcessLog()
542 {
543 #if CMK_BLUEGENE_CHARM
544   bgUpdateProj(1);   // event type
545 #endif
546 }
547
548 LogEntry::LogEntry(double tm, unsigned short m, unsigned short e, int ev, int p,
549              int ml, CmiObjId *d, double rt, int num, int *pelist) 
550 {
551     type = CREATION_MULTICAST; mIdx = m; eIdx = e; event = ev; pe = p; time = tm; msglen = ml;
552     if (d) id = *d; else {id.id[0]=id.id[1]=id.id[2]=0; };
553     recvTime = rt; 
554     numpes = num;
555     if (pelist != NULL) {
556         pes = new int[num];
557         for (int i=0; i<num; i++) {
558           pes[i] = pelist[i];
559         }
560     } else {
561         pes= NULL;
562     }
563 }
564
565 void LogEntry::addPapi(int numPapiEvts, int *papi_ids, LONG_LONG_PAPI *papiVals)
566 {
567 #if CMK_HAS_COUNTER_PAPI
568   numPapiEvents = numPapiEvts;
569   if (papiVals != NULL) {
570     papiIDs = new int[numPapiEvents];
571     papiValues = new LONG_LONG_PAPI[numPapiEvents];
572     for (int i=0; i<numPapiEvents; i++) {
573       papiIDs[i] = papi_ids[i];
574       papiValues[i] = papiVals[i];
575     }
576   }
577 #endif
578 }
579
580 void LogEntry::pup(PUP::er &p)
581 {
582   int itime, irecvtime, icputime, i;
583   char ret = '\n';
584
585   p|type;
586   if (p.isPacking()) itime = (int)(1.0e6*time);
587   switch (type) {
588     case USER_EVENT:
589     case USER_EVENT_PAIR:
590       p|mIdx; p|itime; p|event; p|pe;
591       break;
592     case BEGIN_IDLE:
593     case END_IDLE:
594     case BEGIN_PACK:
595     case END_PACK:
596     case BEGIN_UNPACK:
597     case END_UNPACK:
598       p|itime; p|pe; 
599       break;
600     case BEGIN_PROCESSING:
601       if (p.isPacking()) {
602         irecvtime = (int)(recvTime==-1?-1:1.0e6*recvTime);
603         icputime = (int)(1.0e6*cputime);
604       }
605       p|mIdx; p|eIdx; p|itime; p|event; p|pe; 
606       p|msglen; p|irecvtime; p|id.id[0]; p|id.id[1]; p|id.id[2];
607       p|icputime;
608 #if CMK_HAS_COUNTER_PAPI
609       p|numPapiEvents;
610       for (i=0; i<numPapiEvents; i++) {
611         // not yet!!!
612         //      p|papiIDs[i]; 
613         p|papiValues[i];
614       }
615 #else
616       p|numPapiEvents;     // non papi version has value 0
617 #endif
618       if (p.isUnpacking()) {
619         recvTime = irecvtime/1.0e6;
620         cputime = icputime/1.0e6;
621       }
622       break;
623     case END_PROCESSING:
624       if (p.isPacking()) icputime = (int)(1.0e6*cputime);
625       p|mIdx; p|eIdx; p|itime; p|event; p|pe; p|msglen; p|icputime;
626 #if CMK_HAS_COUNTER_PAPI
627       p|numPapiEvents;
628       for (i=0; i<numPapiEvents; i++) {
629         // not yet!!!
630         //      p|papiIDs[i];
631         p|papiValues[i];
632       }
633 #else
634       p|numPapiEvents;  // non papi version has value 0
635 #endif
636       if (p.isUnpacking()) cputime = icputime/1.0e6;
637       break;
638     case CREATION:
639       if (p.isPacking()) irecvtime = (int)(1.0e6*recvTime);
640       p|mIdx; p|eIdx; p|itime;
641       p|event; p|pe; p|msglen; p|irecvtime;
642       if (p.isUnpacking()) recvTime = irecvtime/1.0e6;
643       break;
644     case CREATION_MULTICAST:
645       if (p.isPacking()) irecvtime = (int)(1.0e6*recvTime);
646       p|mIdx; p|eIdx; p|itime;
647       p|event; p|pe; p|msglen; p|irecvtime; p|numpes;
648       if (pes == NULL) {
649         int n=-1;
650         p(n);
651       }
652       else {
653         for (i=0; i<numpes; i++) p|pes[i];
654       }
655       if (p.isUnpacking()) recvTime = irecvtime/1.0e6;
656       break;
657     case MESSAGE_RECV:
658       p|mIdx; p|eIdx; p|itime; p|event; p|pe; p|msglen;
659       break;
660
661     case ENQUEUE:
662     case DEQUEUE:
663       p|mIdx; p|itime; p|event; p|pe;
664       break;
665
666     case BEGIN_INTERRUPT:
667     case END_INTERRUPT:
668       p|itime; p|event; p|pe;
669       break;
670
671       // **CW** absolute timestamps are used here to support a quick
672       // way of determining the total time of a run in projections
673       // visualization.
674     case BEGIN_COMPUTATION:
675     case END_COMPUTATION:
676     case BEGIN_TRACE:
677     case END_TRACE:
678       p|itime;
679       break;
680     case BEGIN_FUNC:
681         p | itime;
682         p | mIdx;
683         p | event;
684         if(!p.isUnpacking()){
685                 p(fName,flen-1);
686         }
687         break;
688     case END_FUNC:
689         p | itime;
690         p | mIdx;
691         break;
692     default:
693       CmiError("***Internal Error*** Wierd Event %d.\n", type);
694       break;
695   }
696   if (p.isUnpacking()) time = itime/1.0e6;
697   p|ret;
698 }
699
700 TraceProjections::TraceProjections(char **argv): 
701 curevent(0), inEntry(0), computationStarted(0)
702 {
703   if (CkpvAccess(traceOnPe) == 0) return;
704
705   CtvInitialize(int,curThreadEvent);
706   CtvAccess(curThreadEvent)=0;
707   checknested = CmiGetArgFlagDesc(argv,"+checknested","check projections nest begin end execute events");
708   int binary = CmiGetArgFlagDesc(argv,"+binary-trace","Write log files in (unreadable) binary format");
709 #if CMK_PROJECTIONS_USE_ZLIB
710   int compressed = CmiGetArgFlagDesc(argv,"+gz-trace","Write log files pre-compressed with gzip");
711 #endif
712
713   // **CW** default to non delta log encoding. The user may choose to do
714   // create both logs (for debugging) or just the old log timestamping
715   // (for compatibility).
716   // Generating just the non delta log takes precedence over generating
717   // both logs (if both arguments appear on the command line).
718
719   // switch to OLD log format until everything works // Gengbin
720   nonDeltaLog = 1;
721   deltaLog = 0;
722   deltaLog = CmiGetArgFlagDesc(argv, "+logDelta",
723                                   "Generate Delta encoded and simple timestamped log files");
724
725   _logPool = new LogPool(CkpvAccess(traceRoot));
726   _logPool->setBinary(binary);
727 #if CMK_PROJECTIONS_USE_ZLIB
728   _logPool->setCompressed(compressed);
729 #endif
730   _logPool->creatFiles();
731
732   funcCount=1;
733
734 #if CMK_HAS_COUNTER_PAPI
735   // We initialize and create the event sets for use with PAPI here.
736   int papiRetValue = PAPI_library_init(PAPI_VER_CURRENT);
737   if (papiRetValue != PAPI_VER_CURRENT) {
738     CmiAbort("PAPI Library initialization failure!\n");
739   }
740   if (PAPI_create_eventset(&papiEventSet) != PAPI_OK) {
741     CmiAbort("PAPI failed to create event set!\n");
742   }
743   papiRetValue = PAPI_add_events(papiEventSet, papiEvents, numPAPIEvents);
744   if (papiRetValue != PAPI_OK) {
745     if (papiRetValue == PAPI_ECNFLCT) {
746       CmiAbort("PAPI events conflict! Please re-assign event types!\n");
747     } else {
748       CmiAbort("PAPI failed to add designated events!\n");
749     }
750   }
751   papiValues = new long_long[numPAPIEvents];
752   memset(papiValues, 0, numPAPIEvents*sizeof(long_long));
753 #endif
754 }
755
756 int TraceProjections::traceRegisterUserEvent(const char* evt, int e)
757 {
758   OPTIMIZED_VERSION
759   CkAssert(e==-1 || e>=0);
760   CkAssert(evt != NULL);
761   int event;
762   int biggest = -1;
763   for (int i=0; i<CkpvAccess(usrEvents)->length(); i++) {
764     int cur = (*CkpvAccess(usrEvents))[i]->e;
765     if (cur == e) {
766       //CmiPrintf("%s %s\n", (*CkpvAccess(usrEvents))[i]->str, evt);
767       if (strcmp((*CkpvAccess(usrEvents))[i]->str, evt) == 0) 
768         return e;
769       else
770         CmiAbort("UserEvent double registered!");
771     }
772     if (cur > biggest) biggest = cur;
773   }
774   // if no user events have so far been registered. biggest will be -1
775   // and hence newly assigned event numbers will begin from 0.
776   if (e==-1) event = biggest+1;  // automatically assign new event number
777   else event = e;
778   CkpvAccess(usrEvents)->push_back(new UsrEvent(event,(char *)evt));
779   return event;
780 }
781
782 void TraceProjections::traceClearEps(void)
783 {
784   // In trace-summary, this zeros out the EP bins, to eliminate noise
785   // from startup.  Here, this isn't useful, since we can do that in
786   // post-processing
787 }
788
789 void TraceProjections::traceWriteSts(void)
790 {
791   if(CkMyPe()==0)
792     _logPool->writeSts(this);
793 }
794
795 void TraceProjections::traceClose(void)
796 {
797   if(CkMyPe()==0){
798     _logPool->writeSts(this);
799   }
800   CkpvAccess(_trace)->endComputation();
801   delete _logPool;              // will write
802   // remove myself from traceArray so that no tracing will be called.
803   CkpvAccess(_traces)->removeTrace(this);
804 //    delete CkpvAccess(_trace);
805 //  free(CkpvAccess(traceRoot));
806 }
807
808 void TraceProjections::traceBegin(void)
809 {
810   if (!computationStarted) return;
811   _logPool->add(BEGIN_TRACE, 0, 0, TraceTimer(), curevent++, CkMyPe());
812 }
813
814 void TraceProjections::traceEnd(void)
815 {
816   _logPool->add(END_TRACE, 0, 0, TraceTimer(), curevent++, CkMyPe());
817 }
818
819 void TraceProjections::userEvent(int e)
820 {
821   if (!computationStarted) return;
822   _logPool->add(USER_EVENT, e, 0, TraceTimer(),curevent++,CkMyPe());
823 }
824
825 void TraceProjections::userBracketEvent(int e, double bt, double et)
826 {
827   if (!computationStarted) return;
828   // two events record Begin/End of event e.
829   _logPool->add(USER_EVENT_PAIR, e, 0, TraceTimer(bt), curevent, CkMyPe());
830   _logPool->add(USER_EVENT_PAIR, e, 0, TraceTimer(et), curevent++, CkMyPe());
831 }
832
833 void TraceProjections::creation(envelope *e, int ep, int num)
834 {
835   double curTime = TraceTimer();
836   if(e==0) {
837     CtvAccess(curThreadEvent)=curevent;
838     _logPool->add(CREATION,ForChareMsg,ep,curTime,
839                     curevent++,CkMyPe(), 0, 0, 0.0);
840   } else {
841     int type=e->getMsgtype();
842     e->setEvent(curevent);
843     for(int i=0; i<num; i++) {
844       _logPool->add(CREATION,type,ep, curTime,
845                     curevent+i,CkMyPe(),e->getTotalsize(), 0, 0.0);
846     }
847     curevent += num;
848   }
849 }
850
851 /* **CW** Non-disruptive attempt to add destination PE knowledge to
852    Communication Library-specific Multicasts via new event 
853    CREATION_MULTICAST.
854 */
855
856 void TraceProjections::creationMulticast(envelope *e, int ep, int num,
857                                          int *pelist)
858 {
859   double curTime = TraceTimer();
860   if (e==0) {
861     CtvAccess(curThreadEvent)=curevent;
862     _logPool->addCreationMulticast(ForChareMsg, ep, curTime, curevent++,
863                                    CkMyPe(), 0, 0, 0.0, num, pelist);
864   } else {
865     int type=e->getMsgtype();
866     e->setEvent(curevent);
867     _logPool->addCreationMulticast(type, ep, curTime, curevent++, CkMyPe(),
868                                    e->getTotalsize(), 0, 0.0, num, pelist);
869   }
870 }
871
872 void TraceProjections::creationDone(int num)
873 {
874   // modified the creation done time of the last num log entries
875   // FIXME: totally a hack
876   double curTime = TraceTimer();
877   int idx = _logPool->numEntries-1;
878   while (idx >=0 && num >0 ) {
879     LogEntry &log = _logPool->pool[idx];
880     if (log.type == CREATION) {
881       log.recvTime = curTime - log.time;
882       num --;
883     }
884     idx--;
885   }
886 }
887
888 void TraceProjections::beginExecute(CmiObjId *tid)
889 {
890 #if CMK_HAS_COUNTER_PAPI
891   if (PAPI_read(papiEventSet, papiValues) != PAPI_OK) {
892     CmiAbort("PAPI failed to read at begin execute!\n");
893   }
894 #endif
895   if (checknested && inEntry) CmiAbort("Nested Begin Execute!\n");
896   execEvent = CtvAccess(curThreadEvent);
897   execEp = (-1);
898   _logPool->add(BEGIN_PROCESSING,ForChareMsg,_threadEP,TraceTimer(),
899                              execEvent,CkMyPe(), 0, tid);
900 #if CMK_HAS_COUNTER_PAPI
901   _logPool->addPapi(numPAPIEvents, papiEvents, papiValues);
902 #endif
903   inEntry = 1;
904 }
905
906 void TraceProjections::beginExecute(envelope *e)
907 {
908   if(e==0) {
909 #if CMK_HAS_COUNTER_PAPI
910     if (PAPI_read(papiEventSet, papiValues) != PAPI_OK) {
911       CmiAbort("PAPI failed to read at begin execute!\n");
912     }
913 #endif
914     if (checknested && inEntry) CmiAbort("Nested Begin Execute!\n");
915     execEvent = CtvAccess(curThreadEvent);
916     execEp = (-1);
917     _logPool->add(BEGIN_PROCESSING,ForChareMsg,_threadEP,TraceTimer(),
918                   execEvent,CkMyPe(), 0, 0, 0.0, TraceCpuTimer());
919 #if CMK_HAS_COUNTER_PAPI
920     _logPool->addPapi(numPAPIEvents, papiEvents, papiValues);
921 #endif
922     inEntry = 1;
923   } else {
924     beginExecute(e->getEvent(),e->getMsgtype(),e->getEpIdx(),e->getSrcPe(),e->getTotalsize());
925   }
926 }
927
928 void TraceProjections::beginExecute(int event,int msgType,int ep,int srcPe, int mlen,CmiObjId *idx)
929 {
930 #if CMK_HAS_COUNTER_PAPI
931   if (PAPI_read(papiEventSet, papiValues) != PAPI_OK) {
932     CmiAbort("PAPI failed to read at begin execute!\n");
933   }
934 #endif
935   if (checknested && inEntry) CmiAbort("Nested Begin Execute!\n");
936   execEvent=event;
937   execEp=ep;
938   execPe=srcPe;
939   _logPool->add(BEGIN_PROCESSING,msgType,ep,TraceTimer(),event,
940                 srcPe, mlen, idx, 0.0, TraceCpuTimer());
941 #if CMK_HAS_COUNTER_PAPI
942   _logPool->addPapi(numPAPIEvents, papiEvents, papiValues);
943 #endif
944   inEntry = 1;
945 }
946
947 void TraceProjections::endExecute(void)
948 {
949 #if CMK_HAS_COUNTER_PAPI
950   if (PAPI_read(papiEventSet, papiValues) != PAPI_OK) {
951     CmiAbort("PAPI failed to read at end execute!\n");
952   }
953 #endif
954   if (checknested && !inEntry) CmiAbort("Nested EndExecute!\n");
955   double cputime = TraceCpuTimer();
956   if(execEp == (-1)) {
957     _logPool->add(END_PROCESSING,0,_threadEP,TraceTimer(),
958                              execEvent,CkMyPe(),0,0,0.0,cputime);
959   } else {
960     _logPool->add(END_PROCESSING,0,execEp,TraceTimer(),
961                              execEvent,execPe,0,0,0.0,cputime);
962   }
963 #if CMK_HAS_COUNTER_PAPI
964   _logPool->addPapi(numPAPIEvents, papiEvents, papiValues);
965 #endif
966   inEntry = 0;
967 }
968
969 void TraceProjections::messageRecv(char *env, int pe)
970 {
971 #if 0
972   envelope *e = (envelope *)env;
973   int msgType = e->getMsgtype();
974   int ep = e->getEpIdx();
975 #if 0
976   if (msgType==NewChareMsg || msgType==NewVChareMsg
977           || msgType==ForChareMsg || msgType==ForVidMsg
978           || msgType==BocInitMsg || msgType==NodeBocInitMsg
979           || msgType==ForBocMsg || msgType==ForNodeBocMsg)
980     ep = e->getEpIdx();
981   else
982     ep = _threadEP;
983 #endif
984   _logPool->add(MESSAGE_RECV,msgType,ep,TraceTimer(),
985                              curevent++,e->getSrcPe(), e->getTotalsize());
986 #endif
987 }
988
989 void TraceProjections::beginIdle(double curWallTime)
990 {
991   _logPool->add(BEGIN_IDLE, 0, 0, TraceTimer(curWallTime), 0, CkMyPe());
992 }
993
994 void TraceProjections::endIdle(double curWallTime)
995 {
996   _logPool->add(END_IDLE, 0, 0, TraceTimer(curWallTime), 0, CkMyPe());
997 }
998
999 void TraceProjections::beginPack(void)
1000 {
1001   _logPool->add(BEGIN_PACK, 0, 0, TraceTimer(), 0, CkMyPe());
1002 }
1003
1004 void TraceProjections::endPack(void)
1005 {
1006   _logPool->add(END_PACK, 0, 0, TraceTimer(), 0, CkMyPe());
1007 }
1008
1009 void TraceProjections::beginUnpack(void)
1010 {
1011   _logPool->add(BEGIN_UNPACK, 0, 0, TraceTimer(), 0, CkMyPe());
1012 }
1013
1014 void TraceProjections::endUnpack(void)
1015 {
1016   _logPool->add(END_UNPACK, 0, 0, TraceTimer(), 0, CkMyPe());
1017 }
1018
1019 void TraceProjections::enqueue(envelope *) {}
1020
1021 void TraceProjections::dequeue(envelope *) {}
1022
1023 void TraceProjections::beginComputation(void)
1024 {
1025   computationStarted = 1;
1026 //  CkpvAccess(traceInitTime) = TRACE_TIMER();
1027 //  CkpvAccess(traceInitCpuTime) = TRACE_CPUTIMER();
1028   _logPool->add(BEGIN_COMPUTATION, 0, 0, TraceTimer(), -1, -1);
1029 #if CMK_HAS_COUNTER_PAPI
1030   // we start the counters here
1031   if (PAPI_start(papiEventSet) != PAPI_OK) {
1032     CmiAbort("PAPI failed to start designated counters!\n");
1033   }
1034 #endif
1035 }
1036
1037 void TraceProjections::endComputation(void)
1038 {
1039 #if CMK_HAS_COUNTER_PAPI
1040   // we stop the counters here. A silent failure is alright since we
1041   // are already at the end of the program.
1042   if (PAPI_stop(papiEventSet, papiValues) != PAPI_OK) {
1043     CkPrintf("Warning: PAPI failed to stop correctly!\n");
1044   }
1045   // NOTE: We should not do a complete close of PAPI until after the
1046   // sts writer is done.
1047 #endif
1048   _logPool->add(END_COMPUTATION, 0, 0, TraceTimer(), -1, -1);
1049 }
1050
1051 void TraceProjections::regFunc(const char *name, int &idx){
1052         StrKey k((char*)name,strlen(name));
1053         int num = funcHashtable.get(k);
1054         if(num == 0){
1055                 char *st = new char[strlen(name)+1];
1056                 memcpy(st,name,strlen(name)+1);
1057                 StrKey *newKey = new StrKey(st,strlen(st));
1058                 int &ref = funcHashtable.put(*newKey);
1059                 ref=funcCount;
1060                 num = funcCount;
1061                 funcCount++;
1062         }
1063         idx = num;      
1064 }
1065
1066 void TraceProjections::beginFunc(char *name,char *file,int line){
1067         StrKey k(name,strlen(name));    
1068         unsigned short  num = (unsigned short)funcHashtable.get(k);
1069         beginFunc(num,file,line);
1070 }
1071
1072 void TraceProjections::beginFunc(int idx,char *file,int line){
1073         if(idx <= 0){
1074                 CmiError("Unregistered function id %d being used in %s:%d \n",idx,file,line);
1075         }       
1076         _logPool->add(BEGIN_FUNC,TraceTimer(),idx,line,file);
1077 }
1078
1079 void TraceProjections::endFunc(char *name){
1080         StrKey k(name,strlen(name));    
1081         int num = funcHashtable.get(k);
1082         endFunc(num);   
1083 }
1084
1085 void TraceProjections::endFunc(int num){
1086         if(num <= 0){
1087                 printf("endFunc without start :O\n");
1088         }
1089         _logPool->add(END_FUNC,TraceTimer(),num,0,NULL);
1090 }
1091
1092 // specialized PUP:ers for handling trace projections logs
1093 void toProjectionsFile::bytes(void *p,int n,size_t itemSize,dataType t)
1094 {
1095   for (int i=0;i<n;i++) 
1096     switch(t) {
1097     case Tchar: CheckAndFPrintF(f,"%c",((char *)p)[i]); break;
1098     case Tuchar:
1099     case Tbyte: CheckAndFPrintF(f,"%d",((unsigned char *)p)[i]); break;
1100     case Tshort: CheckAndFPrintF(f," %d",((short *)p)[i]); break;
1101     case Tushort: CheckAndFPrintF(f," %u",((unsigned short *)p)[i]); break;
1102     case Tint: CheckAndFPrintF(f," %d",((int *)p)[i]); break;
1103     case Tuint: CheckAndFPrintF(f," %u",((unsigned int *)p)[i]); break;
1104     case Tlong: CheckAndFPrintF(f," %ld",((long *)p)[i]); break;
1105     case Tulong: CheckAndFPrintF(f," %lu",((unsigned long *)p)[i]); break;
1106     case Tfloat: CheckAndFPrintF(f," %.7g",((float *)p)[i]); break;
1107     case Tdouble: CheckAndFPrintF(f," %.15g",((double *)p)[i]); break;
1108     case Tlonglong: CheckAndFPrintF(f," %lld",((CMK_TYPEDEF_INT8 *)p)[i]); break;
1109     default: CmiAbort("Unrecognized pup type code!");
1110     };
1111 }
1112
1113 void fromProjectionsFile::bytes(void *p,int n,size_t itemSize,dataType t)
1114 {
1115   for (int i=0;i<n;i++) 
1116     switch(t) {
1117     case Tchar: { 
1118       char c = fgetc(f);
1119       if (c==EOF)
1120         parseError("Could not match character");
1121       else
1122         ((char *)p)[i] = c;
1123       break;
1124     }
1125     case Tuchar:
1126     case Tbyte: ((unsigned char *)p)[i]=(unsigned char)readInt("%d"); break;
1127     case Tshort:((short *)p)[i]=(short)readInt(); break;
1128     case Tushort: ((unsigned short *)p)[i]=(unsigned short)readUint(); break;
1129     case Tint:  ((int *)p)[i]=readInt(); break;
1130     case Tuint: ((unsigned int *)p)[i]=readUint(); break;
1131     case Tlong: ((long *)p)[i]=readInt(); break;
1132     case Tulong:((unsigned long *)p)[i]=readUint(); break;
1133     case Tfloat: ((float *)p)[i]=(float)readDouble(); break;
1134     case Tdouble:((double *)p)[i]=readDouble(); break;
1135     case Tlonglong: ((CMK_TYPEDEF_INT8 *)p)[i]=readLongInt(); break;
1136     default: CmiAbort("Unrecognized pup type code!");
1137     };
1138 }
1139
1140 #if CMK_PROJECTIONS_USE_ZLIB
1141 void toProjectionsGZFile::bytes(void *p,int n,size_t itemSize,dataType t)
1142 {
1143   for (int i=0;i<n;i++) 
1144     switch(t) {
1145     case Tchar: gzprintf(f,"%c",((char *)p)[i]); break;
1146     case Tuchar:
1147     case Tbyte: gzprintf(f,"%d",((unsigned char *)p)[i]); break;
1148     case Tshort: gzprintf(f," %d",((short *)p)[i]); break;
1149     case Tushort: gzprintf(f," %u",((unsigned short *)p)[i]); break;
1150     case Tint: gzprintf(f," %d",((int *)p)[i]); break;
1151     case Tuint: gzprintf(f," %u",((unsigned int *)p)[i]); break;
1152     case Tlong: gzprintf(f," %ld",((long *)p)[i]); break;
1153     case Tulong: gzprintf(f," %lu",((unsigned long *)p)[i]); break;
1154     case Tfloat: gzprintf(f," %.7g",((float *)p)[i]); break;
1155     case Tdouble: gzprintf(f," %.15g",((double *)p)[i]); break;
1156     case Tlonglong: gzprintf(f," %lld",((CMK_TYPEDEF_INT8 *)p)[i]); break;
1157     default: CmiAbort("Unrecognized pup type code!");
1158     };
1159 }
1160 #endif
1161
1162 /*@}*/