add in log summary the meaning of the thread_resume_ep, so that loadlog can tell...
[charm.git] / src / langs / bluegene / bigsim_logs.C
1 #include "blue.h"
2 #include "blue_impl.h"
3
4 #include "bigsim_logs.h"
5
6 /*
7  ChangeLog
8  version 2 
9      * add objId
10  version 3
11      * objId changed to 4 ints 
12 */
13
14 int bglog_version = BG_CURRENT_VERSION;
15
16 int genTimeLog = 0;                     // was 1 for guna 's seq correction
17 int correctTimeLog = 0;
18 int schedule_flag = 0;
19 int bgverbose = 0;
20 int bgcorroff = 0;
21
22 extern BgTimeLineRec* currTline;
23 extern int currTlineIdx;
24
25 // null timer for using blue_logs as a sequential library
26 static double nullTimer() { return 0.; }
27
28 // bluegene timer call
29 double (*timerFunc) (void) = nullTimer;
30
31 extern "C" void BgGenerateLogs()
32 {
33   genTimeLog = 1;;
34 }
35
36 // dstNode is the dest bg node, can be -1
37 BgMsgEntry::BgMsgEntry(char *msg, int dstNode, int tid, int local, int g)
38 {
39   msgID = CmiBgMsgID(msg);
40   sendTime = timerFunc();
41   recvTime = CmiBgMsgRecvTime(msg);
42   dstPe = dstNode;
43   tID = tid;                   // CmiBgMsgThreadID(msg);
44   msgsize = CmiBgMsgLength(msg);
45   group = g;
46   CmiAssert(msgsize > 0);
47 #if DELAY_SEND
48   sendMsg = NULL;
49   if (!local && correctTimeLog) sendMsg = msg;
50 #endif
51 }
52
53 BgMsgEntry::BgMsgEntry(int seqno, int _msgSize, double _sendTime, double _recvTime, int dstNode, int rank)
54 {
55   msgID = seqno;
56   sendTime = _sendTime;
57   recvTime = _recvTime;
58   dstPe = dstNode;
59   tID = rank;                   // CmiBgMsgThreadID(msg);
60   msgsize = _msgSize;
61   CmiAssert(msgsize > 0);
62 }
63
64 /*
65 #if DELAY_SEND
66 void BgMsgEntry::send() {
67   if (!sendMsg) return;
68   CmiBgMsgRecvTime(sendMsg) = recvTime;
69   if (dstPe >= 0) {
70     CmiSyncSendAndFree(nodeInfo::Global2PE(dstPe),CmiBgMsgLength(sendMsg),sendMsg);
71   }
72   else {
73     CmiSyncBroadcastAllAndFree(CmiBgMsgLength(sendMsg),sendMsg);
74   }
75   sendMsg = NULL;
76 }
77 #endif
78 */
79
80 void bgEvents::print()
81 {
82   switch (eType) {
83   case BG_EVENT_PROJ:
84         CmiPrintf("EVT: Projection %d\n", index);  break;
85   case BG_EVENT_PRINT: {
86         CmiPrintf("EVT: time:%f string:%s\n", rTime, data);
87         break;
88        }
89   case BG_EVENT_MARK: {
90         CmiPrintf("EVT: time:%f marker:%s\n", rTime, data);
91         break;
92        }
93   default: CmiAbort("bgEvents::pup(): unknown BG event type!");
94   }
95 }
96
97 void bgEvents::write(FILE *fp)
98 {
99   switch (eType) {
100   case BG_EVENT_PROJ:
101         fprintf(fp, "EVT: Projection %d\n", index);  break;
102   case BG_EVENT_PRINT: {
103         fprintf(fp, "EVT: time:%f string:%s\n", rTime, data);
104         break;
105        }
106   case BG_EVENT_MARK: {
107         fprintf(fp, "EVT: time:%f marker:%s\n", rTime, data);
108         break;
109        }
110   default: CmiAbort("bgEvents::pup(): unknown BG event type!");
111   }
112 }
113
114 void bgEvents::pup(PUP::er &p) 
115 {
116   p|eType; p|rTime;
117   switch (eType) {
118   case BG_EVENT_PROJ:
119            p|index;  break;
120   case BG_EVENT_MARK:
121   case BG_EVENT_PRINT: {
122              int slen = 0;
123              if (p.isPacking()) slen = strlen((char *)data)+1;
124              p|slen;
125              if (p.isUnpacking()) data=malloc(sizeof(char)*slen);
126              p((char *)data,slen); 
127              break;
128            }
129   default: CmiAbort("bgEvents::pup(): unknown BG event type!");
130   }
131 }
132
133 BgTimeLog::BgTimeLog(BgTimeLog *log)
134 {
135   strncpy(name,log->name,20);
136   ep = log->ep;
137   charm_ep = -1;
138   startTime = log->startTime;
139   recvTime = log->recvTime;
140   endTime = 0.0;
141   execTime = 0.0;
142   msgId = log->msgId;
143
144   seqno = 0;
145   effRecvTime = recvTime;
146   doCorrect = 1;
147   flag = 0;
148 }
149
150 BgTimeLog::BgTimeLog(const BgMsgID &msgID)
151 {
152   msgId = msgID;
153   strcpy(name, "msgep");
154   ep = -1;
155   charm_ep = -1;
156   startTime = -1.0;
157   recvTime = -1.0;
158   endTime = execTime = 0.0;
159
160   oldStartTime= startTime;
161   effRecvTime = -1.0;
162   seqno = 0;
163   doCorrect = 1;
164   flag = 0;
165 }
166
167 /*
168 BgTimeLog::BgTimeLog(int _ep, int srcpe, int msgid, double _startTime, double _endTime, double _recvTime, char *str)
169 {
170   if (str)
171     strcpy(name,str);
172   else
173     strcpy(name,"msgep");
174   startTime = _startTime;
175   endTime = _endTime;
176   execTime = endTime - startTime;
177   ep = _ep;
178   recvTime = _recvTime;
179   msgId = BgMsgID(srcpe, msgid);
180
181   recvTime = effRecvTime = startTime;
182 }
183 */
184
185 BgTimeLog::BgTimeLog(int epc, char* namestr,double sTime)
186
187   if(namestr == NULL)
188     namestr = (char*)"dummyname1";
189   strncpy(name,namestr,20);
190   ep = epc;
191   charm_ep = -1;
192   startTime = sTime;
193   recvTime = -1.0;//stime;
194   endTime = execTime = 0.0;
195
196   oldStartTime= startTime;
197   effRecvTime = -1.0;
198   seqno = 0;
199   doCorrect = 1;
200   flag = 0;
201 }
202
203 // for SDAG, somewhere else will set the effective recv time.
204 BgTimeLog::BgTimeLog(int epc, char* namestr, double sTime, double eTime)
205 {
206   if(namestr == NULL)
207     namestr = (char*)"dummyname2";
208   strncpy(name,namestr, 20);
209   ep = epc;
210   charm_ep = -1;
211   startTime = sTime;
212   recvTime = -1.0; //sTime;
213   endTime = eTime;
214   setExecTime();
215
216   oldStartTime = startTime;
217   effRecvTime = -1.0;
218   seqno = 0;
219   doCorrect = 1;
220   flag = 0;
221 }
222
223 // create a new log from a message
224 BgTimeLog::BgTimeLog(char *msg, char *str)
225 {
226   if (str)
227     strcpy(name,str);
228   else
229     strcpy(name,"msgep");
230   startTime = timerFunc();
231   endTime = 0.0;
232   execTime = 0.0;
233   recvTime = 0.0;
234   ep = -1;
235   charm_ep = -1;
236   if (msg) {
237     ep = CmiBgMsgHandle(msg);
238     recvTime = CmiBgMsgRecvTime(msg);  //startTime;
239     msgId = BgMsgID(CmiBgMsgSrcPe(msg), CmiBgMsgID(msg));
240   }
241
242   oldStartTime=startTime;
243   effRecvTime = recvTime;
244   seqno = 0;
245 //  doCorrect = msg?CkMsgDoCorrect(msg):1;
246   doCorrect = 1;
247   flag = 0;
248
249   if (genTimeLog && !doCorrect) {
250       recvTime = effRecvTime = startTime;
251   }
252 }
253
254 BgTimeLog::~BgTimeLog()
255 {
256   int i;
257   for (i=0; i<msgs.length(); i++)
258     delete msgs[i];
259   for (i=0; i<evts.length(); i++)
260     delete evts[i];
261 }
262
263
264 void BgTimeLog::closeLog() 
265
266     endTime = timerFunc();
267     setExecTime();
268     
269 //    if (correctTimeLog) BgAdjustTimeLineInsert(tTIMELINEREC);
270 }
271
272
273 void BgTimeLog::print(int node, int th)
274 {
275   int i;
276   CmiPrintf("<<== [%d th:%d] ep:%d name:%s startTime:%f endTime:%f execTIme:%f srcnode:%d msgID:%d\n", node, th, ep, name,startTime, endTime, execTime, msgId.node(), msgId.msgID());
277   for (i=0; i<msgs.length(); i++)
278     msgs[i]->print();
279   for (i=0; i<evts.length(); i++)
280     evts[i]->print();
281   CmiPrintf("==>>\n");
282 }
283
284
285 void BgTimeLog::write(FILE *fp)
286
287   int i;
288 //  fprintf(fp,"%p ep:%d name:%s (srcnode:%d msgID:%d) startTime:%f endTime:%f recvime:%f effRecvTime:%e seqno:%d startevent:%d\n", this, ep, name, msgId.node(), msgId.msgID(), startTime, endTime, recvTime, effRecvTime, seqno, isStartEvent());
289   fprintf(fp,"%p name:%s (srcnode:%d msgID:%d) ep:%d ", this, name, msgId.node(), msgId.msgID(), ep);
290   if (ep == BgLogGetThreadEP() && ep!=-1) fprintf(fp, "(thread resume) ");
291   if (bglog_version >= 4) fprintf(fp, "charm_ep:%d ", charm_ep);
292   if (isStartEvent()) fprintf(fp, "STARTEVENT");
293   if (isQDEvent()) fprintf(fp, "QDEVENT");
294   fprintf(fp, "\n");
295
296   fprintf(fp," recvtime:%f startTime:%f endTime:%f execTime:%f\n", recvTime, startTime, endTime, execTime);
297   if (bglog_version >= 2) {
298     if (!objId.isNull())
299       fprintf(fp," ObjID: %d %d %d %d\n", objId.id[0], objId.id[1], objId.id[2], objId.id[3]);
300   }
301   for (i=0; i<msgs.length(); i++)
302     msgs[i]->write(fp);
303   for (i=0; i<evts.length(); i++)
304     evts[i]->write(fp);
305   // fprintf(fp,"\nbackwardDeps [%d]:\n",backwardDeps.length());
306   fprintf(fp, "backward: ");
307   for (i=0; i<backwardDeps.length(); i++)
308     fprintf(fp,"[%p %d] ",backwardDeps[i], backwardDeps[i]->seqno);
309   fprintf(fp, "\n");
310   fprintf(fp, "forward: ");
311   for (i=0; i<forwardDeps.length(); i++)
312     fprintf(fp,"[%p %d] ",forwardDeps[i], forwardDeps[i]->seqno);
313   fprintf(fp, "\n");
314   fprintf(fp, "\n");
315 }
316
317 void BgTimeLog::addMsgBackwardDep(BgTimeLineRec &tlinerec, void* msg)
318 {
319   // CmiAssert(recvTime < 0.);
320   int idx;
321   BgTimeLog *msglog = tlinerec.getTimeLogOnThread(BgMsgID(CmiBgMsgSrcPe(msg), CmiBgMsgID(msg)), &idx);
322   //CmiAssert(msglog != NULL);
323   if (msglog != NULL) {
324     CmiAssert(msglog != this);
325     addBackwardDep(msglog);
326   }
327 }
328
329 // log  => this
330 void BgTimeLog::addBackwardDep(BgTimeLog* log)
331 {
332   //CmiAssert(recvTime < 0.);
333   if(log == NULL) return;
334   for (int i=0; i<backwardDeps.length(); i++)
335     if (backwardDeps[i] == log) return; // already exist
336   backwardDeps.insertAtEnd(log);
337   log->forwardDeps.insertAtEnd(this);
338   effRecvTime = BG_MAX(effRecvTime, log->effRecvTime);
339 }
340
341 void BgTimeLog::addBackwardDeps(CkVec<BgTimeLog*> logs){
342
343   /*put backward and forward dependents*/
344   for(int i=0;i<logs.length();i++)
345     addBackwardDep(logs[i]);
346 }
347
348 void BgTimeLog::addBackwardDeps(CkVec<void*> logs){
349
350   /*put backward and forward dependents*/
351   for(int i=0;i<logs.length();i++)
352     addBackwardDep((BgTimeLog*)(logs[i]));
353 }
354
355 int BgTimeLog::bDepExists(BgTimeLog* log){
356
357   for(int i =0;i<backwardDeps.length();i++)
358     if(backwardDeps[i] == log)
359       return 1;
360   return 0;
361 }
362
363 #if defined(_WIN32)
364 #define strcasecmp stricmp
365 #endif
366
367 void BgTimeLog::pup(PUP::er &p){
368     int l=0,idx;
369     int i;
370
371     if(p.isPacking()) {           // sanity check
372       if (!strcasecmp(name, "BgSchedulerEnd")) {       // exit event
373         if (endTime == 0.0) {
374           endTime = startTime;
375           if (msgs.length() > 0 && msgs[msgs.length()-1]->sendTime > endTime)
376             endTime = msgs[msgs.length()-1]->sendTime;
377           execTime = endTime - startTime;
378         }
379       }
380     }
381
382     p|ep; 
383     p|seqno; p|msgId;
384     if (bglog_version >= 4) p(charm_ep);
385     p|recvTime; p|effRecvTime;p|startTime; p|execTime; p|endTime; 
386     p|flag; p(name,20);
387     if (bglog_version >= 3)
388       p((int *)&objId, sizeof(CmiObjId)/sizeof(int));
389     else if (bglog_version == 2)
390       p((int *)&objId, 3);           // only 3 ints before
391     
392     /*    if(p.isUnpacking())
393       CmiPrintf("Puping: %d %d %d %d %e %e %e %e %e %s\n",ep,seqno,srcnode,msgID,recvTime,effRecvTime,startTime,execTime,endTime,name);
394     */
395
396 /*
397     if(p.isUnpacking()){
398       threadNum = currTlineIdx;
399     }
400 */
401
402     // pup for BgMsgEntry
403     if(!p.isUnpacking()) l=msgs.length();
404     p|l;
405
406     for(i=0;i<l;i++) {
407       if (p.isUnpacking()) msgs.push_back(new BgMsgEntry);
408       msgs[i]->pup(p);
409     }
410
411     // pup events list for projections
412     if(!p.isUnpacking()) l=evts.length();
413     p|l;
414
415     for(i=0;i<l;i++) {
416       if (p.isUnpacking()) evts.push_back(new bgEvents);
417       evts[i]->pup(p);
418     }
419
420     // pup for backwardDeps
421     if(!p.isUnpacking()) l = backwardDeps.length();
422     p|l;    
423
424     for(i=0;i<l;i++){
425       if(p.isUnpacking()){
426         p|idx;
427         CmiAssert(currTline != NULL);
428         addBackwardDep(currTline->timeline[idx]);
429       }
430       else{
431         p|backwardDeps[i]->seqno;
432       }
433     }
434  
435     if(!p.isUnpacking()) l=forwardDeps.length();
436     p|l;
437
438     for(i=0;i<l;i++){ 
439       if(p.isUnpacking())
440         p|idx;
441       else
442         p|forwardDeps[i]->seqno;
443     }
444
445     // a sanity check for floatable events
446     if (msgId == BgMsgID(-1,-1) && backwardDeps.length() == 0 && recvTime == -1.0) {
447       CmiPrintf("Potential error in log: (a floating event) \n");
448       print(-1,-1);
449     }
450 }
451
452 // create a log with msg and insert into timeline
453 void BgTimeLineRec::logEntryStart(char *msg) {
454 //CmiPrintf("[%d] BgTimeLineRec::logEntryStart\n", BgGetGlobalWorkerThreadID());
455   CmiAssert(genTimeLog);
456   if (!genTimeLog) return;
457   CmiAssert(bgCurLog == NULL);
458   bgCurLog = new BgTimeLog(msg);
459   enq(bgCurLog, 1);
460 }
461
462 // insert an log into timeline
463 void BgTimeLineRec::logEntryInsert(BgTimeLog* log)
464 {
465   CmiAssert(genTimeLog);
466   if (!genTimeLog) return;
467 //CmiPrintf("[%d] BgTimeLineRec::logEntryInsert\n", BgGetGlobalWorkerThreadID());
468   CmiAssert(bgCurLog == NULL);
469   if(timeline.length() > 0 && timeline[timeline.length()-1]->endTime == 0.0)
470     CmiPrintf("\nERROR tried to insert %s after %s\n",log->name,timeline[timeline.length()-1]->name);
471   enq(log, 1);
472   if (bgPrevLog) {
473     log->addBackwardDep(bgPrevLog);
474     bgPrevLog = NULL;
475   }
476 }
477
478 void BgTimeLineRec::logEntryStart(BgTimeLog* log)
479 {
480 //CmiPrintf("[%d] BgTimeLineRec::logEntryStart with log\n", BgGetGlobalWorkerThreadID());
481   logEntryInsert(log);
482   bgCurLog = log;
483 }
484
485 void BgTimeLineRec::logEntryClose() {
486   CmiAssert(genTimeLog);
487   if (!genTimeLog) return;
488 //CmiPrintf("[%d] BgTimeLineRec::logEntryClose\n", BgGetGlobalWorkerThreadID());
489   BgTimeLog *lastlog = timeline.length()?timeline[timeline.length()-1]:NULL;
490   CmiAssert(bgCurLog == lastlog);
491   lastlog->closeLog();
492   bgCurLog = NULL;
493 }
494
495 void BgTimeLineRec::logEntrySplit(const char *name)
496 {
497 //CmiPrintf("BgTimeLineRec::logEntrySplit\n");
498   CmiAssert(genTimeLog);
499   if (!genTimeLog) return;
500   CmiAssert(bgCurLog != NULL);
501   BgTimeLog *rootLog = bgCurLog;
502   logEntryClose();
503
504   // make up a new bglog to start, setting up dependencies.
505   BgTimeLog *newLog = new BgTimeLog(-1, (char*)name, timerFunc());
506   newLog->addBackwardDep(rootLog);
507   logEntryInsert(newLog);
508   bgCurLog = newLog;
509 }
510
511 BgTimeLog *
512 BgTimeLineRec::getTimeLogOnThread(const BgMsgID &msgId, int *index)
513 {
514   int idxOld = timeline.length()-1;
515   while (idxOld >= 0)  {
516     if (timeline[idxOld]->msgId == msgId) break;
517     idxOld--;
518   }
519                                                                                 
520   *index = idxOld;
521   if (idxOld == -1) return NULL;
522   return timeline[idxOld];
523 }
524
525 void BgTimeLineRec::pup(PUP::er &p)
526 {
527     int l=length();
528     p|l;
529     //    CmiPrintf("Puped len: %d\n",l);
530     if(!p.isUnpacking()){
531       // reorder the seqno
532       for(int i=0;i<l;i++)
533         timeline[i]->seqno = i;
534     }
535     else{
536       //Timeline is empty when unpacking pup is called
537       //timeline.removeFrom(0);
538     }
539
540     for (int i=0;i<l;i++) {
541         if (p.isUnpacking()) {
542                 BgTimeLog* t = new BgTimeLog();
543                 t->pup(p);
544                 timeline.enq(t);
545         }
546         else {
547           timeline[i]->pup(p);
548         }
549     }
550 }
551