Actual source code: eventLog.c
1: #define PETSC_DLL
3: #include petsc.h
4: #include petsctime.h
5: #include plog.h
7: /* Variables for the tracing logger */
14: /*----------------------------------------------- Creation Functions -------------------------------------------------*/
15: /* Note: these functions do not have prototypes in a public directory, so they are considered "internal" and not exported. */
19: /*@C
20: EventRegLogCreate - This creates a EventRegLog object.
22: Not collective
24: Input Parameter:
25: . eventLog - The EventRegLog
27: Level: beginner
29: .keywords: log, event, create
30: .seealso: EventRegLogDestroy(), StageLogCreate()
31: @*/
32: PetscErrorCode EventRegLogCreate(EventRegLog *eventLog)
33: {
34: EventRegLog l;
38: PetscNew(struct _n_EventRegLog, &l);
39: l->numEvents = 0;
40: l->maxEvents = 100;
41: PetscMalloc(l->maxEvents * sizeof(EventRegInfo), &l->eventInfo);
42: *eventLog = l;
43: return(0);
44: }
48: /*@C
49: EventRegLogDestroy - This destroys a EventRegLog object.
51: Not collective
53: Input Paramter:
54: . eventLog - The EventRegLog
56: Level: beginner
58: .keywords: log, event, destroy
59: .seealso: EventRegLogCreate()
60: @*/
61: PetscErrorCode EventRegLogDestroy(EventRegLog eventLog)
62: {
63: int e;
67: for(e = 0; e < eventLog->numEvents; e++) {
68: PetscFree(eventLog->eventInfo[e].name);
69: }
70: PetscFree(eventLog->eventInfo);
71: PetscFree(eventLog);
72: return(0);
73: }
77: /*@C
78: EventPerfLogCreate - This creates a EventPerfLog object.
80: Not collective
82: Input Parameter:
83: . eventLog - The EventPerfLog
85: Level: beginner
87: .keywords: log, event, create
88: .seealso: EventPerfLogDestroy(), StageLogCreate()
89: @*/
90: PetscErrorCode EventPerfLogCreate(EventPerfLog *eventLog)
91: {
92: EventPerfLog l;
96: PetscNew(struct _n_EventPerfLog, &l);
97: l->numEvents = 0;
98: l->maxEvents = 100;
99: PetscMalloc(l->maxEvents * sizeof(EventPerfInfo), &l->eventInfo);
100: *eventLog = l;
101: return(0);
102: }
106: /*@C
107: EventPerfLogDestroy - This destroys a EventPerfLog object.
109: Not collective
111: Input Paramter:
112: . eventLog - The EventPerfLog
114: Level: beginner
116: .keywords: log, event, destroy
117: .seealso: EventPerfLogCreate()
118: @*/
119: PetscErrorCode EventPerfLogDestroy(EventPerfLog eventLog)
120: {
124: PetscFree(eventLog->eventInfo);
125: PetscFree(eventLog);
126: return(0);
127: }
129: /*------------------------------------------------ General Functions -------------------------------------------------*/
132: /*@C
133: EventPerfInfoClear - This clears a EventPerfInfo object.
135: Not collective
137: Input Paramter:
138: . eventInfo - The EventPerfInfo
140: Level: beginner
142: .keywords: log, event, destroy
143: .seealso: EventPerfLogCreate()
144: @*/
145: PetscErrorCode EventPerfInfoClear(EventPerfInfo *eventInfo)
146: {
148: eventInfo->id = -1;
149: eventInfo->active = PETSC_TRUE;
150: eventInfo->visible = PETSC_TRUE;
151: eventInfo->depth = 0;
152: eventInfo->count = 0;
153: eventInfo->flops = 0.0;
154: eventInfo->time = 0.0;
155: eventInfo->numMessages = 0.0;
156: eventInfo->messageLength = 0.0;
157: eventInfo->numReductions = 0.0;
158: return(0);
159: }
163: /*@C
164: EventPerfInfoCopy - Copy the activity and visibility data in eventInfo to outInfo
166: Not collective
168: Input Paramter:
169: . eventInfo - The input EventPerfInfo
171: Output Paramter:
172: . outInfo - The output EventPerfInfo
174: Level: beginner
176: .keywords: log, event, copy
177: .seealso: EventPerfInfoClear()
178: @*/
179: PetscErrorCode EventPerfInfoCopy(EventPerfInfo *eventInfo, EventPerfInfo *outInfo)
180: {
182: outInfo->id = eventInfo->id;
183: outInfo->active = eventInfo->active;
184: outInfo->visible = eventInfo->visible;
185: return(0);
186: }
190: /*@C
191: EventPerfLogEnsureSize - This ensures that a EventPerfLog is at least of a certain size.
193: Not collective
195: Input Paramters:
196: + eventLog - The EventPerfLog
197: - size - The size
199: Level: intermediate
201: .keywords: log, event, size, ensure
202: .seealso: EventPerfLogCreate()
203: @*/
204: PetscErrorCode EventPerfLogEnsureSize(EventPerfLog eventLog, int size)
205: {
206: EventPerfInfo *eventInfo;
210: while(size > eventLog->maxEvents) {
211: PetscMalloc(eventLog->maxEvents*2 * sizeof(EventPerfInfo), &eventInfo);
212: PetscMemcpy(eventInfo, eventLog->eventInfo, eventLog->maxEvents * sizeof(EventPerfInfo));
213: PetscFree(eventLog->eventInfo);
214: eventLog->eventInfo = eventInfo;
215: eventLog->maxEvents *= 2;
216: }
217: while(eventLog->numEvents < size) {
218: EventPerfInfoClear(&eventLog->eventInfo[eventLog->numEvents++]);
219: }
220: return(0);
221: }
223: /*--------------------------------------------- Registration Functions ----------------------------------------------*/
226: /*@C
227: EventRegLogRegister - Registers an event for logging operations in an application code.
229: Not Collective
231: Input Parameters:
232: + eventLog - The EventLog
233: . ename - The name associated with the event
234: - cookie - The cookie associated to the class for this event
236: Output Parameter:
237: . event - The event
239: Example of Usage:
240: .vb
241: int USER_EVENT;
242: int user_event_flops;
245: [code segment to monitor]
246: PetscLogFlops(user_event_flops);
248: .ve
250: Notes:
251: PETSc automatically logs library events if the code has been
252: compiled with -DPETSC_USE_LOG (which is the default) and -log,
254: intended for logging user events to supplement this PETSc
255: information.
257: PETSc can gather data for use with the utilities Upshot/Nupshot
258: (part of the MPICH distribution). If PETSc has been compiled
259: with flag -DPETSC_HAVE_MPE (MPE is an additional utility within
260: MPICH), the user can employ another command line option, -log_mpe,
261: to create a logfile, "mpe.log", which can be visualized
262: Upshot/Nupshot.
264: Level: intermediate
266: .keywords: log, event, register
268: EventLogActivate(), EventLogDeactivate()
269: @*/
270: PetscErrorCode EventRegLogRegister(EventRegLog eventLog, const char ename[], PetscCookie cookie, PetscEvent *event)
271: {
272: EventRegInfo *eventInfo;
273: char *str;
274: int e;
280: /* Should check cookie I think */
281: e = eventLog->numEvents++;
282: if (eventLog->numEvents > eventLog->maxEvents) {
283: PetscMalloc(eventLog->maxEvents*2 * sizeof(EventRegInfo), &eventInfo);
284: PetscMemcpy(eventInfo, eventLog->eventInfo, eventLog->maxEvents * sizeof(EventRegInfo));
285: PetscFree(eventLog->eventInfo);
286: eventLog->eventInfo = eventInfo;
287: eventLog->maxEvents *= 2;
288: }
289: PetscStrallocpy(ename, &str);
290: eventLog->eventInfo[e].name = str;
291: eventLog->eventInfo[e].cookie = cookie;
292: #if defined(PETSC_HAVE_MPE)
293: if (UseMPE) {
294: const char *color;
295: PetscMPIInt rank;
296: int beginID, endID;
298: beginID = MPE_Log_get_event_number();
299: endID = MPE_Log_get_event_number();
300: eventLog->eventInfo[e].mpe_id_begin = beginID;
301: eventLog->eventInfo[e].mpe_id_end = endID;
302: MPI_Comm_rank(PETSC_COMM_WORLD, &rank);
303: if (!rank) {
304: PetscLogGetRGBColor(&color);
305: MPE_Describe_state(beginID, endID, str, (char*)color);
306: }
307: }
308: #endif
309: *event = e;
310: return(0);
311: }
313: /*---------------------------------------------- Activation Functions -----------------------------------------------*/
316: /*@C
317: EventPerfLogActivate - Indicates that a particular event should be logged.
319: Not Collective
321: Input Parameters:
322: + eventLog - The EventPerfLog
323: - event - The event
325: Usage:
326: .vb
327: EventPerfLogDeactivate(log, VEC_SetValues);
328: [code where you do not want to log VecSetValues()]
329: EventPerfLogActivate(log, VEC_SetValues);
330: [code where you do want to log VecSetValues()]
331: .ve
333: Note:
334: The event may be either a pre-defined PETSc event (found in
335: include/petsclog.h) or an event number obtained with EventRegLogRegister().
337: Level: advanced
339: .keywords: log, event, activate
341: @*/
342: PetscErrorCode EventPerfLogActivate(EventPerfLog eventLog, PetscEvent event)
343: {
345: eventLog->eventInfo[event].active = PETSC_TRUE;
346: return(0);
347: }
351: /*@C
352: EventPerfLogDeactivate - Indicates that a particular event should not be logged.
354: Not Collective
356: Input Parameters:
357: + eventLog - The EventPerfLog
358: - event - The event
360: Usage:
361: .vb
362: EventPerfLogDeactivate(log, VEC_SetValues);
363: [code where you do not want to log VecSetValues()]
364: EventPerfLogActivate(log, VEC_SetValues);
365: [code where you do want to log VecSetValues()]
366: .ve
368: Note:
369: The event may be either a pre-defined PETSc event (found in
370: include/petsclog.h) or an event number obtained with EventRegLogRegister().
372: Level: advanced
374: .keywords: log, event, activate
376: @*/
377: PetscErrorCode EventPerfLogDeactivate(EventPerfLog eventLog, PetscEvent event)
378: {
380: eventLog->eventInfo[event].active = PETSC_FALSE;
381: return(0);
382: }
386: /*@C
387: EventPerfLogActivateClass - Activates event logging for a PETSc object class.
389: Not Collective
391: Input Parameters:
392: + eventLog - The EventPerfLog
393: . eventRegLog - The EventRegLog
394: - cookie - The class id, for example MAT_COOKIE, SNES_COOKIE,
396: Level: developer
398: .seealso: EventPerfLogDeactivateClass(), EventPerfLogActivate(), EventPerfLogDeactivate()
399: @*/
400: PetscErrorCode EventPerfLogActivateClass(EventPerfLog eventLog, EventRegLog eventRegLog, PetscCookie cookie)
401: {
402: int e;
405: for(e = 0; e < eventLog->numEvents; e++) {
406: int c = eventRegLog->eventInfo[e].cookie;
408: if (c == cookie) eventLog->eventInfo[e].active = PETSC_TRUE;
409: }
410: return(0);
411: }
415: /*@C
416: EventPerfLogDeactivateClass - Deactivates event logging for a PETSc object class.
418: Not Collective
420: Input Parameters:
421: + eventLog - The EventPerfLog
422: . eventRegLog - The EventRegLog
423: - cookie - The class id, for example MAT_COOKIE, SNES_COOKIE,
425: Level: developer
427: .seealso: EventPerfLogDeactivateClass(), EventPerfLogDeactivate(), EventPerfLogActivate()
428: @*/
429: PetscErrorCode EventPerfLogDeactivateClass(EventPerfLog eventLog, EventRegLog eventRegLog, PetscCookie cookie)
430: {
431: int e;
434: for(e = 0; e < eventLog->numEvents; e++) {
435: int c = eventRegLog->eventInfo[e].cookie;
437: if (c == cookie) eventLog->eventInfo[e].active = PETSC_FALSE;
438: }
439: return(0);
440: }
442: /*------------------------------------------------ Query Functions --------------------------------------------------*/
445: /*@C
446: EventPerfLogSetVisible - This function determines whether an event is printed during PetscLogPrintSummary()
448: Not Collective
450: Input Parameters:
451: + eventLog - The EventPerfLog
452: . event - The event to log
453: - isVisible - The visibility flag, PETSC_TRUE for printing, otherwise PETSC_FALSE (default is PETSC_TRUE)
455: Database Options:
456: . -log_summary - Activates log summary
458: Level: intermediate
460: .keywords: log, visible, event
461: .seealso: EventPerfLogGetVisible(), EventRegLogRegister(), StageLogGetEventLog()
462: @*/
463: PetscErrorCode EventPerfLogSetVisible(EventPerfLog eventLog, PetscEvent event, PetscTruth isVisible)
464: {
466: eventLog->eventInfo[event].visible = isVisible;
467: return(0);
468: }
472: /*@C
473: EventPerfLogGetVisible - This function returns whether an event is printed during PetscLogPrintSummary()
475: Not Collective
477: Input Parameters:
478: + eventLog - The EventPerfLog
479: - event - The event id to log
481: Output Parameter:
482: . isVisible - The visibility flag, PETSC_TRUE for printing, otherwise PETSC_FALSE (default is PETSC_TRUE)
484: Database Options:
485: . -log_summary - Activates log summary
487: Level: intermediate
489: .keywords: log, visible, event
490: .seealso: EventPerfLogSetVisible(), EventRegLogRegister(), StageLogGetEventLog()
491: @*/
492: PetscErrorCode EventPerfLogGetVisible(EventPerfLog eventLog, PetscEvent event, PetscTruth *isVisible)
493: {
496: *isVisible = eventLog->eventInfo[event].visible;
497: return(0);
498: }
500: /*------------------------------------------------ Action Functions -------------------------------------------------*/
504: {
505: StageLog stageLog;
506: EventPerfLog eventLog;
507: int stage;
511: PetscLogGetStageLog(&stageLog);
512: StageLogGetCurrent(stageLog, &stage);
513: StageLogGetEventPerfLog(stageLog, stage, &eventLog);
514: /* Check for double counting */
515: eventLog->eventInfo[event].depth++;
516: if (eventLog->eventInfo[event].depth > 1) return(0);
517: /* Log performance info */
518: eventLog->eventInfo[event].count++;
519: PetscTimeSubtract(eventLog->eventInfo[event].time);
520: eventLog->eventInfo[event].flops -= _TotalFlops;
521: eventLog->eventInfo[event].numMessages -= irecv_ct + isend_ct + recv_ct + send_ct;
522: eventLog->eventInfo[event].messageLength -= irecv_len + isend_len + recv_len + send_len;
523: eventLog->eventInfo[event].numReductions -= allreduce_ct;
524: return(0);
525: }
530: {
531: StageLog stageLog;
532: EventPerfLog eventLog;
533: int stage;
537: PetscLogGetStageLog(&stageLog);
538: StageLogGetCurrent(stageLog, &stage);
539: StageLogGetEventPerfLog(stageLog, stage, &eventLog);
540: /* Check for double counting */
541: eventLog->eventInfo[event].depth--;
542: if (eventLog->eventInfo[event].depth > 0) {
543: return(0);
544: } else if (eventLog->eventInfo[event].depth < 0) {
545: SETERRQ(PETSC_ERR_ARG_WRONGSTATE, "Logging event had unbalanced begin/end pairs");
546: }
547: /* Log performance info */
548: PetscTimeAdd(eventLog->eventInfo[event].time);
549: eventLog->eventInfo[event].flops += _TotalFlops;
550: eventLog->eventInfo[event].numMessages += irecv_ct + isend_ct + recv_ct + send_ct;
551: eventLog->eventInfo[event].messageLength += irecv_len + isend_len + recv_len + send_len;
552: eventLog->eventInfo[event].numReductions += allreduce_ct;
553: return(0);
554: }
559: {
560: StageLog stageLog;
561: EventRegLog eventRegLog;
562: EventPerfLog eventPerfLog;
563: Action *tmpAction;
564: PetscLogDouble start, end;
565: PetscLogDouble curTime;
566: int stage;
570: /* Dynamically enlarge logging structures */
571: if (numActions >= maxActions) {
572: PetscTime(start);
573: PetscMalloc(maxActions*2 * sizeof(Action), &tmpAction);
574: PetscMemcpy(tmpAction, actions, maxActions * sizeof(Action));
575: PetscFree(actions);
576: actions = tmpAction;
577: maxActions *= 2;
578: PetscTime(end);
579: BaseTime += (end - start);
580: }
581: /* Record the event */
582: PetscLogGetStageLog(&stageLog);
583: StageLogGetCurrent(stageLog, &stage);
584: StageLogGetEventRegLog(stageLog, &eventRegLog);
585: StageLogGetEventPerfLog(stageLog, stage, &eventPerfLog);
586: PetscTime(curTime);
587: if (logActions) {
588: actions[numActions].time = curTime - BaseTime;
589: actions[numActions].action = ACTIONBEGIN;
590: actions[numActions].event = event;
591: actions[numActions].cookie = eventRegLog->eventInfo[event].cookie;
592: if (o1) actions[numActions].id1 = o1->id; else actions[numActions].id1 = -1;
593: if (o2) actions[numActions].id2 = o2->id; else actions[numActions].id2 = -1;
594: if (o3) actions[numActions].id3 = o3->id; else actions[numActions].id3 = -1;
595: actions[numActions].flops = _TotalFlops;
596: PetscMallocGetCurrentUsage(&actions[numActions].mem);
597: PetscMallocGetMaximumUsage(&actions[numActions].maxmem);
598: numActions++;
599: }
600: /* Check for double counting */
601: eventPerfLog->eventInfo[event].depth++;
602: if (eventPerfLog->eventInfo[event].depth > 1) return(0);
603: /* Log the performance info */
604: eventPerfLog->eventInfo[event].count++;
605: eventPerfLog->eventInfo[event].time -= curTime;
606: eventPerfLog->eventInfo[event].flops -= _TotalFlops;
607: eventPerfLog->eventInfo[event].numMessages -= irecv_ct + isend_ct + recv_ct + send_ct;
608: eventPerfLog->eventInfo[event].messageLength -= irecv_len + isend_len + recv_len + send_len;
609: eventPerfLog->eventInfo[event].numReductions -= allreduce_ct;
610: return(0);
611: }
616: {
617: StageLog stageLog;
618: EventRegLog eventRegLog;
619: EventPerfLog eventPerfLog;
620: Action *tmpAction;
621: PetscLogDouble start, end;
622: PetscLogDouble curTime;
623: int stage;
627: /* Dynamically enlarge logging structures */
628: if (numActions >= maxActions) {
629: PetscTime(start);
630: PetscMalloc(maxActions*2 * sizeof(Action), &tmpAction);
631: PetscMemcpy(tmpAction, actions, maxActions * sizeof(Action));
632: PetscFree(actions);
633: actions = tmpAction;
634: maxActions *= 2;
635: PetscTime(end);
636: BaseTime += (end - start);
637: }
638: /* Record the event */
639: PetscLogGetStageLog(&stageLog);
640: StageLogGetCurrent(stageLog, &stage);
641: StageLogGetEventRegLog(stageLog, &eventRegLog);
642: StageLogGetEventPerfLog(stageLog, stage, &eventPerfLog);
643: PetscTime(curTime);
644: if (logActions) {
645: actions[numActions].time = curTime - BaseTime;
646: actions[numActions].action = ACTIONEND;
647: actions[numActions].event = event;
648: actions[numActions].cookie = eventRegLog->eventInfo[event].cookie;
649: if (o1) actions[numActions].id1 = o1->id; else actions[numActions].id1 = -1;
650: if (o2) actions[numActions].id2 = o2->id; else actions[numActions].id2 = -1;
651: if (o3) actions[numActions].id3 = o3->id; else actions[numActions].id3 = -1;
652: actions[numActions].flops = _TotalFlops;
653: PetscMallocGetCurrentUsage(&actions[numActions].mem);
654: PetscMallocGetMaximumUsage(&actions[numActions].maxmem);
655: numActions++;
656: }
657: /* Check for double counting */
658: eventPerfLog->eventInfo[event].depth--;
659: if (eventPerfLog->eventInfo[event].depth > 0) {
660: return(0);
661: } else if (eventPerfLog->eventInfo[event].depth < 0) {
662: SETERRQ(PETSC_ERR_ARG_WRONGSTATE, "Logging event had unbalanced begin/end pairs");
663: }
664: /* Log the performance info */
665: eventPerfLog->eventInfo[event].count++;
666: eventPerfLog->eventInfo[event].time += curTime;
667: eventPerfLog->eventInfo[event].flops += _TotalFlops;
668: eventPerfLog->eventInfo[event].numMessages += irecv_ct + isend_ct + recv_ct + send_ct;
669: eventPerfLog->eventInfo[event].messageLength += irecv_len + isend_len + recv_len + send_len;
670: eventPerfLog->eventInfo[event].numReductions += allreduce_ct;
671: return(0);
672: }
677: {
678: StageLog stageLog;
679: EventRegLog eventRegLog;
680: EventPerfLog eventPerfLog;
681: PetscLogDouble cur_time;
682: PetscMPIInt rank;
683: int stage;
687: if (!tracetime) {PetscTime(tracetime);}
689: MPI_Comm_rank(PETSC_COMM_WORLD, &rank);
690: PetscLogGetStageLog(&stageLog);
691: StageLogGetCurrent(stageLog, &stage);
692: StageLogGetEventRegLog(stageLog, &eventRegLog);
693: StageLogGetEventPerfLog(stageLog, stage, &eventPerfLog);
694: /* Check for double counting */
695: eventPerfLog->eventInfo[event].depth++;
696: tracelevel++;
697: if (eventPerfLog->eventInfo[event].depth > 1) return(0);
698: /* Log performance info */
699: PetscStrncpy(tracespace, traceblanks, 2*tracelevel);
700: tracespace[2*tracelevel] = 0;
701: PetscTime(cur_time);
702: PetscFPrintf(PETSC_COMM_SELF,tracefile, "%s[%d] %g Event begin: %s\n", tracespace, rank, cur_time-tracetime, eventRegLog->eventInfo[event].name);
703: fflush(tracefile);
705: return(0);
706: }
711: {
712: StageLog stageLog;
713: EventRegLog eventRegLog;
714: EventPerfLog eventPerfLog;
715: PetscLogDouble cur_time;
716: int stage;
717: PetscMPIInt rank;
721: tracelevel--;
722: MPI_Comm_rank(PETSC_COMM_WORLD, &rank);
723: PetscLogGetStageLog(&stageLog);
724: StageLogGetCurrent(stageLog, &stage);
725: StageLogGetEventRegLog(stageLog, &eventRegLog);
726: StageLogGetEventPerfLog(stageLog, stage, &eventPerfLog);
727: /* Check for double counting */
728: eventPerfLog->eventInfo[event].depth--;
729: if (eventPerfLog->eventInfo[event].depth > 0) {
730: return(0);
731: } else if (eventPerfLog->eventInfo[event].depth < 0 || tracelevel < 0) {
732: SETERRQ(PETSC_ERR_ARG_WRONGSTATE, "Logging event had unbalanced begin/end pairs");
733: }
734: /* Log performance info */
735: PetscStrncpy(tracespace, traceblanks, 2*tracelevel);
736: tracespace[2*tracelevel] = 0;
737: PetscTime(cur_time);
738: PetscFPrintf(PETSC_COMM_SELF,tracefile, "%s[%d] %g Event end: %s\n", tracespace, rank, cur_time-tracetime, eventRegLog->eventInfo[event].name);
739: fflush(tracefile);
740: return(0);
741: }