Actual source code: plog.c
petsc-3.7.7 2017-09-25
2: /*
3: PETSc code to log object creation and destruction and PETSc events.
5: This provides the public API used by the rest of PETSc and by users.
7: These routines use a private API that is not used elsewhere in PETSc and is not
8: accessible to users. The private API is defined in logimpl.h and the utils directory.
10: */
11: #include <petsc/private/logimpl.h> /*I "petscsys.h" I*/
12: #include <petsctime.h>
13: #include <petscviewer.h>
15: PetscErrorCode PetscLogObjectParent(PetscObject p,PetscObject c)
16: {
17: if (!c || !p) return 0;
18: c->parent = p;
19: c->parentid = p->id;
20: return 0;
21: }
23: PetscErrorCode PetscLogObjectMemory(PetscObject p,PetscLogDouble m)
24: {
25: if (!p) return 0;
26: p->mem += m;
27: return 0;
28: }
30: PetscLogEvent PETSC_LARGEST_EVENT = PETSC_EVENT;
32: #if defined(PETSC_USE_LOG)
33: #include <petscmachineinfo.h>
34: #include <petscconfiginfo.h>
36: /* used in the MPI_XXX() count macros in petsclog.h */
38: /* Action and object logging variables */
39: Action *petsc_actions = NULL;
40: Object *petsc_objects = NULL;
41: PetscBool petsc_logActions = PETSC_FALSE;
42: PetscBool petsc_logObjects = PETSC_FALSE;
43: int petsc_numActions = 0, petsc_maxActions = 100;
44: int petsc_numObjects = 0, petsc_maxObjects = 100;
45: int petsc_numObjectsDestroyed = 0;
47: /* Global counters */
48: PetscLogDouble petsc_BaseTime = 0.0;
49: PetscLogDouble petsc_TotalFlops = 0.0; /* The number of flops */
50: PetscLogDouble petsc_tmp_flops = 0.0; /* The incremental number of flops */
51: PetscLogDouble petsc_send_ct = 0.0; /* The number of sends */
52: PetscLogDouble petsc_recv_ct = 0.0; /* The number of receives */
53: PetscLogDouble petsc_send_len = 0.0; /* The total length of all sent messages */
54: PetscLogDouble petsc_recv_len = 0.0; /* The total length of all received messages */
55: PetscLogDouble petsc_isend_ct = 0.0; /* The number of immediate sends */
56: PetscLogDouble petsc_irecv_ct = 0.0; /* The number of immediate receives */
57: PetscLogDouble petsc_isend_len = 0.0; /* The total length of all immediate send messages */
58: PetscLogDouble petsc_irecv_len = 0.0; /* The total length of all immediate receive messages */
59: PetscLogDouble petsc_wait_ct = 0.0; /* The number of waits */
60: PetscLogDouble petsc_wait_any_ct = 0.0; /* The number of anywaits */
61: PetscLogDouble petsc_wait_all_ct = 0.0; /* The number of waitalls */
62: PetscLogDouble petsc_sum_of_waits_ct = 0.0; /* The total number of waits */
63: PetscLogDouble petsc_allreduce_ct = 0.0; /* The number of reductions */
64: PetscLogDouble petsc_gather_ct = 0.0; /* The number of gathers and gathervs */
65: PetscLogDouble petsc_scatter_ct = 0.0; /* The number of scatters and scattervs */
67: /* Logging functions */
68: PetscErrorCode (*PetscLogPHC)(PetscObject) = NULL;
69: PetscErrorCode (*PetscLogPHD)(PetscObject) = NULL;
70: PetscErrorCode (*PetscLogPLB)(PetscLogEvent, int, PetscObject, PetscObject, PetscObject, PetscObject) = NULL;
71: PetscErrorCode (*PetscLogPLE)(PetscLogEvent, int, PetscObject, PetscObject, PetscObject, PetscObject) = NULL;
73: /* Tracing event logging variables */
74: FILE *petsc_tracefile = NULL;
75: int petsc_tracelevel = 0;
76: const char *petsc_traceblanks = " ";
77: char petsc_tracespace[128] = " ";
78: PetscLogDouble petsc_tracetime = 0.0;
79: static PetscBool PetscLogInitializeCalled = PETSC_FALSE;
81: /*---------------------------------------------- General Functions --------------------------------------------------*/
84: /*@C
85: PetscLogDestroy - Destroys the object and event logging data and resets the global counters.
87: Not Collective
89: Notes:
90: This routine should not usually be used by programmers. Instead employ
91: PetscLogStagePush() and PetscLogStagePop().
93: Level: developer
95: .keywords: log, destroy
96: .seealso: PetscLogDump(), PetscLogAllBegin(), PetscLogView(), PetscLogStagePush(), PlogStagePop()
97: @*/
98: PetscErrorCode PetscLogDestroy(void)
99: {
100: PetscStageLog stageLog;
104: PetscFree(petsc_actions);
105: PetscFree(petsc_objects);
106: PetscLogSet(NULL, NULL);
108: /* Resetting phase */
109: PetscLogGetStageLog(&stageLog);
110: PetscStageLogDestroy(stageLog);
112: petsc_TotalFlops = 0.0;
113: petsc_numActions = 0;
114: petsc_numObjects = 0;
115: petsc_numObjectsDestroyed = 0;
116: petsc_maxActions = 100;
117: petsc_maxObjects = 100;
118: petsc_actions = NULL;
119: petsc_objects = NULL;
120: petsc_logActions = PETSC_FALSE;
121: petsc_logObjects = PETSC_FALSE;
122: petsc_BaseTime = 0.0;
123: petsc_TotalFlops = 0.0;
124: petsc_tmp_flops = 0.0;
125: petsc_send_ct = 0.0;
126: petsc_recv_ct = 0.0;
127: petsc_send_len = 0.0;
128: petsc_recv_len = 0.0;
129: petsc_isend_ct = 0.0;
130: petsc_irecv_ct = 0.0;
131: petsc_isend_len = 0.0;
132: petsc_irecv_len = 0.0;
133: petsc_wait_ct = 0.0;
134: petsc_wait_any_ct = 0.0;
135: petsc_wait_all_ct = 0.0;
136: petsc_sum_of_waits_ct = 0.0;
137: petsc_allreduce_ct = 0.0;
138: petsc_gather_ct = 0.0;
139: petsc_scatter_ct = 0.0;
140: PETSC_LARGEST_EVENT = PETSC_EVENT;
141: PetscLogPHC = NULL;
142: PetscLogPHD = NULL;
143: petsc_tracefile = NULL;
144: petsc_tracelevel = 0;
145: petsc_traceblanks = " ";
146: petsc_tracespace[0] = ' '; petsc_tracespace[1] = 0;
147: petsc_tracetime = 0.0;
148: PETSC_LARGEST_CLASSID = PETSC_SMALLEST_CLASSID;
149: PETSC_OBJECT_CLASSID = 0;
150: petsc_stageLog = 0;
151: PetscLogInitializeCalled = PETSC_FALSE;
152: return(0);
153: }
157: /*@C
158: PetscLogSet - Sets the logging functions called at the beginning and ending of every event.
160: Not Collective
162: Input Parameters:
163: + b - The function called at beginning of event
164: - e - The function called at end of event
166: Level: developer
168: .seealso: PetscLogDump(), PetscLogDefaultBegin(), PetscLogAllBegin(), PetscLogTraceBegin()
169: @*/
170: PetscErrorCode PetscLogSet(PetscErrorCode (*b)(PetscLogEvent, int, PetscObject, PetscObject, PetscObject, PetscObject),
171: PetscErrorCode (*e)(PetscLogEvent, int, PetscObject, PetscObject, PetscObject, PetscObject))
172: {
174: PetscLogPLB = b;
175: PetscLogPLE = e;
176: return(0);
177: }
179: #if defined(PETSC_HAVE_PAPI)
180: #include <papi.h>
181: int PAPIEventSet = PAPI_NULL;
182: #endif
184: /*------------------------------------------- Initialization Functions ----------------------------------------------*/
187: /*
188: The data structures for logging are always created even if no logging is turned on. This is so events etc can
189: be registered in the code before the actually logging is turned on.
190: */
191: PetscErrorCode PetscLogInitialize(void)
192: {
193: int stage;
194: PetscBool opt;
198: if (PetscLogInitializeCalled) return(0);
199: PetscLogInitializeCalled = PETSC_TRUE;
201: PetscOptionsHasName(NULL,NULL, "-log_exclude_actions", &opt);
202: if (opt) petsc_logActions = PETSC_FALSE;
203: PetscOptionsHasName(NULL,NULL, "-log_exclude_objects", &opt);
204: if (opt) petsc_logObjects = PETSC_FALSE;
205: if (petsc_logActions) {
206: PetscMalloc1(petsc_maxActions, &petsc_actions);
207: }
208: if (petsc_logObjects) {
209: PetscMalloc1(petsc_maxObjects, &petsc_objects);
210: }
211: PetscLogPHC = PetscLogObjCreateDefault;
212: PetscLogPHD = PetscLogObjDestroyDefault;
213: /* Setup default logging structures */
214: PetscStageLogCreate(&petsc_stageLog);
215: PetscStageLogRegister(petsc_stageLog, "Main Stage", &stage);
216: #if defined(PETSC_HAVE_PAPI)
217: PAPI_library_init(PAPI_VER_CURRENT);
218: if (ierr != PAPI_VER_CURRENT) SETERRQ(PETSC_COMM_SELF,PETSC_ERR_LIB,"Cannot initialize PAPI");
219: PAPI_query_event(PAPI_FP_INS);
220: PAPI_create_eventset(&PAPIEventSet);
221: PAPI_add_event(PAPIEventSet,PAPI_FP_INS);
222: PAPI_start(PAPIEventSet);
223: #endif
225: /* All processors sync here for more consistent logging */
226: MPI_Barrier(PETSC_COMM_WORLD);
227: PetscTime(&petsc_BaseTime);
228: PetscLogStagePush(stage);
229: return(0);
230: }
234: /*@C
235: PetscLogDefaultBegin - Turns on logging of objects and events. This logs flop
236: rates and object creation and should not slow programs down too much.
237: This routine may be called more than once.
239: Logically Collective over PETSC_COMM_WORLD
241: Options Database Keys:
242: . -log_view [viewertype:filename:viewerformat] - Prints summary of flop and timing information to the
243: screen (for code configured with --with-log=1 (which is the default))
245: Usage:
246: .vb
247: PetscInitialize(...);
248: PetscLogDefaultBegin();
249: ... code ...
250: PetscLogView(viewer); or PetscLogDump();
251: PetscFinalize();
252: .ve
254: Notes:
255: PetscLogView(viewer) or PetscLogDump() actually cause the printing of
256: the logging information.
258: Level: advanced
260: .keywords: log, begin
261: .seealso: PetscLogDump(), PetscLogAllBegin(), PetscLogView(), PetscLogTraceBegin()
262: @*/
263: PetscErrorCode PetscLogDefaultBegin(void)
264: {
268: PetscLogSet(PetscLogEventBeginDefault, PetscLogEventEndDefault);
269: return(0);
270: }
274: /*@C
275: PetscLogAllBegin - Turns on extensive logging of objects and events. Logs
276: all events. This creates large log files and slows the program down.
278: Logically Collective on PETSC_COMM_WORLD
280: Options Database Keys:
281: . -log_all - Prints extensive log information
283: Usage:
284: .vb
285: PetscInitialize(...);
286: PetscLogAllBegin();
287: ... code ...
288: PetscLogDump(filename);
289: PetscFinalize();
290: .ve
292: Notes:
293: A related routine is PetscLogDefaultBegin() (with the options key -log), which is
294: intended for production runs since it logs only flop rates and object
295: creation (and shouldn't significantly slow the programs).
297: Level: advanced
299: .keywords: log, all, begin
300: .seealso: PetscLogDump(), PetscLogDefaultBegin(), PetscLogTraceBegin()
301: @*/
302: PetscErrorCode PetscLogAllBegin(void)
303: {
307: PetscLogSet(PetscLogEventBeginComplete, PetscLogEventEndComplete);
308: return(0);
309: }
313: /*@
314: PetscLogTraceBegin - Activates trace logging. Every time a PETSc event
315: begins or ends, the event name is printed.
317: Logically Collective on PETSC_COMM_WORLD
319: Input Parameter:
320: . file - The file to print trace in (e.g. stdout)
322: Options Database Key:
323: . -log_trace [filename] - Activates PetscLogTraceBegin()
325: Notes:
326: PetscLogTraceBegin() prints the processor number, the execution time (sec),
327: then "Event begin:" or "Event end:" followed by the event name.
329: PetscLogTraceBegin() allows tracing of all PETSc calls, which is useful
330: to determine where a program is hanging without running in the
331: debugger. Can be used in conjunction with the -info option.
333: Level: intermediate
335: .seealso: PetscLogDump(), PetscLogAllBegin(), PetscLogView(), PetscLogDefaultBegin()
336: @*/
337: PetscErrorCode PetscLogTraceBegin(FILE *file)
338: {
342: petsc_tracefile = file;
344: PetscLogSet(PetscLogEventBeginTrace, PetscLogEventEndTrace);
345: return(0);
346: }
350: /*@
351: PetscLogActions - Determines whether actions are logged for the graphical viewer.
353: Not Collective
355: Input Parameter:
356: . flag - PETSC_TRUE if actions are to be logged
358: Level: intermediate
360: Note: Logging of actions continues to consume more memory as the program
361: runs. Long running programs should consider turning this feature off.
363: Options Database Keys:
364: . -log_exclude_actions - Turns off actions logging
366: .keywords: log, stage, register
367: .seealso: PetscLogStagePush(), PetscLogStagePop()
368: @*/
369: PetscErrorCode PetscLogActions(PetscBool flag)
370: {
372: petsc_logActions = flag;
373: return(0);
374: }
378: /*@
379: PetscLogObjects - Determines whether objects are logged for the graphical viewer.
381: Not Collective
383: Input Parameter:
384: . flag - PETSC_TRUE if objects are to be logged
386: Level: intermediate
388: Note: Logging of objects continues to consume more memory as the program
389: runs. Long running programs should consider turning this feature off.
391: Options Database Keys:
392: . -log_exclude_objects - Turns off objects logging
394: .keywords: log, stage, register
395: .seealso: PetscLogStagePush(), PetscLogStagePop()
396: @*/
397: PetscErrorCode PetscLogObjects(PetscBool flag)
398: {
400: petsc_logObjects = flag;
401: return(0);
402: }
404: /*------------------------------------------------ Stage Functions --------------------------------------------------*/
407: /*@C
408: PetscLogStageRegister - Attaches a character string name to a logging stage.
410: Not Collective
412: Input Parameter:
413: . sname - The name to associate with that stage
415: Output Parameter:
416: . stage - The stage number
418: Level: intermediate
420: .keywords: log, stage, register
421: .seealso: PetscLogStagePush(), PetscLogStagePop()
422: @*/
423: PetscErrorCode PetscLogStageRegister(const char sname[],PetscLogStage *stage)
424: {
425: PetscStageLog stageLog;
426: PetscLogEvent event;
430: PetscLogGetStageLog(&stageLog);
431: PetscStageLogRegister(stageLog, sname, stage);
432: /* Copy events already changed in the main stage, this sucks */
433: EventPerfLogEnsureSize(stageLog->stageInfo[*stage].eventLog, stageLog->eventLog->numEvents);
434: for (event = 0; event < stageLog->eventLog->numEvents; event++) {
435: EventPerfInfoCopy(&stageLog->stageInfo[0].eventLog->eventInfo[event],&stageLog->stageInfo[*stage].eventLog->eventInfo[event]);
436: }
437: ClassPerfLogEnsureSize(stageLog->stageInfo[*stage].classLog, stageLog->classLog->numClasses);
438: return(0);
439: }
443: /*@C
444: PetscLogStagePush - This function pushes a stage on the stack.
446: Not Collective
448: Input Parameter:
449: . stage - The stage on which to log
451: Usage:
452: If the option -log_sumary is used to run the program containing the
453: following code, then 2 sets of summary data will be printed during
454: PetscFinalize().
455: .vb
456: PetscInitialize(int *argc,char ***args,0,0);
457: [stage 0 of code]
458: PetscLogStagePush(1);
459: [stage 1 of code]
460: PetscLogStagePop();
461: PetscBarrier(...);
462: [more stage 0 of code]
463: PetscFinalize();
464: .ve
466: Notes:
467: Use PetscLogStageRegister() to register a stage.
469: Level: intermediate
471: .keywords: log, push, stage
472: .seealso: PetscLogStagePop(), PetscLogStageRegister(), PetscBarrier()
473: @*/
474: PetscErrorCode PetscLogStagePush(PetscLogStage stage)
475: {
476: PetscStageLog stageLog;
480: PetscLogGetStageLog(&stageLog);
481: PetscStageLogPush(stageLog, stage);
482: return(0);
483: }
487: /*@C
488: PetscLogStagePop - This function pops a stage from the stack.
490: Not Collective
492: Usage:
493: If the option -log_sumary is used to run the program containing the
494: following code, then 2 sets of summary data will be printed during
495: PetscFinalize().
496: .vb
497: PetscInitialize(int *argc,char ***args,0,0);
498: [stage 0 of code]
499: PetscLogStagePush(1);
500: [stage 1 of code]
501: PetscLogStagePop();
502: PetscBarrier(...);
503: [more stage 0 of code]
504: PetscFinalize();
505: .ve
507: Notes:
508: Use PetscLogStageRegister() to register a stage.
510: Level: intermediate
512: .keywords: log, pop, stage
513: .seealso: PetscLogStagePush(), PetscLogStageRegister(), PetscBarrier()
514: @*/
515: PetscErrorCode PetscLogStagePop(void)
516: {
517: PetscStageLog stageLog;
521: PetscLogGetStageLog(&stageLog);
522: PetscStageLogPop(stageLog);
523: return(0);
524: }
528: /*@
529: PetscLogStageSetActive - Determines stage activity for PetscLogEventBegin() and PetscLogEventEnd().
531: Not Collective
533: Input Parameters:
534: + stage - The stage
535: - isActive - The activity flag, PETSC_TRUE for logging, else PETSC_FALSE (defaults to PETSC_TRUE)
537: Level: intermediate
539: .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadBegin(), PetscPreLoadEnd(), PetscPreLoadStage()
540: @*/
541: PetscErrorCode PetscLogStageSetActive(PetscLogStage stage, PetscBool isActive)
542: {
543: PetscStageLog stageLog;
547: PetscLogGetStageLog(&stageLog);
548: PetscStageLogSetActive(stageLog, stage, isActive);
549: return(0);
550: }
554: /*@
555: PetscLogStageGetActive - Returns stage activity for PetscLogEventBegin() and PetscLogEventEnd().
557: Not Collective
559: Input Parameter:
560: . stage - The stage
562: Output Parameter:
563: . isActive - The activity flag, PETSC_TRUE for logging, else PETSC_FALSE (defaults to PETSC_TRUE)
565: Level: intermediate
567: .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadBegin(), PetscPreLoadEnd(), PetscPreLoadStage()
568: @*/
569: PetscErrorCode PetscLogStageGetActive(PetscLogStage stage, PetscBool *isActive)
570: {
571: PetscStageLog stageLog;
575: PetscLogGetStageLog(&stageLog);
576: PetscStageLogGetActive(stageLog, stage, isActive);
577: return(0);
578: }
582: /*@
583: PetscLogStageSetVisible - Determines stage visibility in PetscLogView()
585: Not Collective
587: Input Parameters:
588: + stage - The stage
589: - isVisible - The visibility flag, PETSC_TRUE to print, else PETSC_FALSE (defaults to PETSC_TRUE)
591: Level: intermediate
593: .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscLogView()
594: @*/
595: PetscErrorCode PetscLogStageSetVisible(PetscLogStage stage, PetscBool isVisible)
596: {
597: PetscStageLog stageLog;
601: PetscLogGetStageLog(&stageLog);
602: PetscStageLogSetVisible(stageLog, stage, isVisible);
603: return(0);
604: }
608: /*@
609: PetscLogStageGetVisible - Returns stage visibility in PetscLogView()
611: Not Collective
613: Input Parameter:
614: . stage - The stage
616: Output Parameter:
617: . isVisible - The visibility flag, PETSC_TRUE to print, else PETSC_FALSE (defaults to PETSC_TRUE)
619: Level: intermediate
621: .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscLogView()
622: @*/
623: PetscErrorCode PetscLogStageGetVisible(PetscLogStage stage, PetscBool *isVisible)
624: {
625: PetscStageLog stageLog;
629: PetscLogGetStageLog(&stageLog);
630: PetscStageLogGetVisible(stageLog, stage, isVisible);
631: return(0);
632: }
636: /*@C
637: PetscLogStageGetId - Returns the stage id when given the stage name.
639: Not Collective
641: Input Parameter:
642: . name - The stage name
644: Output Parameter:
645: . stage - The stage, , or -1 if no stage with that name exists
647: Level: intermediate
649: .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscPreLoadBegin(), PetscPreLoadEnd(), PetscPreLoadStage()
650: @*/
651: PetscErrorCode PetscLogStageGetId(const char name[], PetscLogStage *stage)
652: {
653: PetscStageLog stageLog;
657: PetscLogGetStageLog(&stageLog);
658: PetscStageLogGetStage(stageLog, name, stage);
659: return(0);
660: }
662: /*------------------------------------------------ Event Functions --------------------------------------------------*/
665: /*@C
666: PetscLogEventRegister - Registers an event name for logging operations in an application code.
668: Not Collective
670: Input Parameter:
671: + name - The name associated with the event
672: - classid - The classid associated to the class for this event, obtain either with
673: PetscClassIdRegister() or use a predefined one such as KSP_CLASSID, SNES_CLASSID, the predefined ones
674: are only available in C code
676: Output Parameter:
677: . event - The event id for use with PetscLogEventBegin() and PetscLogEventEnd().
679: Example of Usage:
680: .vb
681: PetscLogEvent USER_EVENT;
682: PetscClassId classid;
683: PetscLogDouble user_event_flops;
684: PetscClassIdRegister("class name",&classid);
685: PetscLogEventRegister("User event name",classid,&USER_EVENT);
686: PetscLogEventBegin(USER_EVENT,0,0,0,0);
687: [code segment to monitor]
688: PetscLogFlops(user_event_flops);
689: PetscLogEventEnd(USER_EVENT,0,0,0,0);
690: .ve
692: Notes:
693: PETSc automatically logs library events if the code has been
694: configured with --with-log (which is the default) and
695: -log_view or -log_all is specified. PetscLogEventRegister() is
696: intended for logging user events to supplement this PETSc
697: information.
699: PETSc can gather data for use with the utilities Jumpshot
700: (part of the MPICH distribution). If PETSc has been compiled
701: with flag -DPETSC_HAVE_MPE (MPE is an additional utility within
702: MPICH), the user can employ another command line option, -log_mpe,
703: to create a logfile, "mpe.log", which can be visualized
704: Jumpshot.
706: The classid is associated with each event so that classes of events
707: can be disabled simultaneously, such as all matrix events. The user
708: can either use an existing classid, such as MAT_CLASSID, or create
709: their own as shown in the example.
711: If an existing event with the same name exists, its event handle is
712: returned instead of creating a new event.
714: Level: intermediate
716: .keywords: log, event, register
717: .seealso: PetscLogEventBegin(), PetscLogEventEnd(), PetscLogFlops(),
718: PetscLogEventMPEActivate(), PetscLogEventMPEDeactivate(),
719: PetscLogEventActivate(), PetscLogEventDeactivate(), PetscClassIdRegister()
720: @*/
721: PetscErrorCode PetscLogEventRegister(const char name[],PetscClassId classid,PetscLogEvent *event)
722: {
723: PetscStageLog stageLog;
724: int stage;
728: *event = PETSC_DECIDE;
729: PetscLogGetStageLog(&stageLog);
730: EventRegLogGetEvent(stageLog->eventLog, name, event);
731: if (*event > 0) return(0);
732: EventRegLogRegister(stageLog->eventLog, name, classid, event);
733: for (stage = 0; stage < stageLog->numStages; stage++) {
734: EventPerfLogEnsureSize(stageLog->stageInfo[stage].eventLog, stageLog->eventLog->numEvents);
735: ClassPerfLogEnsureSize(stageLog->stageInfo[stage].classLog, stageLog->classLog->numClasses);
736: }
737: return(0);
738: }
742: /*@
743: PetscLogEventActivate - Indicates that a particular event should be logged.
745: Not Collective
747: Input Parameter:
748: . event - The event id
750: Usage:
751: .vb
752: PetscLogEventDeactivate(VEC_SetValues);
753: [code where you do not want to log VecSetValues()]
754: PetscLogEventActivate(VEC_SetValues);
755: [code where you do want to log VecSetValues()]
756: .ve
758: Note:
759: The event may be either a pre-defined PETSc event (found in include/petsclog.h)
760: or an event number obtained with PetscLogEventRegister().
762: Level: advanced
764: .keywords: log, event, activate
765: .seealso: PetscLogEventMPEDeactivate(),PetscLogEventMPEActivate(),PlogEventDeactivate()
766: @*/
767: PetscErrorCode PetscLogEventActivate(PetscLogEvent event)
768: {
769: PetscStageLog stageLog;
770: int stage;
774: PetscLogGetStageLog(&stageLog);
775: PetscStageLogGetCurrent(stageLog, &stage);
776: EventPerfLogActivate(stageLog->stageInfo[stage].eventLog, event);
777: return(0);
778: }
782: /*@
783: PetscLogEventDeactivate - Indicates that a particular event should not be logged.
785: Not Collective
787: Input Parameter:
788: . event - The event id
790: Usage:
791: .vb
792: PetscLogEventDeactivate(VEC_SetValues);
793: [code where you do not want to log VecSetValues()]
794: PetscLogEventActivate(VEC_SetValues);
795: [code where you do want to log VecSetValues()]
796: .ve
798: Note:
799: The event may be either a pre-defined PETSc event (found in
800: include/petsclog.h) or an event number obtained with PetscLogEventRegister()).
802: Level: advanced
804: .keywords: log, event, deactivate
805: .seealso: PetscLogEventMPEDeactivate(),PetscLogEventMPEActivate(),PlogEventActivate()
806: @*/
807: PetscErrorCode PetscLogEventDeactivate(PetscLogEvent event)
808: {
809: PetscStageLog stageLog;
810: int stage;
814: PetscLogGetStageLog(&stageLog);
815: PetscStageLogGetCurrent(stageLog, &stage);
816: EventPerfLogDeactivate(stageLog->stageInfo[stage].eventLog, event);
817: return(0);
818: }
822: /*@
823: PetscLogEventSetActiveAll - Sets the event activity in every stage.
825: Not Collective
827: Input Parameters:
828: + event - The event id
829: - isActive - The activity flag determining whether the event is logged
831: Level: advanced
833: .keywords: log, event, activate
834: .seealso: PetscLogEventMPEDeactivate(),PetscLogEventMPEActivate(),PlogEventActivate(),PlogEventDeactivate()
835: @*/
836: PetscErrorCode PetscLogEventSetActiveAll(PetscLogEvent event, PetscBool isActive)
837: {
838: PetscStageLog stageLog;
839: int stage;
843: PetscLogGetStageLog(&stageLog);
844: for (stage = 0; stage < stageLog->numStages; stage++) {
845: if (isActive) {
846: EventPerfLogActivate(stageLog->stageInfo[stage].eventLog, event);
847: } else {
848: EventPerfLogDeactivate(stageLog->stageInfo[stage].eventLog, event);
849: }
850: }
851: return(0);
852: }
856: /*@
857: PetscLogEventActivateClass - Activates event logging for a PETSc object class.
859: Not Collective
861: Input Parameter:
862: . classid - The event class, for example MAT_CLASSID, SNES_CLASSID, etc.
864: Level: developer
866: .keywords: log, event, activate, class
867: .seealso: PetscInfoActivate(),PetscInfo(),PetscInfoAllow(),PetscLogEventDeactivateClass(), PetscLogEventActivate(),PetscLogEventDeactivate()
868: @*/
869: PetscErrorCode PetscLogEventActivateClass(PetscClassId classid)
870: {
871: PetscStageLog stageLog;
872: int stage;
876: PetscLogGetStageLog(&stageLog);
877: PetscStageLogGetCurrent(stageLog, &stage);
878: EventPerfLogActivateClass(stageLog->stageInfo[stage].eventLog, stageLog->eventLog, classid);
879: return(0);
880: }
884: /*@
885: PetscLogEventDeactivateClass - Deactivates event logging for a PETSc object class.
887: Not Collective
889: Input Parameter:
890: . classid - The event class, for example MAT_CLASSID, SNES_CLASSID, etc.
892: Level: developer
894: .keywords: log, event, deactivate, class
895: .seealso: PetscInfoActivate(),PetscInfo(),PetscInfoAllow(),PetscLogEventActivateClass(), PetscLogEventActivate(),PetscLogEventDeactivate()
896: @*/
897: PetscErrorCode PetscLogEventDeactivateClass(PetscClassId classid)
898: {
899: PetscStageLog stageLog;
900: int stage;
904: PetscLogGetStageLog(&stageLog);
905: PetscStageLogGetCurrent(stageLog, &stage);
906: EventPerfLogDeactivateClass(stageLog->stageInfo[stage].eventLog, stageLog->eventLog, classid);
907: return(0);
908: }
910: /*MC
911: PetscLogEventBegin - Logs the beginning of a user event.
913: Synopsis:
914: #include <petsclog.h>
915: PetscErrorCode PetscLogEventBegin(int e,PetscObject o1,PetscObject o2,PetscObject o3,PetscObject o4)
917: Not Collective
919: Input Parameters:
920: + e - integer associated with the event obtained from PetscLogEventRegister()
921: - o1,o2,o3,o4 - objects associated with the event, or 0
924: Fortran Synopsis:
925: void PetscLogEventBegin(int e,PetscErrorCode ierr)
927: Usage:
928: .vb
929: PetscLogEvent USER_EVENT;
930: PetscLogDouble user_event_flops;
931: PetscLogEventRegister("User event",0,&USER_EVENT);
932: PetscLogEventBegin(USER_EVENT,0,0,0,0);
933: [code segment to monitor]
934: PetscLogFlops(user_event_flops);
935: PetscLogEventEnd(USER_EVENT,0,0,0,0);
936: .ve
938: Notes:
939: You need to register each integer event with the command
940: PetscLogEventRegister().
942: Level: intermediate
944: .seealso: PetscLogEventRegister(), PetscLogEventEnd(), PetscLogFlops()
946: .keywords: log, event, begin
947: M*/
949: /*MC
950: PetscLogEventEnd - Log the end of a user event.
952: Synopsis:
953: #include <petsclog.h>
954: PetscErrorCode PetscLogEventEnd(int e,PetscObject o1,PetscObject o2,PetscObject o3,PetscObject o4)
956: Not Collective
958: Input Parameters:
959: + e - integer associated with the event obtained with PetscLogEventRegister()
960: - o1,o2,o3,o4 - objects associated with the event, or 0
963: Fortran Synopsis:
964: void PetscLogEventEnd(int e,PetscErrorCode ierr)
966: Usage:
967: .vb
968: PetscLogEvent USER_EVENT;
969: PetscLogDouble user_event_flops;
970: PetscLogEventRegister("User event",0,&USER_EVENT,);
971: PetscLogEventBegin(USER_EVENT,0,0,0,0);
972: [code segment to monitor]
973: PetscLogFlops(user_event_flops);
974: PetscLogEventEnd(USER_EVENT,0,0,0,0);
975: .ve
977: Notes:
978: You should also register each additional integer event with the command
979: PetscLogEventRegister().
981: Level: intermediate
983: .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogFlops()
985: .keywords: log, event, end
986: M*/
988: /*MC
989: PetscLogEventBarrierBegin - Logs the time in a barrier before an event.
991: Synopsis:
992: #include <petsclog.h>
993: PetscErrorCode PetscLogEventBarrierBegin(int e,PetscObject o1,PetscObject o2,PetscObject o3,PetscObject o4,MPI_Comm comm)
995: Not Collective
997: Input Parameters:
998: . e - integer associated with the event obtained from PetscLogEventRegister()
999: . o1,o2,o3,o4 - objects associated with the event, or 0
1000: . comm - communicator the barrier takes place over
1003: Usage:
1004: .vb
1005: PetscLogEventBarrierBegin(VEC_NormBarrier,0,0,0,0,comm);
1006: MPIU_Allreduce()
1007: PetscLogEventBarrierEnd(VEC_NormBarrier,0,0,0,0,comm);
1008: .ve
1010: Notes:
1011: This is for logging the amount of time spent in a barrier for an event
1012: that requires synchronization.
1014: Additional Notes:
1015: Synchronization events always come in pairs; for example, VEC_NormBarrier and
1016: VEC_NormComm = VEC_NormBarrier + 1
1018: Level: advanced
1020: .seealso: PetscLogEventRegister(), PetscLogEventEnd(), PetscLogFlops(), PetscLogEventBegin(),
1021: PetscLogEventBarrierEnd()
1023: .keywords: log, event, begin, barrier
1024: M*/
1026: /*MC
1027: PetscLogEventBarrierEnd - Logs the time in a barrier before an event.
1029: Synopsis:
1030: #include <petsclog.h>
1031: PetscErrorCode PetscLogEventBarrierEnd(int e,PetscObject o1,PetscObject o2,PetscObject o3,PetscObject o4,MPI_Comm comm)
1033: Logically Collective on MPI_Comm
1035: Input Parameters:
1036: . e - integer associated with the event obtained from PetscLogEventRegister()
1037: . o1,o2,o3,o4 - objects associated with the event, or 0
1038: . comm - communicator the barrier takes place over
1041: Usage:
1042: .vb
1043: PetscLogEventBarrierBegin(VEC_NormBarrier,0,0,0,0,comm);
1044: MPIU_Allreduce()
1045: PetscLogEventBarrierEnd(VEC_NormBarrier,0,0,0,0,comm);
1046: .ve
1048: Notes:
1049: This is for logging the amount of time spent in a barrier for an event
1050: that requires synchronization.
1052: Additional Notes:
1053: Synchronization events always come in pairs; for example, VEC_NormBarrier and
1054: VEC_NormComm = VEC_NormBarrier + 1
1056: Level: advanced
1058: .seealso: PetscLogEventRegister(), PetscLogEventEnd(), PetscLogFlops(), PetscLogEventBegin(),
1059: PetscLogEventBarrierBegin()
1061: .keywords: log, event, begin, barrier
1062: M*/
1066: /*@C
1067: PetscLogEventGetId - Returns the event id when given the event name.
1069: Not Collective
1071: Input Parameter:
1072: . name - The event name
1074: Output Parameter:
1075: . event - The event, or -1 if no event with that name exists
1077: Level: intermediate
1079: .seealso: PetscLogEventBegin(), PetscLogEventEnd(), PetscLogStageGetId()
1080: @*/
1081: PetscErrorCode PetscLogEventGetId(const char name[], PetscLogEvent *event)
1082: {
1083: PetscStageLog stageLog;
1087: PetscLogGetStageLog(&stageLog);
1088: EventRegLogGetEvent(stageLog->eventLog, name, event);
1089: return(0);
1090: }
1093: /*------------------------------------------------ Output Functions -------------------------------------------------*/
1096: /*@C
1097: PetscLogDump - Dumps logs of objects to a file. This file is intended to
1098: be read by bin/petscview. This program no longer exists.
1100: Collective on PETSC_COMM_WORLD
1102: Input Parameter:
1103: . name - an optional file name
1105: Usage:
1106: .vb
1107: PetscInitialize(...);
1108: PetscLogDefaultBegin(); or PetscLogAllBegin();
1109: ... code ...
1110: PetscLogDump(filename);
1111: PetscFinalize();
1112: .ve
1114: Notes:
1115: The default file name is
1116: $ Log.<rank>
1117: where <rank> is the processor number. If no name is specified,
1118: this file will be used.
1120: Level: advanced
1122: .keywords: log, dump
1123: .seealso: PetscLogDefaultBegin(), PetscLogAllBegin(), PetscLogView()
1124: @*/
1125: PetscErrorCode PetscLogDump(const char sname[])
1126: {
1127: PetscStageLog stageLog;
1128: PetscEventPerfInfo *eventInfo;
1129: FILE *fd;
1130: char file[PETSC_MAX_PATH_LEN], fname[PETSC_MAX_PATH_LEN];
1131: PetscLogDouble flops, _TotalTime;
1132: PetscMPIInt rank;
1133: int action, object, curStage;
1134: PetscLogEvent event;
1135: PetscErrorCode ierr;
1138: /* Calculate the total elapsed time */
1139: PetscTime(&_TotalTime);
1140: _TotalTime -= petsc_BaseTime;
1141: /* Open log file */
1142: MPI_Comm_rank(PETSC_COMM_WORLD, &rank);
1143: if (sname) sprintf(file, "%s.%d", sname, rank);
1144: else sprintf(file, "Log.%d", rank);
1145: PetscFixFilename(file, fname);
1146: PetscFOpen(PETSC_COMM_WORLD, fname, "w", &fd);
1147: if ((!rank) && (!fd)) SETERRQ1(PETSC_COMM_SELF,PETSC_ERR_FILE_OPEN, "Cannot open file: %s", fname);
1148: /* Output totals */
1149: PetscFPrintf(PETSC_COMM_WORLD, fd, "Total Flops %14e %16.8e\n", petsc_TotalFlops, _TotalTime);
1150: PetscFPrintf(PETSC_COMM_WORLD, fd, "Clock Resolution %g\n", 0.0);
1151: /* Output actions */
1152: if (petsc_logActions) {
1153: PetscFPrintf(PETSC_COMM_WORLD, fd, "Actions accomplished %d\n", petsc_numActions);
1154: for (action = 0; action < petsc_numActions; action++) {
1155: PetscFPrintf(PETSC_COMM_WORLD, fd, "%g %d %d %d %d %d %d %g %g %g\n",
1156: petsc_actions[action].time, petsc_actions[action].action, (int)petsc_actions[action].event, (int)petsc_actions[action].classid, petsc_actions[action].id1,
1157: petsc_actions[action].id2, petsc_actions[action].id3, petsc_actions[action].flops, petsc_actions[action].mem, petsc_actions[action].maxmem);
1158: }
1159: }
1160: /* Output objects */
1161: if (petsc_logObjects) {
1162: PetscFPrintf(PETSC_COMM_WORLD, fd, "Objects created %d destroyed %d\n", petsc_numObjects, petsc_numObjectsDestroyed);
1163: for (object = 0; object < petsc_numObjects; object++) {
1164: PetscFPrintf(PETSC_COMM_WORLD, fd, "Parent ID: %d Memory: %d\n", petsc_objects[object].parent, (int) petsc_objects[object].mem);
1165: if (!petsc_objects[object].name[0]) {
1166: PetscFPrintf(PETSC_COMM_WORLD, fd,"No Name\n");
1167: } else {
1168: PetscFPrintf(PETSC_COMM_WORLD, fd, "Name: %s\n", petsc_objects[object].name);
1169: }
1170: if (petsc_objects[object].info[0] != 0) {
1171: PetscFPrintf(PETSC_COMM_WORLD, fd, "No Info\n");
1172: } else {
1173: PetscFPrintf(PETSC_COMM_WORLD, fd, "Info: %s\n", petsc_objects[object].info);
1174: }
1175: }
1176: }
1177: /* Output events */
1178: PetscFPrintf(PETSC_COMM_WORLD, fd, "Event log:\n");
1179: PetscLogGetStageLog(&stageLog);
1180: PetscIntStackTop(stageLog->stack, &curStage);
1181: eventInfo = stageLog->stageInfo[curStage].eventLog->eventInfo;
1182: for (event = 0; event < stageLog->stageInfo[curStage].eventLog->numEvents; event++) {
1183: if (eventInfo[event].time != 0.0) flops = eventInfo[event].flops/eventInfo[event].time;
1184: else flops = 0.0;
1185: PetscFPrintf(PETSC_COMM_WORLD, fd, "%d %16d %16g %16g %16g\n", event, eventInfo[event].count,
1186: eventInfo[event].flops, eventInfo[event].time, flops);
1187: }
1188: PetscFClose(PETSC_COMM_WORLD, fd);
1189: return(0);
1190: }
1194: /*
1195: PetscLogView_Detailed - Each process prints the times for its own events
1197: */
1198: PetscErrorCode PetscLogView_Detailed(PetscViewer viewer)
1199: {
1200: MPI_Comm comm = PetscObjectComm((PetscObject) viewer);
1201: PetscEventPerfInfo *eventInfo = NULL;
1202: PetscLogDouble locTotalTime, numRed, maxMem;
1203: PetscStageLog stageLog;
1204: int numStages,numEvents,stage,event;
1205: PetscMPIInt rank,size;
1206: PetscErrorCode ierr;
1209: MPI_Comm_size(comm, &size);
1210: MPI_Comm_rank(comm, &rank);
1211: /* Must preserve reduction count before we go on */
1212: numRed = petsc_allreduce_ct + petsc_gather_ct + petsc_scatter_ct;
1213: /* Get the total elapsed time */
1214: PetscTime(&locTotalTime); locTotalTime -= petsc_BaseTime;
1215: PetscViewerASCIIPrintf(viewer,"numProcs = %d\n",size);
1216: PetscViewerASCIIPrintf(viewer,"LocalTimes = {}\n");
1217: PetscViewerASCIIPrintf(viewer,"LocalFlops = {}\n");
1218: PetscViewerASCIIPrintf(viewer,"LocalMessageLens = {}\n");
1219: PetscViewerASCIIPrintf(viewer,"LocalMessages = {}\n");
1220: PetscViewerASCIIPrintf(viewer,"LocalReductions = {}\n");
1221: PetscViewerASCIIPrintf(viewer,"LocalObjects = {}\n");
1222: PetscViewerASCIIPrintf(viewer,"LocalMemory = {}\n");
1223: PetscLogGetStageLog(&stageLog);
1224: MPIU_Allreduce(&stageLog->numStages, &numStages, 1, MPI_INT, MPI_MAX, comm);
1225: PetscViewerASCIIPrintf(viewer,"Stages = {}\n");
1226: for (stage=0; stage<numStages; stage++) {
1227: PetscViewerASCIIPrintf(viewer,"Stages[\"%s\"] = {}\n",stageLog->stageInfo[stage].name);
1228: PetscViewerASCIIPrintf(viewer,"Stages[\"%s\"][\"summary\"] = {}\n",stageLog->stageInfo[stage].name);
1229: MPIU_Allreduce(&stageLog->stageInfo[stage].eventLog->numEvents, &numEvents, 1, MPI_INT, MPI_MAX, comm);
1230: for (event = 0; event < numEvents; event++) {
1231: PetscViewerASCIIPrintf(viewer,"Stages[\"%s\"][\"%s\"] = {}\n",stageLog->stageInfo[stage].name,stageLog->eventLog->eventInfo[event].name);
1232: }
1233: }
1234: PetscViewerASCIIPushSynchronized(viewer);
1235: PetscViewerASCIISynchronizedPrintf(viewer,"LocalTimes[%d] = %g\n",rank,locTotalTime);
1236: PetscViewerASCIISynchronizedPrintf(viewer,"LocalFlops[%d] = %g\n",rank,petsc_TotalFlops);
1237: PetscViewerASCIISynchronizedPrintf(viewer,"LocalMessageLens[%d] = %g\n",rank,(petsc_irecv_len + petsc_isend_len + petsc_recv_len + petsc_send_len));
1238: PetscViewerASCIISynchronizedPrintf(viewer,"LocalMessages[%d] = %g\n",rank,(petsc_irecv_ct + petsc_isend_ct + petsc_recv_ct + petsc_send_ct));
1239: PetscViewerASCIISynchronizedPrintf(viewer,"LocalReductions[%d] = %g\n",rank,numRed);
1240: PetscViewerASCIISynchronizedPrintf(viewer,"LocalObjects[%d] = %d\n",rank,petsc_numObjects);
1241: PetscMallocGetMaximumUsage(&maxMem);
1242: PetscViewerASCIISynchronizedPrintf(viewer,"LocalMemory[%d] = %g\n",rank,maxMem);
1243: PetscViewerFlush(viewer);
1244: for (stage=0; stage<numStages; stage++) {
1245: PetscViewerASCIISynchronizedPrintf(viewer,"Stages[\"%s\"][\"summary\"][%d] = {\"time\" : %g, \"numMessages\" : %g, \"messageLength\" : %g, \"numReductions\" : %g, \"flops\" : %g}\n",
1246: stageLog->stageInfo[stage].name,rank,
1247: stageLog->stageInfo[stage].perfInfo.time,stageLog->stageInfo[stage].perfInfo.numMessages,stageLog->stageInfo[stage].perfInfo.messageLength,
1248: stageLog->stageInfo[stage].perfInfo.numReductions,stageLog->stageInfo[stage].perfInfo.flops);
1249: MPIU_Allreduce(&stageLog->stageInfo[stage].eventLog->numEvents, &numEvents, 1, MPI_INT, MPI_MAX, comm);
1250: for (event = 0; event < numEvents; event++) {
1251: eventInfo = stageLog->stageInfo[stage].eventLog->eventInfo;
1252: PetscViewerASCIISynchronizedPrintf(viewer,"Stages[\"%s\"][\"%s\"][%d] = {\"count\" : %D, \"time\" : %g, \"numMessages\" : %g, \"messageLength\" : %g, \"numReductions\" : %g, \"flops\" : %g}\n",stageLog->stageInfo[stage].name,stageLog->eventLog->eventInfo[event].name,rank,
1253: eventInfo[event].count, eventInfo[event].time,eventInfo[event].numMessages, eventInfo[event].messageLength,
1254: eventInfo[event].numReductions,eventInfo[event].flops);
1255: }
1256: }
1257: PetscViewerFlush(viewer);
1258: PetscViewerASCIIPopSynchronized(viewer);
1259: return(0);
1260: }
1264: PetscErrorCode PetscLogView_Default(PetscViewer viewer)
1265: {
1266: FILE *fd;
1267: PetscLogDouble zero = 0.0;
1268: PetscStageLog stageLog;
1269: PetscStageInfo *stageInfo = NULL;
1270: PetscEventPerfInfo *eventInfo = NULL;
1271: PetscClassPerfInfo *classInfo;
1272: char arch[128],hostname[128],username[128],pname[PETSC_MAX_PATH_LEN],date[128];
1273: const char *name;
1274: PetscLogDouble locTotalTime, TotalTime, TotalFlops;
1275: PetscLogDouble numMessages, messageLength, avgMessLen, numReductions;
1276: PetscLogDouble stageTime, flops, flopr, mem, mess, messLen, red;
1277: PetscLogDouble fracTime, fracFlops, fracMessages, fracLength, fracReductions, fracMess, fracMessLen, fracRed;
1278: PetscLogDouble fracStageTime, fracStageFlops, fracStageMess, fracStageMessLen, fracStageRed;
1279: PetscLogDouble min, max, tot, ratio, avg, x, y;
1280: PetscLogDouble minf, maxf, totf, ratf, mint, maxt, tott, ratt, ratCt, totm, totml, totr;
1281: PetscMPIInt minCt, maxCt;
1282: PetscMPIInt size, rank;
1283: PetscBool *localStageUsed, *stageUsed;
1284: PetscBool *localStageVisible, *stageVisible;
1285: int numStages, localNumEvents, numEvents;
1286: int stage, oclass;
1287: PetscLogEvent event;
1288: PetscErrorCode ierr;
1289: char version[256];
1290: MPI_Comm comm;
1293: PetscObjectGetComm((PetscObject)viewer,&comm);
1294: PetscViewerASCIIGetPointer(viewer,&fd);
1295: MPI_Comm_size(comm, &size);
1296: MPI_Comm_rank(comm, &rank);
1297: /* Get the total elapsed time */
1298: PetscTime(&locTotalTime); locTotalTime -= petsc_BaseTime;
1300: PetscFPrintf(comm, fd, "************************************************************************************************************************\n");
1301: PetscFPrintf(comm, fd, "*** WIDEN YOUR WINDOW TO 120 CHARACTERS. Use 'enscript -r -fCourier9' to print this document ***\n");
1302: PetscFPrintf(comm, fd, "************************************************************************************************************************\n");
1303: PetscFPrintf(comm, fd, "\n---------------------------------------------- PETSc Performance Summary: ----------------------------------------------\n\n");
1304: PetscGetArchType(arch,sizeof(arch));
1305: PetscGetHostName(hostname,sizeof(hostname));
1306: PetscGetUserName(username,sizeof(username));
1307: PetscGetProgramName(pname,sizeof(pname));
1308: PetscGetDate(date,sizeof(date));
1309: PetscGetVersion(version,sizeof(version));
1310: if (size == 1) {
1311: PetscFPrintf(comm,fd,"%s on a %s named %s with %d processor, by %s %s\n", pname, arch, hostname, size, username, date);
1312: } else {
1313: PetscFPrintf(comm,fd,"%s on a %s named %s with %d processors, by %s %s\n", pname, arch, hostname, size, username, date);
1314: }
1316: PetscFPrintf(comm, fd, "Using %s\n", version);
1318: /* Must preserve reduction count before we go on */
1319: red = petsc_allreduce_ct + petsc_gather_ct + petsc_scatter_ct;
1321: /* Calculate summary information */
1322: PetscFPrintf(comm, fd, "\n Max Max/Min Avg Total \n");
1323: /* Time */
1324: MPIU_Allreduce(&locTotalTime, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1325: MPIU_Allreduce(&locTotalTime, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1326: MPIU_Allreduce(&locTotalTime, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1327: avg = (tot)/((PetscLogDouble) size);
1328: if (min != 0.0) ratio = max/min;
1329: else ratio = 0.0;
1330: PetscFPrintf(comm, fd, "Time (sec): %5.3e %10.5f %5.3e\n", max, ratio, avg);
1331: TotalTime = tot;
1332: /* Objects */
1333: avg = (PetscLogDouble) petsc_numObjects;
1334: MPIU_Allreduce(&avg, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1335: MPIU_Allreduce(&avg, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1336: MPIU_Allreduce(&avg, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1337: avg = (tot)/((PetscLogDouble) size);
1338: if (min != 0.0) ratio = max/min;
1339: else ratio = 0.0;
1340: PetscFPrintf(comm, fd, "Objects: %5.3e %10.5f %5.3e\n", max, ratio, avg);
1341: /* Flops */
1342: MPIU_Allreduce(&petsc_TotalFlops, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1343: MPIU_Allreduce(&petsc_TotalFlops, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1344: MPIU_Allreduce(&petsc_TotalFlops, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1345: avg = (tot)/((PetscLogDouble) size);
1346: if (min != 0.0) ratio = max/min;
1347: else ratio = 0.0;
1348: PetscFPrintf(comm, fd, "Flops: %5.3e %10.5f %5.3e %5.3e\n", max, ratio, avg, tot);
1349: TotalFlops = tot;
1350: /* Flops/sec -- Must talk to Barry here */
1351: if (locTotalTime != 0.0) flops = petsc_TotalFlops/locTotalTime;
1352: else flops = 0.0;
1353: MPIU_Allreduce(&flops, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1354: MPIU_Allreduce(&flops, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1355: MPIU_Allreduce(&flops, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1356: avg = (tot)/((PetscLogDouble) size);
1357: if (min != 0.0) ratio = max/min;
1358: else ratio = 0.0;
1359: PetscFPrintf(comm, fd, "Flops/sec: %5.3e %10.5f %5.3e %5.3e\n", max, ratio, avg, tot);
1360: /* Memory */
1361: PetscMallocGetMaximumUsage(&mem);
1362: if (mem > 0.0) {
1363: MPIU_Allreduce(&mem, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1364: MPIU_Allreduce(&mem, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1365: MPIU_Allreduce(&mem, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1366: avg = (tot)/((PetscLogDouble) size);
1367: if (min != 0.0) ratio = max/min;
1368: else ratio = 0.0;
1369: PetscFPrintf(comm, fd, "Memory: %5.3e %10.5f %5.3e\n", max, ratio, tot);
1370: }
1371: /* Messages */
1372: mess = 0.5*(petsc_irecv_ct + petsc_isend_ct + petsc_recv_ct + petsc_send_ct);
1373: MPIU_Allreduce(&mess, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1374: MPIU_Allreduce(&mess, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1375: MPIU_Allreduce(&mess, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1376: avg = (tot)/((PetscLogDouble) size);
1377: if (min != 0.0) ratio = max/min;
1378: else ratio = 0.0;
1379: PetscFPrintf(comm, fd, "MPI Messages: %5.3e %10.5f %5.3e %5.3e\n", max, ratio, avg, tot);
1380: numMessages = tot;
1381: /* Message Lengths */
1382: mess = 0.5*(petsc_irecv_len + petsc_isend_len + petsc_recv_len + petsc_send_len);
1383: MPIU_Allreduce(&mess, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1384: MPIU_Allreduce(&mess, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1385: MPIU_Allreduce(&mess, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1386: if (numMessages != 0) avg = (tot)/(numMessages);
1387: else avg = 0.0;
1388: if (min != 0.0) ratio = max/min;
1389: else ratio = 0.0;
1390: PetscFPrintf(comm, fd, "MPI Message Lengths: %5.3e %10.5f %5.3e %5.3e\n", max, ratio, avg, tot);
1391: messageLength = tot;
1392: /* Reductions */
1393: MPIU_Allreduce(&red, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1394: MPIU_Allreduce(&red, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1395: MPIU_Allreduce(&red, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1396: if (min != 0.0) ratio = max/min;
1397: else ratio = 0.0;
1398: PetscFPrintf(comm, fd, "MPI Reductions: %5.3e %10.5f\n", max, ratio);
1399: numReductions = red; /* wrong because uses count from process zero */
1400: PetscFPrintf(comm, fd, "\nFlop counting convention: 1 flop = 1 real number operation of type (multiply/divide/add/subtract)\n");
1401: PetscFPrintf(comm, fd, " e.g., VecAXPY() for real vectors of length N --> 2N flops\n");
1402: PetscFPrintf(comm, fd, " and VecAXPY() for complex vectors of length N --> 8N flops\n");
1404: /* Get total number of stages --
1405: Currently, a single processor can register more stages than another, but stages must all be registered in order.
1406: We can removed this requirement if necessary by having a global stage numbering and indirection on the stage ID.
1407: This seems best accomplished by assoicating a communicator with each stage.
1408: */
1409: PetscLogGetStageLog(&stageLog);
1410: MPIU_Allreduce(&stageLog->numStages, &numStages, 1, MPI_INT, MPI_MAX, comm);
1411: PetscMalloc1(numStages, &localStageUsed);
1412: PetscMalloc1(numStages, &stageUsed);
1413: PetscMalloc1(numStages, &localStageVisible);
1414: PetscMalloc1(numStages, &stageVisible);
1415: if (numStages > 0) {
1416: stageInfo = stageLog->stageInfo;
1417: for (stage = 0; stage < numStages; stage++) {
1418: if (stage < stageLog->numStages) {
1419: localStageUsed[stage] = stageInfo[stage].used;
1420: localStageVisible[stage] = stageInfo[stage].perfInfo.visible;
1421: } else {
1422: localStageUsed[stage] = PETSC_FALSE;
1423: localStageVisible[stage] = PETSC_TRUE;
1424: }
1425: }
1426: MPIU_Allreduce(localStageUsed, stageUsed, numStages, MPIU_BOOL, MPI_LOR, comm);
1427: MPIU_Allreduce(localStageVisible, stageVisible, numStages, MPIU_BOOL, MPI_LAND, comm);
1428: for (stage = 0; stage < numStages; stage++) {
1429: if (stageUsed[stage]) {
1430: PetscFPrintf(comm, fd, "\nSummary of Stages: ----- Time ------ ----- Flops ----- --- Messages --- -- Message Lengths -- -- Reductions --\n");
1431: PetscFPrintf(comm, fd, " Avg %%Total Avg %%Total counts %%Total Avg %%Total counts %%Total \n");
1432: break;
1433: }
1434: }
1435: for (stage = 0; stage < numStages; stage++) {
1436: if (!stageUsed[stage]) continue;
1437: if (localStageUsed[stage]) {
1438: MPIU_Allreduce(&stageInfo[stage].perfInfo.time, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1439: MPIU_Allreduce(&stageInfo[stage].perfInfo.flops, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1440: MPIU_Allreduce(&stageInfo[stage].perfInfo.numMessages, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1441: MPIU_Allreduce(&stageInfo[stage].perfInfo.messageLength, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1442: MPIU_Allreduce(&stageInfo[stage].perfInfo.numReductions, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1443: name = stageInfo[stage].name;
1444: } else {
1445: MPIU_Allreduce(&zero, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1446: MPIU_Allreduce(&zero, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1447: MPIU_Allreduce(&zero, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1448: MPIU_Allreduce(&zero, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1449: MPIU_Allreduce(&zero, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1450: name = "";
1451: }
1452: mess *= 0.5; messLen *= 0.5; red /= size;
1453: if (TotalTime != 0.0) fracTime = stageTime/TotalTime; else fracTime = 0.0;
1454: if (TotalFlops != 0.0) fracFlops = flops/TotalFlops; else fracFlops = 0.0;
1455: /* Talk to Barry if (stageTime != 0.0) flops = (size*flops)/stageTime; else flops = 0.0; */
1456: if (numMessages != 0.0) fracMessages = mess/numMessages; else fracMessages = 0.0;
1457: if (numMessages != 0.0) avgMessLen = messLen/numMessages; else avgMessLen = 0.0;
1458: if (messageLength != 0.0) fracLength = messLen/messageLength; else fracLength = 0.0;
1459: if (numReductions != 0.0) fracReductions = red/numReductions; else fracReductions = 0.0;
1460: PetscFPrintf(comm, fd, "%2d: %15s: %6.4e %5.1f%% %6.4e %5.1f%% %5.3e %5.1f%% %5.3e %5.1f%% %5.3e %5.1f%% \n",
1461: stage, name, stageTime/size, 100.0*fracTime, flops, 100.0*fracFlops,
1462: mess, 100.0*fracMessages, avgMessLen, 100.0*fracLength, red, 100.0*fracReductions);
1463: }
1464: }
1466: PetscFPrintf(comm, fd,"\n------------------------------------------------------------------------------------------------------------------------\n");
1467: PetscFPrintf(comm, fd, "See the 'Profiling' chapter of the users' manual for details on interpreting output.\n");
1468: PetscFPrintf(comm, fd, "Phase summary info:\n");
1469: PetscFPrintf(comm, fd, " Count: number of times phase was executed\n");
1470: PetscFPrintf(comm, fd, " Time and Flops: Max - maximum over all processors\n");
1471: PetscFPrintf(comm, fd, " Ratio - ratio of maximum to minimum over all processors\n");
1472: PetscFPrintf(comm, fd, " Mess: number of messages sent\n");
1473: PetscFPrintf(comm, fd, " Avg. len: average message length (bytes)\n");
1474: PetscFPrintf(comm, fd, " Reduct: number of global reductions\n");
1475: PetscFPrintf(comm, fd, " Global: entire computation\n");
1476: PetscFPrintf(comm, fd, " Stage: stages of a computation. Set stages with PetscLogStagePush() and PetscLogStagePop().\n");
1477: PetscFPrintf(comm, fd, " %%T - percent time in this phase %%F - percent flops in this phase\n");
1478: PetscFPrintf(comm, fd, " %%M - percent messages in this phase %%L - percent message lengths in this phase\n");
1479: PetscFPrintf(comm, fd, " %%R - percent reductions in this phase\n");
1480: PetscFPrintf(comm, fd, " Total Mflop/s: 10e-6 * (sum of flops over all processors)/(max time over all processors)\n");
1481: PetscFPrintf(comm, fd, "------------------------------------------------------------------------------------------------------------------------\n");
1483: #if defined(PETSC_USE_DEBUG)
1484: PetscFPrintf(comm, fd, "\n\n");
1485: PetscFPrintf(comm, fd, " ##########################################################\n");
1486: PetscFPrintf(comm, fd, " # #\n");
1487: PetscFPrintf(comm, fd, " # WARNING!!! #\n");
1488: PetscFPrintf(comm, fd, " # #\n");
1489: PetscFPrintf(comm, fd, " # This code was compiled with a debugging option, #\n");
1490: PetscFPrintf(comm, fd, " # To get timing results run ./configure #\n");
1491: PetscFPrintf(comm, fd, " # using --with-debugging=no, the performance will #\n");
1492: PetscFPrintf(comm, fd, " # be generally two or three times faster. #\n");
1493: PetscFPrintf(comm, fd, " # #\n");
1494: PetscFPrintf(comm, fd, " ##########################################################\n\n\n");
1495: #endif
1496: #if defined(PETSC_USE_COMPLEX) && !defined(PETSC_USE_FORTRAN_KERNELS)
1497: PetscFPrintf(comm, fd, "\n\n");
1498: PetscFPrintf(comm, fd, " ##########################################################\n");
1499: PetscFPrintf(comm, fd, " # #\n");
1500: PetscFPrintf(comm, fd, " # WARNING!!! #\n");
1501: PetscFPrintf(comm, fd, " # #\n");
1502: PetscFPrintf(comm, fd, " # The code for various complex numbers numerical #\n");
1503: PetscFPrintf(comm, fd, " # kernels uses C++, which generally is not well #\n");
1504: PetscFPrintf(comm, fd, " # optimized. For performance that is about 4-5 times #\n");
1505: PetscFPrintf(comm, fd, " # faster, specify --with-fortran-kernels=1 #\n");
1506: PetscFPrintf(comm, fd, " # when running ./configure.py. #\n");
1507: PetscFPrintf(comm, fd, " # #\n");
1508: PetscFPrintf(comm, fd, " ##########################################################\n\n\n");
1509: #endif
1511: /* Report events */
1512: PetscFPrintf(comm, fd,"Event Count Time (sec) Flops --- Global --- --- Stage --- Total\n");
1513: PetscFPrintf(comm, fd," Max Ratio Max Ratio Max Ratio Mess Avg len Reduct %%T %%F %%M %%L %%R %%T %%F %%M %%L %%R Mflop/s\n");
1514: PetscFPrintf(comm,fd,"------------------------------------------------------------------------------------------------------------------------\n");
1516: /* Problem: The stage name will not show up unless the stage executed on proc 1 */
1517: for (stage = 0; stage < numStages; stage++) {
1518: if (!stageVisible[stage]) continue;
1519: if (localStageUsed[stage]) {
1520: PetscFPrintf(comm, fd, "\n--- Event Stage %d: %s\n\n", stage, stageInfo[stage].name);
1521: MPIU_Allreduce(&stageInfo[stage].perfInfo.time, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1522: MPIU_Allreduce(&stageInfo[stage].perfInfo.flops, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1523: MPIU_Allreduce(&stageInfo[stage].perfInfo.numMessages, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1524: MPIU_Allreduce(&stageInfo[stage].perfInfo.messageLength, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1525: MPIU_Allreduce(&stageInfo[stage].perfInfo.numReductions, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1526: } else {
1527: PetscFPrintf(comm, fd, "\n--- Event Stage %d: Unknown\n\n", stage);
1528: MPIU_Allreduce(&zero, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1529: MPIU_Allreduce(&zero, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1530: MPIU_Allreduce(&zero, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1531: MPIU_Allreduce(&zero, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1532: MPIU_Allreduce(&zero, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1533: }
1534: mess *= 0.5; messLen *= 0.5; red /= size;
1536: /* Get total number of events in this stage --
1537: Currently, a single processor can register more events than another, but events must all be registered in order,
1538: just like stages. We can removed this requirement if necessary by having a global event numbering and indirection
1539: on the event ID. This seems best accomplished by assoicating a communicator with each stage.
1541: Problem: If the event did not happen on proc 1, its name will not be available.
1542: Problem: Event visibility is not implemented
1543: */
1544: if (localStageUsed[stage]) {
1545: eventInfo = stageLog->stageInfo[stage].eventLog->eventInfo;
1546: localNumEvents = stageLog->stageInfo[stage].eventLog->numEvents;
1547: } else localNumEvents = 0;
1548: MPIU_Allreduce(&localNumEvents, &numEvents, 1, MPI_INT, MPI_MAX, comm);
1549: for (event = 0; event < numEvents; event++) {
1550: if (localStageUsed[stage] && (event < stageLog->stageInfo[stage].eventLog->numEvents) && (eventInfo[event].depth == 0)) {
1551: if ((eventInfo[event].count > 0) && (eventInfo[event].time > 0.0)) flopr = eventInfo[event].flops;
1552: else flopr = 0.0;
1554: MPIU_Allreduce(&flopr, &minf, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1555: MPIU_Allreduce(&flopr, &maxf, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1556: MPIU_Allreduce(&eventInfo[event].flops, &totf, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1557: MPIU_Allreduce(&eventInfo[event].time, &mint, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1558: MPIU_Allreduce(&eventInfo[event].time, &maxt, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1559: MPIU_Allreduce(&eventInfo[event].time, &tott, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1560: MPIU_Allreduce(&eventInfo[event].numMessages, &totm, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1561: MPIU_Allreduce(&eventInfo[event].messageLength, &totml, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1562: MPIU_Allreduce(&eventInfo[event].numReductions, &totr, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1563: MPIU_Allreduce(&eventInfo[event].count, &minCt, 1, MPI_INT, MPI_MIN, comm);
1564: MPIU_Allreduce(&eventInfo[event].count, &maxCt, 1, MPI_INT, MPI_MAX, comm);
1565: name = stageLog->eventLog->eventInfo[event].name;
1566: } else {
1567: flopr = 0.0;
1568: MPIU_Allreduce(&flopr, &minf, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1569: MPIU_Allreduce(&flopr, &maxf, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1570: MPIU_Allreduce(&zero, &totf, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1571: MPIU_Allreduce(&zero, &mint, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);
1572: MPIU_Allreduce(&zero, &maxt, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);
1573: MPIU_Allreduce(&zero, &tott, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1574: MPIU_Allreduce(&zero, &totm, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1575: MPIU_Allreduce(&zero, &totml, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1576: MPIU_Allreduce(&zero, &totr, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);
1577: MPIU_Allreduce(&ierr, &minCt, 1, MPI_INT, MPI_MIN, comm);
1578: MPIU_Allreduce(&ierr, &maxCt, 1, MPI_INT, MPI_MAX, comm);
1579: name = "";
1580: }
1581: if (mint < 0.0) {
1582: PetscFPrintf(comm, fd, "WARNING!!! Minimum time %g over all processors for %s is negative! This happens\n on some machines whose times cannot handle too rapid calls.!\n artificially changing minimum to zero.\n",mint,name);
1583: mint = 0;
1584: }
1585: if (minf < 0.0) SETERRQ2(PETSC_COMM_SELF,PETSC_ERR_PLIB,"Minimum flops %g over all processors for %s is negative! Not possible!",minf,name);
1586: totm *= 0.5; totml *= 0.5; totr /= size;
1588: if (maxCt != 0) {
1589: if (minCt != 0) ratCt = ((PetscLogDouble) maxCt)/minCt; else ratCt = 0.0;
1590: if (mint != 0.0) ratt = maxt/mint; else ratt = 0.0;
1591: if (minf != 0.0) ratf = maxf/minf; else ratf = 0.0;
1592: if (TotalTime != 0.0) fracTime = tott/TotalTime; else fracTime = 0.0;
1593: if (TotalFlops != 0.0) fracFlops = totf/TotalFlops; else fracFlops = 0.0;
1594: if (stageTime != 0.0) fracStageTime = tott/stageTime; else fracStageTime = 0.0;
1595: if (flops != 0.0) fracStageFlops = totf/flops; else fracStageFlops = 0.0;
1596: if (numMessages != 0.0) fracMess = totm/numMessages; else fracMess = 0.0;
1597: if (messageLength != 0.0) fracMessLen = totml/messageLength; else fracMessLen = 0.0;
1598: if (numReductions != 0.0) fracRed = totr/numReductions; else fracRed = 0.0;
1599: if (mess != 0.0) fracStageMess = totm/mess; else fracStageMess = 0.0;
1600: if (messLen != 0.0) fracStageMessLen = totml/messLen; else fracStageMessLen = 0.0;
1601: if (red != 0.0) fracStageRed = totr/red; else fracStageRed = 0.0;
1602: if (totm != 0.0) totml /= totm; else totml = 0.0;
1603: if (maxt != 0.0) flopr = totf/maxt; else flopr = 0.0;
1604: if (fracStageTime > 1.00) PetscFPrintf(comm, fd,"Warning -- total time of event greater than time of entire stage -- something is wrong with the timer\n");
1605: PetscFPrintf(comm, fd,
1606: "%-16s %7d%4.1f %5.4e%4.1f %3.2e%4.1f %2.1e %2.1e %2.1e%3.0f%3.0f%3.0f%3.0f%3.0f %3.0f%3.0f%3.0f%3.0f%3.0f %5.0f\n",
1607: name, maxCt, ratCt, maxt, ratt, maxf, ratf, totm, totml, totr,
1608: 100.0*fracTime, 100.0*fracFlops, 100.0*fracMess, 100.0*fracMessLen, 100.0*fracRed,
1609: 100.0*fracStageTime, 100.0*fracStageFlops, 100.0*fracStageMess, 100.0*fracStageMessLen, 100.0*fracStageRed,
1610: PetscAbsReal(flopr/1.0e6));
1611: }
1612: }
1613: }
1615: /* Memory usage and object creation */
1616: PetscFPrintf(comm, fd, "------------------------------------------------------------------------------------------------------------------------\n");
1617: PetscFPrintf(comm, fd, "\n");
1618: PetscFPrintf(comm, fd, "Memory usage is given in bytes:\n\n");
1620: /* Right now, only stages on the first processor are reported here, meaning only objects associated with
1621: the global communicator, or MPI_COMM_SELF for proc 1. We really should report global stats and then
1622: stats for stages local to processor sets.
1623: */
1624: /* We should figure out the longest object name here (now 20 characters) */
1625: PetscFPrintf(comm, fd, "Object Type Creations Destructions Memory Descendants' Mem.\n");
1626: PetscFPrintf(comm, fd, "Reports information only for process 0.\n");
1627: for (stage = 0; stage < numStages; stage++) {
1628: if (localStageUsed[stage]) {
1629: classInfo = stageLog->stageInfo[stage].classLog->classInfo;
1630: PetscFPrintf(comm, fd, "\n--- Event Stage %d: %s\n\n", stage, stageInfo[stage].name);
1631: for (oclass = 0; oclass < stageLog->stageInfo[stage].classLog->numClasses; oclass++) {
1632: if ((classInfo[oclass].creations > 0) || (classInfo[oclass].destructions > 0)) {
1633: PetscFPrintf(comm, fd, "%20s %5d %5d %11.0f %g\n", stageLog->classLog->classInfo[oclass].name,
1634: classInfo[oclass].creations, classInfo[oclass].destructions, classInfo[oclass].mem,
1635: classInfo[oclass].descMem);
1636: }
1637: }
1638: } else {
1639: PetscFPrintf(comm, fd, "\n--- Event Stage %d: Unknown\n\n", stage);
1640: }
1641: }
1643: PetscFree(localStageUsed);
1644: PetscFree(stageUsed);
1645: PetscFree(localStageVisible);
1646: PetscFree(stageVisible);
1648: /* Information unrelated to this particular run */
1649: PetscFPrintf(comm, fd, "========================================================================================================================\n");
1650: PetscTime(&y);
1651: PetscTime(&x);
1652: PetscTime(&y); PetscTime(&y); PetscTime(&y); PetscTime(&y); PetscTime(&y);
1653: PetscTime(&y); PetscTime(&y); PetscTime(&y); PetscTime(&y); PetscTime(&y);
1654: PetscFPrintf(comm,fd,"Average time to get PetscTime(): %g\n", (y-x)/10.0);
1655: /* MPI information */
1656: if (size > 1) {
1657: MPI_Status status;
1658: PetscMPIInt tag;
1659: MPI_Comm newcomm;
1661: MPI_Barrier(comm);
1662: PetscTime(&x);
1663: MPI_Barrier(comm);
1664: MPI_Barrier(comm);
1665: MPI_Barrier(comm);
1666: MPI_Barrier(comm);
1667: MPI_Barrier(comm);
1668: PetscTime(&y);
1669: PetscFPrintf(comm, fd, "Average time for MPI_Barrier(): %g\n", (y-x)/5.0);
1670: PetscCommDuplicate(comm,&newcomm, &tag);
1671: MPI_Barrier(comm);
1672: if (rank) {
1673: MPI_Recv(0, 0, MPI_INT, rank-1, tag, newcomm, &status);
1674: MPI_Send(0, 0, MPI_INT, (rank+1)%size, tag, newcomm);
1675: } else {
1676: PetscTime(&x);
1677: MPI_Send(0, 0, MPI_INT, 1, tag, newcomm);
1678: MPI_Recv(0, 0, MPI_INT, size-1, tag, newcomm, &status);
1679: PetscTime(&y);
1680: PetscFPrintf(comm,fd,"Average time for zero size MPI_Send(): %g\n", (y-x)/size);
1681: }
1682: PetscCommDestroy(&newcomm);
1683: }
1684: PetscOptionsView(NULL,viewer);
1686: /* Machine and compile information */
1687: #if defined(PETSC_USE_FORTRAN_KERNELS)
1688: PetscFPrintf(comm, fd, "Compiled with FORTRAN kernels\n");
1689: #else
1690: PetscFPrintf(comm, fd, "Compiled without FORTRAN kernels\n");
1691: #endif
1692: #if defined(PETSC_USE_REAL_SINGLE)
1693: PetscFPrintf(comm, fd, "Compiled with single precision PetscScalar and PetscReal\n");
1694: #elif defined(PETSC_USE_LONGDOUBLE)
1695: PetscFPrintf(comm, fd, "Compiled with long double precision PetscScalar and PetscReal\n");
1696: #endif
1698: #if defined(PETSC_USE_REAL_MAT_SINGLE)
1699: PetscFPrintf(comm, fd, "Compiled with single precision matrices\n");
1700: #else
1701: PetscFPrintf(comm, fd, "Compiled with full precision matrices (default)\n");
1702: #endif
1703: PetscFPrintf(comm, fd, "sizeof(short) %d sizeof(int) %d sizeof(long) %d sizeof(void*) %d sizeof(PetscScalar) %d sizeof(PetscInt) %d\n",
1704: (int) sizeof(short), (int) sizeof(int), (int) sizeof(long), (int) sizeof(void*),(int) sizeof(PetscScalar),(int) sizeof(PetscInt));
1706: PetscFPrintf(comm, fd, "Configure options: %s",petscconfigureoptions);
1707: PetscFPrintf(comm, fd, "%s", petscmachineinfo);
1708: PetscFPrintf(comm, fd, "%s", petsccompilerinfo);
1709: PetscFPrintf(comm, fd, "%s", petsccompilerflagsinfo);
1710: PetscFPrintf(comm, fd, "%s", petsclinkerinfo);
1712: /* Cleanup */
1713: PetscFPrintf(comm, fd, "\n");
1714: return(0);
1715: }
1717: PetscErrorCode PetscLogView_Nested(PetscViewer);
1721: /*@C
1722: PetscLogView - Prints a summary of the logging.
1724: Collective over MPI_Comm
1726: Input Parameter:
1727: . viewer - an ASCII viewer
1729: Options Database Keys:
1730: + -log_view [:filename] - Prints summary of log information
1731: . -log_view :filename.py:ascii_info_detail - Saves logging information from each process as a Python file
1732: . -log_view :filename.xml:ascii_xml - Saves a summary of the logging information in a nested format, use a browser to open this file, for example on
1733: Apple MacOS systems use open -a Safari filename.xml
1734: . -log_all - Saves a file Log.rank for each MPI process with details of each step of the computation
1735: - -log_trace [filename] - Displays a trace of what each process is doing
1737: Notes:
1738: It is possible to control the logging programatically but we recommend using the options database approach whenever possible
1739: By default the summary is printed to stdout.
1741: Before calling this routine you must have called either PetscLogDefaultBegin() or PetscLogNestedBegin()
1743: If PETSc is configured with --with-logging=0 then this functionality is not available
1745: The nested XML format was kindly donated by Koos Huijssen and Christiaan M. Klaij MARITIME RESEARCH INSTITUTE NETHERLANDS
1747: Level: beginner
1749: .keywords: log, dump, print
1750: .seealso: PetscLogDefaultBegin(), PetscLogDump()
1751: @*/
1752: PetscErrorCode PetscLogView(PetscViewer viewer)
1753: {
1754: PetscErrorCode ierr;
1755: PetscBool isascii;
1756: PetscViewerFormat format;
1757: int stage, lastStage;
1758: PetscStageLog stageLog;
1761: if (!PetscLogPLB) SETERRQ(PETSC_COMM_SELF,PETSC_ERR_SUP,"Must use -log_summary or PetscLogDefaultBegin() before calling this routine");
1762: /* Pop off any stages the user forgot to remove */
1763: lastStage = 0;
1764: PetscLogGetStageLog(&stageLog);
1765: PetscStageLogGetCurrent(stageLog, &stage);
1766: while (stage >= 0) {
1767: lastStage = stage;
1768: PetscStageLogPop(stageLog);
1769: PetscStageLogGetCurrent(stageLog, &stage);
1770: }
1771: PetscObjectTypeCompare((PetscObject)viewer,PETSCVIEWERASCII,&isascii);
1772: if (!isascii) SETERRQ(PetscObjectComm((PetscObject)viewer),PETSC_ERR_SUP,"Currently can only view logging to ASCII");
1773: PetscViewerGetFormat(viewer,&format);
1774: if (format == PETSC_VIEWER_DEFAULT || format == PETSC_VIEWER_ASCII_INFO) {
1775: PetscLogView_Default(viewer);
1776: } else if (format == PETSC_VIEWER_ASCII_INFO_DETAIL) {
1777: PetscLogView_Detailed(viewer);
1778: } else if (format == PETSC_VIEWER_ASCII_XML) {
1779: PetscLogView_Nested(viewer);
1780: }
1781: PetscStageLogPush(stageLog, lastStage);
1782: return(0);
1783: }
1787: /*@C
1788: PetscLogViewFromOptions - Processes command line options to determine if/how a PetscLog is to be viewed.
1790: Collective on PETSC_COMM_WORLD
1792: Not normally called by user
1794: Level: intermediate
1796: @*/
1797: PetscErrorCode PetscLogViewFromOptions(void)
1798: {
1799: PetscErrorCode ierr;
1800: PetscViewer viewer;
1801: PetscBool flg;
1802: PetscViewerFormat format;
1805: PetscOptionsGetViewer(PETSC_COMM_WORLD,NULL,"-log_view",&viewer,&format,&flg);
1806: if (flg) {
1807: PetscViewerPushFormat(viewer,format);
1808: PetscLogView(viewer);
1809: PetscViewerPopFormat(viewer);
1810: PetscViewerDestroy(&viewer);
1811: }
1812: return(0);
1813: }
1817: /*----------------------------------------------- Counter Functions -------------------------------------------------*/
1820: /*@C
1821: PetscGetFlops - Returns the number of flops used on this processor
1822: since the program began.
1824: Not Collective
1826: Output Parameter:
1827: flops - number of floating point operations
1829: Notes:
1830: A global counter logs all PETSc flop counts. The user can use
1831: PetscLogFlops() to increment this counter to include flops for the
1832: application code.
1834: Level: intermediate
1836: .keywords: log, flops, floating point operations
1838: .seealso: PetscTime(), PetscLogFlops()
1839: @*/
1840: PetscErrorCode PetscGetFlops(PetscLogDouble *flops)
1841: {
1843: *flops = petsc_TotalFlops;
1844: return(0);
1845: }
1849: PetscErrorCode PetscLogObjectState(PetscObject obj, const char format[], ...)
1850: {
1852: size_t fullLength;
1853: va_list Argp;
1856: if (!petsc_logObjects) return(0);
1857: va_start(Argp, format);
1858: PetscVSNPrintf(petsc_objects[obj->id].info, 64,format,&fullLength, Argp);
1859: va_end(Argp);
1860: return(0);
1861: }
1864: /*MC
1865: PetscLogFlops - Adds floating point operations to the global counter.
1867: Synopsis:
1868: #include <petsclog.h>
1869: PetscErrorCode PetscLogFlops(PetscLogDouble f)
1871: Not Collective
1873: Input Parameter:
1874: . f - flop counter
1877: Usage:
1878: .vb
1879: PetscLogEvent USER_EVENT;
1880: PetscLogEventRegister("User event",0,&USER_EVENT);
1881: PetscLogEventBegin(USER_EVENT,0,0,0,0);
1882: [code segment to monitor]
1883: PetscLogFlops(user_flops)
1884: PetscLogEventEnd(USER_EVENT,0,0,0,0);
1885: .ve
1887: Notes:
1888: A global counter logs all PETSc flop counts. The user can use
1889: PetscLogFlops() to increment this counter to include flops for the
1890: application code.
1892: Level: intermediate
1894: .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogEventEnd(), PetscGetFlops()
1896: .keywords: log, flops, floating point operations
1897: M*/
1899: /*MC
1900: PetscPreLoadBegin - Begin a segment of code that may be preloaded (run twice)
1901: to get accurate timings
1903: Synopsis:
1904: #include <petsclog.h>
1905: void PetscPreLoadBegin(PetscBool flag,char *name);
1907: Not Collective
1909: Input Parameter:
1910: + flag - PETSC_TRUE to run twice, PETSC_FALSE to run once, may be overridden
1911: with command line option -preload true or -preload false
1912: - name - name of first stage (lines of code timed separately with -log_summary) to
1913: be preloaded
1915: Usage:
1916: .vb
1917: PetscPreLoadBegin(PETSC_TRUE,"first stage);
1918: lines of code
1919: PetscPreLoadStage("second stage");
1920: lines of code
1921: PetscPreLoadEnd();
1922: .ve
1924: Notes: Only works in C/C++, not Fortran
1926: Flags available within the macro.
1927: + PetscPreLoadingUsed - true if we are or have done preloading
1928: . PetscPreLoadingOn - true if it is CURRENTLY doing preload
1929: . PetscPreLoadIt - 0 for the first computation (with preloading turned off it is only 0) 1 for the second
1930: - PetscPreLoadMax - number of times it will do the computation, only one when preloading is turned on
1931: The first two variables are available throughout the program, the second two only between the PetscPreLoadBegin()
1932: and PetscPreLoadEnd()
1934: Level: intermediate
1936: .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadEnd(), PetscPreLoadStage()
1938: Concepts: preloading
1939: Concepts: timing^accurate
1940: Concepts: paging^eliminating effects of
1943: M*/
1945: /*MC
1946: PetscPreLoadEnd - End a segment of code that may be preloaded (run twice)
1947: to get accurate timings
1949: Synopsis:
1950: #include <petsclog.h>
1951: void PetscPreLoadEnd(void);
1953: Not Collective
1955: Usage:
1956: .vb
1957: PetscPreLoadBegin(PETSC_TRUE,"first stage);
1958: lines of code
1959: PetscPreLoadStage("second stage");
1960: lines of code
1961: PetscPreLoadEnd();
1962: .ve
1964: Notes: only works in C/C++ not fortran
1966: Level: intermediate
1968: .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadBegin(), PetscPreLoadStage()
1970: M*/
1972: /*MC
1973: PetscPreLoadStage - Start a new segment of code to be timed separately.
1974: to get accurate timings
1976: Synopsis:
1977: #include <petsclog.h>
1978: void PetscPreLoadStage(char *name);
1980: Not Collective
1982: Usage:
1983: .vb
1984: PetscPreLoadBegin(PETSC_TRUE,"first stage);
1985: lines of code
1986: PetscPreLoadStage("second stage");
1987: lines of code
1988: PetscPreLoadEnd();
1989: .ve
1991: Notes: only works in C/C++ not fortran
1993: Level: intermediate
1995: .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadBegin(), PetscPreLoadEnd()
1997: M*/
2000: #else /* end of -DPETSC_USE_LOG section */
2004: PetscErrorCode PetscLogObjectState(PetscObject obj, const char format[], ...)
2005: {
2007: return(0);
2008: }
2010: #endif /* PETSC_USE_LOG*/
2013: PetscClassId PETSC_LARGEST_CLASSID = PETSC_SMALLEST_CLASSID;
2014: PetscClassId PETSC_OBJECT_CLASSID = 0;
2018: /*@C
2019: PetscClassIdRegister - Registers a new class name for objects and logging operations in an application code.
2021: Not Collective
2023: Input Parameter:
2024: . name - The class name
2026: Output Parameter:
2027: . oclass - The class id or classid
2029: Level: developer
2031: .keywords: log, class, register
2033: @*/
2034: PetscErrorCode PetscClassIdRegister(const char name[],PetscClassId *oclass)
2035: {
2036: #if defined(PETSC_USE_LOG)
2037: PetscStageLog stageLog;
2038: PetscInt stage;
2040: #endif
2043: *oclass = ++PETSC_LARGEST_CLASSID;
2044: #if defined(PETSC_USE_LOG)
2045: PetscLogGetStageLog(&stageLog);
2046: PetscClassRegLogRegister(stageLog->classLog, name, *oclass);
2047: for (stage = 0; stage < stageLog->numStages; stage++) {
2048: ClassPerfLogEnsureSize(stageLog->stageInfo[stage].classLog, stageLog->classLog->numClasses);
2049: }
2050: #endif
2051: return(0);
2052: }
2054: #if defined(PETSC_USE_LOG) && defined(PETSC_HAVE_MPE)
2055: #include <mpe.h>
2057: PetscBool PetscBeganMPE = PETSC_FALSE;
2059: PETSC_INTERN PetscErrorCode PetscLogEventBeginMPE(PetscLogEvent,int,PetscObject,PetscObject,PetscObject,PetscObject);
2060: PETSC_INTERN PetscErrorCode PetscLogEventEndMPE(PetscLogEvent,int,PetscObject,PetscObject,PetscObject,PetscObject);
2064: /*@C
2065: PetscLogMPEBegin - Turns on MPE logging of events. This creates large log files
2066: and slows the program down.
2068: Collective over PETSC_COMM_WORLD
2070: Options Database Keys:
2071: . -log_mpe - Prints extensive log information
2073: Notes:
2074: A related routine is PetscLogDefaultBegin() (with the options key -log_summary), which is
2075: intended for production runs since it logs only flop rates and object
2076: creation (and should not significantly slow the programs).
2078: Level: advanced
2080: Concepts: logging^MPE
2081: Concepts: logging^message passing
2083: .seealso: PetscLogDump(), PetscLogDefaultBegin(), PetscLogAllBegin(), PetscLogEventActivate(),
2084: PetscLogEventDeactivate()
2085: @*/
2086: PetscErrorCode PetscLogMPEBegin(void)
2087: {
2091: /* Do MPE initialization */
2092: if (!MPE_Initialized_logging()) { /* This function exists in mpich 1.1.2 and higher */
2093: PetscInfo(0,"Initializing MPE.\n");
2094: MPE_Init_log();
2096: PetscBeganMPE = PETSC_TRUE;
2097: } else {
2098: PetscInfo(0,"MPE already initialized. Not attempting to reinitialize.\n");
2099: }
2100: PetscLogSet(PetscLogEventBeginMPE, PetscLogEventEndMPE);
2101: return(0);
2102: }
2106: /*@C
2107: PetscLogMPEDump - Dumps the MPE logging info to file for later use with Jumpshot.
2109: Collective over PETSC_COMM_WORLD
2111: Level: advanced
2113: .seealso: PetscLogDump(), PetscLogAllBegin(), PetscLogMPEBegin()
2114: @*/
2115: PetscErrorCode PetscLogMPEDump(const char sname[])
2116: {
2117: char name[PETSC_MAX_PATH_LEN];
2121: if (PetscBeganMPE) {
2122: PetscInfo(0,"Finalizing MPE.\n");
2123: if (sname) {
2124: PetscStrcpy(name,sname);
2125: } else {
2126: PetscGetProgramName(name,PETSC_MAX_PATH_LEN);
2127: }
2128: MPE_Finish_log(name);
2129: } else {
2130: PetscInfo(0,"Not finalizing MPE (not started by PETSc).\n");
2131: }
2132: return(0);
2133: }
2135: #define PETSC_RGB_COLORS_MAX 39
2136: static const char *PetscLogMPERGBColors[PETSC_RGB_COLORS_MAX] = {
2137: "OliveDrab: ",
2138: "BlueViolet: ",
2139: "CadetBlue: ",
2140: "CornflowerBlue: ",
2141: "DarkGoldenrod: ",
2142: "DarkGreen: ",
2143: "DarkKhaki: ",
2144: "DarkOliveGreen: ",
2145: "DarkOrange: ",
2146: "DarkOrchid: ",
2147: "DarkSeaGreen: ",
2148: "DarkSlateGray: ",
2149: "DarkTurquoise: ",
2150: "DeepPink: ",
2151: "DarkKhaki: ",
2152: "DimGray: ",
2153: "DodgerBlue: ",
2154: "GreenYellow: ",
2155: "HotPink: ",
2156: "IndianRed: ",
2157: "LavenderBlush: ",
2158: "LawnGreen: ",
2159: "LemonChiffon: ",
2160: "LightCoral: ",
2161: "LightCyan: ",
2162: "LightPink: ",
2163: "LightSalmon: ",
2164: "LightSlateGray: ",
2165: "LightYellow: ",
2166: "LimeGreen: ",
2167: "MediumPurple: ",
2168: "MediumSeaGreen: ",
2169: "MediumSlateBlue:",
2170: "MidnightBlue: ",
2171: "MintCream: ",
2172: "MistyRose: ",
2173: "NavajoWhite: ",
2174: "NavyBlue: ",
2175: "OliveDrab: "
2176: };
2180: /*@C
2181: PetscLogMPEGetRGBColor - This routine returns a rgb color useable with PetscLogEventRegister()
2183: Not collective. Maybe it should be?
2185: Output Parameter
2186: . str - character string representing the color
2188: Level: developer
2190: .keywords: log, mpe , color
2191: .seealso: PetscLogEventRegister
2192: @*/
2193: PetscErrorCode PetscLogMPEGetRGBColor(const char *str[])
2194: {
2195: static int idx = 0;
2198: *str = PetscLogMPERGBColors[idx];
2199: idx = (idx + 1)% PETSC_RGB_COLORS_MAX;
2200: return(0);
2201: }
2203: #endif /* PETSC_USE_LOG && PETSC_HAVE_MPE */