1 2 /* 3 PETSc code to log object creation and destruction and PETSc events. 4 5 This provides the public API used by the rest of PETSc and by users. 6 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. 9 10 */ 11 #include <petscsys.h> /*I "petscsys.h" I*/ 12 #include <petsctime.h> 13 #if defined(PETSC_HAVE_MPE) 14 #include <mpe.h> 15 #endif 16 #include <stdarg.h> 17 #include <sys/types.h> 18 #if defined(PETSC_HAVE_STDLIB_H) 19 #include <stdlib.h> 20 #endif 21 #if defined(PETSC_HAVE_MALLOC_H) 22 #include <malloc.h> 23 #endif 24 #include <petsc-private/logimpl.h> 25 #include <petscthreadcomm.h> 26 27 PetscLogEvent PETSC_LARGEST_EVENT = PETSC_EVENT; 28 29 #if defined(PETSC_CLANGUAGE_CXX) && !defined(PETSC_USE_EXTERN_CXX) 30 std::map<std::string,PETSc::LogEvent> PETSc::Log::event_registry; 31 std::map<std::string,PETSc::LogStage> PETSc::Log::stage_registry; 32 #endif 33 34 #if defined(PETSC_USE_LOG) 35 #include <petscmachineinfo.h> 36 #include <petscconfiginfo.h> 37 38 /* used in the MPI_XXX() count macros in petsclog.h */ 39 40 /* Action and object logging variables */ 41 Action *petsc_actions = PETSC_NULL; 42 Object *petsc_objects = PETSC_NULL; 43 PetscBool petsc_logActions = PETSC_FALSE; 44 PetscBool petsc_logObjects = PETSC_FALSE; 45 int petsc_numActions = 0, petsc_maxActions = 100; 46 int petsc_numObjects = 0, petsc_maxObjects = 100; 47 int petsc_numObjectsDestroyed = 0; 48 49 /* Global counters */ 50 PetscLogDouble petsc_BaseTime = 0.0; 51 PetscLogDouble petsc_TotalFlops = 0.0; /* The number of flops */ 52 PetscLogDouble petsc_tmp_flops = 0.0; /* The incremental number of flops */ 53 PetscLogDouble petsc_send_ct = 0.0; /* The number of sends */ 54 PetscLogDouble petsc_recv_ct = 0.0; /* The number of receives */ 55 PetscLogDouble petsc_send_len = 0.0; /* The total length of all sent messages */ 56 PetscLogDouble petsc_recv_len = 0.0; /* The total length of all received messages */ 57 PetscLogDouble petsc_isend_ct = 0.0; /* The number of immediate sends */ 58 PetscLogDouble petsc_irecv_ct = 0.0; /* The number of immediate receives */ 59 PetscLogDouble petsc_isend_len = 0.0; /* The total length of all immediate send messages */ 60 PetscLogDouble petsc_irecv_len = 0.0; /* The total length of all immediate receive messages */ 61 PetscLogDouble petsc_wait_ct = 0.0; /* The number of waits */ 62 PetscLogDouble petsc_wait_any_ct = 0.0; /* The number of anywaits */ 63 PetscLogDouble petsc_wait_all_ct = 0.0; /* The number of waitalls */ 64 PetscLogDouble petsc_sum_of_waits_ct = 0.0; /* The total number of waits */ 65 PetscLogDouble petsc_allreduce_ct = 0.0; /* The number of reductions */ 66 PetscLogDouble petsc_gather_ct = 0.0; /* The number of gathers and gathervs */ 67 PetscLogDouble petsc_scatter_ct = 0.0; /* The number of scatters and scattervs */ 68 69 /* Logging functions */ 70 PetscErrorCode (*PetscLogPHC)(PetscObject) = PETSC_NULL; 71 PetscErrorCode (*PetscLogPHD)(PetscObject) = PETSC_NULL; 72 PetscErrorCode (*PetscLogPLB)(PetscLogEvent, int, PetscObject, PetscObject, PetscObject, PetscObject) = PETSC_NULL; 73 PetscErrorCode (*PetscLogPLE)(PetscLogEvent, int, PetscObject, PetscObject, PetscObject, PetscObject) = PETSC_NULL; 74 75 /* Tracing event logging variables */ 76 FILE *petsc_tracefile = PETSC_NULL; 77 int petsc_tracelevel = 0; 78 const char *petsc_traceblanks = " "; 79 char petsc_tracespace[128] = " "; 80 PetscLogDouble petsc_tracetime = 0.0; 81 static PetscBool PetscLogBegin_PrivateCalled = PETSC_FALSE; 82 83 /*---------------------------------------------- General Functions --------------------------------------------------*/ 84 #undef __FUNCT__ 85 #define __FUNCT__ "PetscLogDestroy" 86 /*@C 87 PetscLogDestroy - Destroys the object and event logging data and resets the global counters. 88 89 Not Collective 90 91 Notes: 92 This routine should not usually be used by programmers. Instead employ 93 PetscLogStagePush() and PetscLogStagePop(). 94 95 Level: developer 96 97 .keywords: log, destroy 98 .seealso: PetscLogDump(), PetscLogAllBegin(), PetscLogView(), PetscLogStagePush(), PlogStagePop() 99 @*/ 100 PetscErrorCode PetscLogDestroy(void) 101 { 102 PetscStageLog stageLog; 103 PetscErrorCode ierr; 104 105 PetscFunctionBegin; 106 ierr = PetscFree(petsc_actions);CHKERRQ(ierr); 107 ierr = PetscFree(petsc_objects);CHKERRQ(ierr); 108 ierr = PetscLogSet(PETSC_NULL, PETSC_NULL);CHKERRQ(ierr); 109 110 /* Resetting phase */ 111 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 112 ierr = PetscStageLogDestroy(stageLog);CHKERRQ(ierr); 113 114 petsc_TotalFlops = 0.0; 115 petsc_numActions = 0; 116 petsc_numObjects = 0; 117 petsc_numObjectsDestroyed = 0; 118 petsc_maxActions = 100; 119 petsc_maxObjects = 100; 120 petsc_actions = PETSC_NULL; 121 petsc_objects = PETSC_NULL; 122 petsc_logActions = PETSC_FALSE; 123 petsc_logObjects = PETSC_FALSE; 124 petsc_BaseTime = 0.0; 125 petsc_TotalFlops = 0.0; 126 petsc_tmp_flops = 0.0; 127 petsc_send_ct = 0.0; 128 petsc_recv_ct = 0.0; 129 petsc_send_len = 0.0; 130 petsc_recv_len = 0.0; 131 petsc_isend_ct = 0.0; 132 petsc_irecv_ct = 0.0; 133 petsc_isend_len = 0.0; 134 petsc_irecv_len = 0.0; 135 petsc_wait_ct = 0.0; 136 petsc_wait_any_ct = 0.0; 137 petsc_wait_all_ct = 0.0; 138 petsc_sum_of_waits_ct = 0.0; 139 petsc_allreduce_ct = 0.0; 140 petsc_gather_ct = 0.0; 141 petsc_scatter_ct = 0.0; 142 PETSC_LARGEST_EVENT = PETSC_EVENT; 143 PetscLogPHC = PETSC_NULL; 144 PetscLogPHD = PETSC_NULL; 145 petsc_tracefile = PETSC_NULL; 146 petsc_tracelevel = 0; 147 petsc_traceblanks = " "; 148 petsc_tracespace[0] = ' '; petsc_tracespace[1] = 0; 149 petsc_tracetime = 0.0; 150 PETSC_LARGEST_CLASSID = PETSC_SMALLEST_CLASSID; 151 PETSC_OBJECT_CLASSID = 0; 152 petsc_stageLog = 0; 153 PetscLogBegin_PrivateCalled = PETSC_FALSE; 154 PetscFunctionReturn(0); 155 } 156 157 #undef __FUNCT__ 158 #define __FUNCT__ "PetscLogSet" 159 /*@C 160 PetscLogSet - Sets the logging functions called at the beginning and ending of every event. 161 162 Not Collective 163 164 Input Parameters: 165 + b - The function called at beginning of event 166 - e - The function called at end of event 167 168 Level: developer 169 170 .seealso: PetscLogDump(), PetscLogBegin(), PetscLogAllBegin(), PetscLogTraceBegin() 171 @*/ 172 PetscErrorCode PetscLogSet(PetscErrorCode (*b)(PetscLogEvent, int, PetscObject, PetscObject, PetscObject, PetscObject), 173 PetscErrorCode (*e)(PetscLogEvent, int, PetscObject, PetscObject, PetscObject, PetscObject)) 174 { 175 PetscFunctionBegin; 176 PetscLogPLB = b; 177 PetscLogPLE = e; 178 PetscFunctionReturn(0); 179 } 180 181 #if defined(PETSC_HAVE_CHUD) 182 #include <CHUD/CHUD.h> 183 #endif 184 #if defined(PETSC_HAVE_PAPI) 185 #include <papi.h> 186 int PAPIEventSet = PAPI_NULL; 187 #endif 188 189 /*------------------------------------------- Initialization Functions ----------------------------------------------*/ 190 #undef __FUNCT__ 191 #define __FUNCT__ "PetscLogBegin_Private" 192 PetscErrorCode PetscLogBegin_Private(void) 193 { 194 int stage; 195 PetscBool opt; 196 PetscErrorCode ierr; 197 198 PetscFunctionBegin; 199 if (PetscLogBegin_PrivateCalled) PetscFunctionReturn(0); 200 PetscLogBegin_PrivateCalled = PETSC_TRUE; 201 202 ierr = PetscOptionsHasName(PETSC_NULL, "-log_exclude_actions", &opt);CHKERRQ(ierr); 203 if (opt) petsc_logActions = PETSC_FALSE; 204 ierr = PetscOptionsHasName(PETSC_NULL, "-log_exclude_objects", &opt);CHKERRQ(ierr); 205 if (opt) petsc_logObjects = PETSC_FALSE; 206 if (petsc_logActions) { 207 ierr = PetscMalloc(petsc_maxActions * sizeof(Action), &petsc_actions);CHKERRQ(ierr); 208 } 209 if (petsc_logObjects) { 210 ierr = PetscMalloc(petsc_maxObjects * sizeof(Object), &petsc_objects);CHKERRQ(ierr); 211 } 212 PetscLogPHC = PetscLogObjCreateDefault; 213 PetscLogPHD = PetscLogObjDestroyDefault; 214 /* Setup default logging structures */ 215 ierr = PetscStageLogCreate(&petsc_stageLog);CHKERRQ(ierr); 216 ierr = PetscStageLogRegister(petsc_stageLog, "Main Stage", &stage);CHKERRQ(ierr); 217 #if defined(PETSC_HAVE_CHUD) 218 ierr = chudInitialize();CHKERRQ(ierr); 219 ierr = chudAcquireSamplingFacility(CHUD_BLOCKING);CHKERRQ(ierr); 220 ierr = chudSetSamplingDevice(chudCPU1Dev);CHKERRQ(ierr); 221 ierr = chudSetStartDelay(0,chudNanoSeconds);CHKERRQ(ierr); 222 ierr = chudClearPMCMode(chudCPU1Dev,chudUnused);CHKERRQ(ierr); 223 ierr = chudClearPMCs();CHKERRQ(ierr); 224 /* ierr = chudSetPMCMuxPosition(chudCPU1Dev,0,0);CHKERRQ(ierr); */ 225 printf("%s\n",chudGetEventName(chudCPU1Dev,PMC_1,193)); 226 printf("%s\n",chudGetEventDescription(chudCPU1Dev,PMC_1,193)); 227 printf("%s\n",chudGetEventNotes(chudCPU1Dev,PMC_1,193)); 228 ierr = chudSetPMCEvent(chudCPU1Dev,PMC_1,193);CHKERRQ(ierr); 229 ierr = chudSetPMCMode(chudCPU1Dev,PMC_1,chudCounter);CHKERRQ(ierr); 230 ierr = chudSetPrivilegeFilter(chudCPU1Dev,PMC_1,chudCountUserEvents);CHKERRQ(ierr); 231 ierr = chudSetPMCEventMask(chudCPU1Dev,PMC_1,0xFE);CHKERRQ(ierr); 232 if (!chudIsEventValid(chudCPU1Dev,PMC_1,193)) SETERRQ1(PETSC_COMM_SELF,PETSC_ERR_SUP,"Event is not valid %d",193); 233 ierr = chudStartPMCs();CHKERRQ(ierr); 234 #endif 235 #if defined(PETSC_HAVE_PAPI) 236 ierr = PAPI_library_init(PAPI_VER_CURRENT); 237 if (ierr != PAPI_VER_CURRENT) SETERRQ(PETSC_COMM_SELF,PETSC_ERR_LIB,"Cannot initialize PAPI"); 238 ierr = PAPI_query_event(PAPI_FP_INS);CHKERRQ(ierr); 239 ierr = PAPI_create_eventset(&PAPIEventSet);CHKERRQ(ierr); 240 ierr = PAPI_add_event(PAPIEventSet,PAPI_FP_INS);CHKERRQ(ierr); 241 ierr = PAPI_start(PAPIEventSet);CHKERRQ(ierr); 242 #endif 243 244 /* All processors sync here for more consistent logging */ 245 ierr = MPI_Barrier(PETSC_COMM_WORLD);CHKERRQ(ierr); 246 PetscTime(petsc_BaseTime); 247 ierr = PetscLogStagePush(stage);CHKERRQ(ierr); 248 PetscFunctionReturn(0); 249 } 250 251 #undef __FUNCT__ 252 #define __FUNCT__ "PetscLogBegin" 253 /*@C 254 PetscLogBegin - Turns on logging of objects and events. This logs flop 255 rates and object creation and should not slow programs down too much. 256 This routine may be called more than once. 257 258 Logically Collective over PETSC_COMM_WORLD 259 260 Options Database Keys: 261 + -log_summary - Prints summary of flop and timing information to the 262 screen (for code compiled with PETSC_USE_LOG) 263 - -log - Prints detailed log information (for code compiled with PETSC_USE_LOG) 264 265 Usage: 266 .vb 267 PetscInitialize(...); 268 PetscLogBegin(); 269 ... code ... 270 PetscLogView(viewer); or PetscLogDump(); 271 PetscFinalize(); 272 .ve 273 274 Notes: 275 PetscLogView(viewer) or PetscLogDump() actually cause the printing of 276 the logging information. 277 278 Level: advanced 279 280 .keywords: log, begin 281 .seealso: PetscLogDump(), PetscLogAllBegin(), PetscLogView(), PetscLogTraceBegin() 282 @*/ 283 PetscErrorCode PetscLogBegin(void) 284 { 285 PetscErrorCode ierr; 286 287 PetscFunctionBegin; 288 ierr = PetscLogSet(PetscLogEventBeginDefault, PetscLogEventEndDefault);CHKERRQ(ierr); 289 ierr = PetscLogBegin_Private();CHKERRQ(ierr); 290 PetscFunctionReturn(0); 291 } 292 293 #undef __FUNCT__ 294 #define __FUNCT__ "PetscLogAllBegin" 295 /*@C 296 PetscLogAllBegin - Turns on extensive logging of objects and events. Logs 297 all events. This creates large log files and slows the program down. 298 299 Logically Collective on PETSC_COMM_WORLD 300 301 Options Database Keys: 302 . -log_all - Prints extensive log information (for code compiled with PETSC_USE_LOG) 303 304 Usage: 305 .vb 306 PetscInitialize(...); 307 PetscLogAllBegin(); 308 ... code ... 309 PetscLogDump(filename); 310 PetscFinalize(); 311 .ve 312 313 Notes: 314 A related routine is PetscLogBegin (with the options key -log), which is 315 intended for production runs since it logs only flop rates and object 316 creation (and shouldn't significantly slow the programs). 317 318 Level: advanced 319 320 .keywords: log, all, begin 321 .seealso: PetscLogDump(), PetscLogBegin(), PetscLogTraceBegin() 322 @*/ 323 PetscErrorCode PetscLogAllBegin(void) 324 { 325 PetscErrorCode ierr; 326 327 PetscFunctionBegin; 328 ierr = PetscLogSet(PetscLogEventBeginComplete, PetscLogEventEndComplete);CHKERRQ(ierr); 329 ierr = PetscLogBegin_Private();CHKERRQ(ierr); 330 PetscFunctionReturn(0); 331 } 332 333 #undef __FUNCT__ 334 #define __FUNCT__ "PetscLogTraceBegin" 335 /*@ 336 PetscLogTraceBegin - Activates trace logging. Every time a PETSc event 337 begins or ends, the event name is printed. 338 339 Logically Collective on PETSC_COMM_WORLD 340 341 Input Parameter: 342 . file - The file to print trace in (e.g. stdout) 343 344 Options Database Key: 345 . -log_trace [filename] - Activates PetscLogTraceBegin() 346 347 Notes: 348 PetscLogTraceBegin() prints the processor number, the execution time (sec), 349 then "Event begin:" or "Event end:" followed by the event name. 350 351 PetscLogTraceBegin() allows tracing of all PETSc calls, which is useful 352 to determine where a program is hanging without running in the 353 debugger. Can be used in conjunction with the -info option. 354 355 Level: intermediate 356 357 .seealso: PetscLogDump(), PetscLogAllBegin(), PetscLogView(), PetscLogBegin() 358 @*/ 359 PetscErrorCode PetscLogTraceBegin(FILE *file) 360 { 361 PetscErrorCode ierr; 362 363 PetscFunctionBegin; 364 petsc_tracefile = file; 365 366 ierr = PetscLogSet(PetscLogEventBeginTrace, PetscLogEventEndTrace);CHKERRQ(ierr); 367 ierr = PetscLogBegin_Private();CHKERRQ(ierr); 368 PetscFunctionReturn(0); 369 } 370 371 #undef __FUNCT__ 372 #define __FUNCT__ "PetscLogActions" 373 /*@ 374 PetscLogActions - Determines whether actions are logged for the graphical viewer. 375 376 Not Collective 377 378 Input Parameter: 379 . flag - PETSC_TRUE if actions are to be logged 380 381 Level: intermediate 382 383 Note: Logging of actions continues to consume more memory as the program 384 runs. Long running programs should consider turning this feature off. 385 386 Options Database Keys: 387 . -log_exclude_actions - Turns off actions logging 388 389 .keywords: log, stage, register 390 .seealso: PetscLogStagePush(), PetscLogStagePop() 391 @*/ 392 PetscErrorCode PetscLogActions(PetscBool flag) 393 { 394 PetscFunctionBegin; 395 petsc_logActions = flag; 396 PetscFunctionReturn(0); 397 } 398 399 #undef __FUNCT__ 400 #define __FUNCT__ "PetscLogObjects" 401 /*@ 402 PetscLogObjects - Determines whether objects are logged for the graphical viewer. 403 404 Not Collective 405 406 Input Parameter: 407 . flag - PETSC_TRUE if objects are to be logged 408 409 Level: intermediate 410 411 Note: Logging of objects continues to consume more memory as the program 412 runs. Long running programs should consider turning this feature off. 413 414 Options Database Keys: 415 . -log_exclude_objects - Turns off objects logging 416 417 .keywords: log, stage, register 418 .seealso: PetscLogStagePush(), PetscLogStagePop() 419 @*/ 420 PetscErrorCode PetscLogObjects(PetscBool flag) 421 { 422 PetscFunctionBegin; 423 petsc_logObjects = flag; 424 PetscFunctionReturn(0); 425 } 426 427 /*------------------------------------------------ Stage Functions --------------------------------------------------*/ 428 #undef __FUNCT__ 429 #define __FUNCT__ "PetscLogStageRegister" 430 /*@C 431 PetscLogStageRegister - Attaches a charactor string name to a logging stage. 432 433 Not Collective 434 435 Input Parameter: 436 . sname - The name to associate with that stage 437 438 Output Parameter: 439 . stage - The stage number 440 441 Level: intermediate 442 443 .keywords: log, stage, register 444 .seealso: PetscLogStagePush(), PetscLogStagePop() 445 @*/ 446 PetscErrorCode PetscLogStageRegister(const char sname[],PetscLogStage *stage) 447 { 448 PetscStageLog stageLog; 449 PetscLogEvent event; 450 PetscErrorCode ierr; 451 452 PetscFunctionBegin; 453 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 454 ierr = PetscStageLogRegister(stageLog, sname, stage);CHKERRQ(ierr); 455 /* Copy events already changed in the main stage, this sucks */ 456 ierr = EventPerfLogEnsureSize(stageLog->stageInfo[*stage].eventLog, stageLog->eventLog->numEvents);CHKERRQ(ierr); 457 for (event = 0; event < stageLog->eventLog->numEvents; event++) { 458 ierr = EventPerfInfoCopy(&stageLog->stageInfo[0].eventLog->eventInfo[event],&stageLog->stageInfo[*stage].eventLog->eventInfo[event]);CHKERRQ(ierr); 459 } 460 ierr = ClassPerfLogEnsureSize(stageLog->stageInfo[*stage].classLog, stageLog->classLog->numClasses);CHKERRQ(ierr); 461 PetscFunctionReturn(0); 462 } 463 464 #undef __FUNCT__ 465 #define __FUNCT__ "PetscLogStagePush" 466 /*@C 467 PetscLogStagePush - This function pushes a stage on the stack. 468 469 Not Collective 470 471 Input Parameter: 472 . stage - The stage on which to log 473 474 Usage: 475 If the option -log_sumary is used to run the program containing the 476 following code, then 2 sets of summary data will be printed during 477 PetscFinalize(). 478 .vb 479 PetscInitialize(int *argc,char ***args,0,0); 480 [stage 0 of code] 481 PetscLogStagePush(1); 482 [stage 1 of code] 483 PetscLogStagePop(); 484 PetscBarrier(...); 485 [more stage 0 of code] 486 PetscFinalize(); 487 .ve 488 489 Notes: 490 Use PetscLogStageRegister() to register a stage. 491 492 Level: intermediate 493 494 .keywords: log, push, stage 495 .seealso: PetscLogStagePop(), PetscLogStageRegister(), PetscBarrier() 496 @*/ 497 PetscErrorCode PetscLogStagePush(PetscLogStage stage) 498 { 499 PetscStageLog stageLog; 500 PetscErrorCode ierr; 501 502 PetscFunctionBegin; 503 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 504 ierr = PetscStageLogPush(stageLog, stage);CHKERRQ(ierr); 505 PetscFunctionReturn(0); 506 } 507 508 #undef __FUNCT__ 509 #define __FUNCT__ "PetscLogStagePop" 510 /*@C 511 PetscLogStagePop - This function pops a stage from the stack. 512 513 Not Collective 514 515 Usage: 516 If the option -log_sumary is used to run the program containing the 517 following code, then 2 sets of summary data will be printed during 518 PetscFinalize(). 519 .vb 520 PetscInitialize(int *argc,char ***args,0,0); 521 [stage 0 of code] 522 PetscLogStagePush(1); 523 [stage 1 of code] 524 PetscLogStagePop(); 525 PetscBarrier(...); 526 [more stage 0 of code] 527 PetscFinalize(); 528 .ve 529 530 Notes: 531 Use PetscLogStageRegister() to register a stage. 532 533 Level: intermediate 534 535 .keywords: log, pop, stage 536 .seealso: PetscLogStagePush(), PetscLogStageRegister(), PetscBarrier() 537 @*/ 538 PetscErrorCode PetscLogStagePop(void) 539 { 540 PetscStageLog stageLog; 541 PetscErrorCode ierr; 542 543 PetscFunctionBegin; 544 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 545 ierr = PetscStageLogPop(stageLog);CHKERRQ(ierr); 546 PetscFunctionReturn(0); 547 } 548 549 #undef __FUNCT__ 550 #define __FUNCT__ "PetscLogStageSetActive" 551 /*@ 552 PetscLogStageSetActive - Determines stage activity for PetscLogEventBegin() and PetscLogEventEnd(). 553 554 Not Collective 555 556 Input Parameters: 557 + stage - The stage 558 - isActive - The activity flag, PETSC_TRUE for logging, else PETSC_FALSE (defaults to PETSC_TRUE) 559 560 Level: intermediate 561 562 .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadBegin(), PetscPreLoadEnd(), PetscPreLoadStage() 563 @*/ 564 PetscErrorCode PetscLogStageSetActive(PetscLogStage stage, PetscBool isActive) 565 { 566 PetscStageLog stageLog; 567 PetscErrorCode ierr; 568 569 PetscFunctionBegin; 570 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 571 ierr = PetscStageLogSetActive(stageLog, stage, isActive);CHKERRQ(ierr); 572 PetscFunctionReturn(0); 573 } 574 575 #undef __FUNCT__ 576 #define __FUNCT__ "PetscLogStageGetActive" 577 /*@ 578 PetscLogStageGetActive - Returns stage activity for PetscLogEventBegin() and PetscLogEventEnd(). 579 580 Not Collective 581 582 Input Parameter: 583 . stage - The stage 584 585 Output Parameter: 586 . isActive - The activity flag, PETSC_TRUE for logging, else PETSC_FALSE (defaults to PETSC_TRUE) 587 588 Level: intermediate 589 590 .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadBegin(), PetscPreLoadEnd(), PetscPreLoadStage() 591 @*/ 592 PetscErrorCode PetscLogStageGetActive(PetscLogStage stage, PetscBool *isActive) 593 { 594 PetscStageLog stageLog; 595 PetscErrorCode ierr; 596 597 PetscFunctionBegin; 598 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 599 ierr = PetscStageLogGetActive(stageLog, stage, isActive);CHKERRQ(ierr); 600 PetscFunctionReturn(0); 601 } 602 603 #undef __FUNCT__ 604 #define __FUNCT__ "PetscLogStageSetVisible" 605 /*@ 606 PetscLogStageSetVisible - Determines stage visibility in PetscLogView() 607 608 Not Collective 609 610 Input Parameters: 611 + stage - The stage 612 - isVisible - The visibility flag, PETSC_TRUE to print, else PETSC_FALSE (defaults to PETSC_TRUE) 613 614 Level: intermediate 615 616 .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscLogView() 617 @*/ 618 PetscErrorCode PetscLogStageSetVisible(PetscLogStage stage, PetscBool isVisible) 619 { 620 PetscStageLog stageLog; 621 PetscErrorCode ierr; 622 623 PetscFunctionBegin; 624 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 625 ierr = PetscStageLogSetVisible(stageLog, stage, isVisible);CHKERRQ(ierr); 626 PetscFunctionReturn(0); 627 } 628 629 #undef __FUNCT__ 630 #define __FUNCT__ "PetscLogStageGetVisible" 631 /*@ 632 PetscLogStageGetVisible - Returns stage visibility in PetscLogView() 633 634 Not Collective 635 636 Input Parameter: 637 . stage - The stage 638 639 Output Parameter: 640 . isVisible - The visibility flag, PETSC_TRUE to print, else PETSC_FALSE (defaults to PETSC_TRUE) 641 642 Level: intermediate 643 644 .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscLogView() 645 @*/ 646 PetscErrorCode PetscLogStageGetVisible(PetscLogStage stage, PetscBool *isVisible) 647 { 648 PetscStageLog stageLog; 649 PetscErrorCode ierr; 650 651 PetscFunctionBegin; 652 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 653 ierr = PetscStageLogGetVisible(stageLog, stage, isVisible);CHKERRQ(ierr); 654 PetscFunctionReturn(0); 655 } 656 657 #undef __FUNCT__ 658 #define __FUNCT__ "PetscLogStageGetId" 659 /*@C 660 PetscLogStageGetId - Returns the stage id when given the stage name. 661 662 Not Collective 663 664 Input Parameter: 665 . name - The stage name 666 667 Output Parameter: 668 . stage - The stage 669 670 Level: intermediate 671 672 .seealso: PetscLogStagePush(), PetscLogStagePop(), PetscPreLoadBegin(), PetscPreLoadEnd(), PetscPreLoadStage() 673 @*/ 674 PetscErrorCode PetscLogStageGetId(const char name[], PetscLogStage *stage) 675 { 676 PetscStageLog stageLog; 677 PetscErrorCode ierr; 678 679 PetscFunctionBegin; 680 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 681 ierr = PetscStageLogGetStage(stageLog, name, stage);CHKERRQ(ierr); 682 PetscFunctionReturn(0); 683 } 684 685 /*------------------------------------------------ Event Functions --------------------------------------------------*/ 686 #undef __FUNCT__ 687 #define __FUNCT__ "PetscLogEventRegister" 688 /*@C 689 PetscLogEventRegister - Registers an event name for logging operations in an application code. 690 691 Not Collective 692 693 Input Parameter: 694 + name - The name associated with the event 695 - classid - The classid associated to the class for this event, obtain either with 696 PetscClassIdRegister() or use a predefined one such as KSP_CLASSID, SNES_CLASSID, the predefined ones 697 are only available in C code 698 699 Output Parameter: 700 . event - The event id for use with PetscLogEventBegin() and PetscLogEventEnd(). 701 702 Example of Usage: 703 .vb 704 PetscLogEvent USER_EVENT; 705 PetscClassId classid; 706 PetscLogDouble user_event_flops; 707 PetscClassIdRegister("class name",&classid); 708 PetscLogEventRegister("User event name",classid,&USER_EVENT); 709 PetscLogEventBegin(USER_EVENT,0,0,0,0); 710 [code segment to monitor] 711 PetscLogFlops(user_event_flops); 712 PetscLogEventEnd(USER_EVENT,0,0,0,0); 713 .ve 714 715 Notes: 716 PETSc automatically logs library events if the code has been 717 compiled with -DPETSC_USE_LOG (which is the default) and -log, 718 -log_summary, or -log_all are specified. PetscLogEventRegister() is 719 intended for logging user events to supplement this PETSc 720 information. 721 722 PETSc can gather data for use with the utilities Upshot/Nupshot 723 (part of the MPICH distribution). If PETSc has been compiled 724 with flag -DPETSC_HAVE_MPE (MPE is an additional utility within 725 MPICH), the user can employ another command line option, -log_mpe, 726 to create a logfile, "mpe.log", which can be visualized 727 Upshot/Nupshot. 728 729 The classid is associated with each event so that classes of events 730 can be disabled simultaneously, such as all matrix events. The user 731 can either use an existing classid, such as MAT_CLASSID, or create 732 their own as shown in the example. 733 734 Level: intermediate 735 736 .keywords: log, event, register 737 .seealso: PetscLogEventBegin(), PetscLogEventEnd(), PetscLogFlops(), 738 PetscLogEventMPEActivate(), PetscLogEventMPEDeactivate(), 739 PetscLogEventActivate(), PetscLogEventDeactivate(), PetscClassIdRegister() 740 @*/ 741 PetscErrorCode PetscLogEventRegister(const char name[],PetscClassId classid,PetscLogEvent *event) 742 { 743 PetscStageLog stageLog; 744 int stage; 745 PetscErrorCode ierr; 746 747 PetscFunctionBegin; 748 *event = PETSC_DECIDE; 749 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 750 ierr = EventRegLogRegister(stageLog->eventLog, name, classid, event);CHKERRQ(ierr); 751 for (stage = 0; stage < stageLog->numStages; stage++) { 752 ierr = EventPerfLogEnsureSize(stageLog->stageInfo[stage].eventLog, stageLog->eventLog->numEvents);CHKERRQ(ierr); 753 ierr = ClassPerfLogEnsureSize(stageLog->stageInfo[stage].classLog, stageLog->classLog->numClasses);CHKERRQ(ierr); 754 } 755 PetscFunctionReturn(0); 756 } 757 758 #undef __FUNCT__ 759 #define __FUNCT__ "PetscLogEventActivate" 760 /*@ 761 PetscLogEventActivate - Indicates that a particular event should be logged. 762 763 Not Collective 764 765 Input Parameter: 766 . event - The event id 767 768 Usage: 769 .vb 770 PetscLogEventDeactivate(VEC_SetValues); 771 [code where you do not want to log VecSetValues()] 772 PetscLogEventActivate(VEC_SetValues); 773 [code where you do want to log VecSetValues()] 774 .ve 775 776 Note: 777 The event may be either a pre-defined PETSc event (found in include/petsclog.h) 778 or an event number obtained with PetscLogEventRegister(). 779 780 Level: advanced 781 782 .keywords: log, event, activate 783 .seealso: PetscLogEventMPEDeactivate(),PetscLogEventMPEActivate(),PlogEventDeactivate() 784 @*/ 785 PetscErrorCode PetscLogEventActivate(PetscLogEvent event) 786 { 787 PetscStageLog stageLog; 788 int stage; 789 PetscErrorCode ierr; 790 791 PetscFunctionBegin; 792 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 793 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 794 ierr = EventPerfLogActivate(stageLog->stageInfo[stage].eventLog, event);CHKERRQ(ierr); 795 PetscFunctionReturn(0); 796 } 797 798 #undef __FUNCT__ 799 #define __FUNCT__ "PetscLogEventDeactivate" 800 /*@ 801 PetscLogEventDeactivate - Indicates that a particular event should not be logged. 802 803 Not Collective 804 805 Input Parameter: 806 . event - The event id 807 808 Usage: 809 .vb 810 PetscLogEventDeactivate(VEC_SetValues); 811 [code where you do not want to log VecSetValues()] 812 PetscLogEventActivate(VEC_SetValues); 813 [code where you do want to log VecSetValues()] 814 .ve 815 816 Note: 817 The event may be either a pre-defined PETSc event (found in 818 include/petsclog.h) or an event number obtained with PetscLogEventRegister()). 819 820 Level: advanced 821 822 .keywords: log, event, deactivate 823 .seealso: PetscLogEventMPEDeactivate(),PetscLogEventMPEActivate(),PlogEventActivate() 824 @*/ 825 PetscErrorCode PetscLogEventDeactivate(PetscLogEvent event) 826 { 827 PetscStageLog stageLog; 828 int stage; 829 PetscErrorCode ierr; 830 831 PetscFunctionBegin; 832 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 833 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 834 ierr = EventPerfLogDeactivate(stageLog->stageInfo[stage].eventLog, event);CHKERRQ(ierr); 835 PetscFunctionReturn(0); 836 } 837 838 #undef __FUNCT__ 839 #define __FUNCT__ "PetscLogEventSetActiveAll" 840 /*@ 841 PetscLogEventSetActiveAll - Sets the event activity in every stage. 842 843 Not Collective 844 845 Input Parameters: 846 + event - The event id 847 - isActive - The activity flag determining whether the event is logged 848 849 Level: advanced 850 851 .keywords: log, event, activate 852 .seealso: PetscLogEventMPEDeactivate(),PetscLogEventMPEActivate(),PlogEventActivate(),PlogEventDeactivate() 853 @*/ 854 PetscErrorCode PetscLogEventSetActiveAll(PetscLogEvent event, PetscBool isActive) 855 { 856 PetscStageLog stageLog; 857 int stage; 858 PetscErrorCode ierr; 859 860 PetscFunctionBegin; 861 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 862 for (stage = 0; stage < stageLog->numStages; stage++) { 863 if (isActive) { 864 ierr = EventPerfLogActivate(stageLog->stageInfo[stage].eventLog, event);CHKERRQ(ierr); 865 } else { 866 ierr = EventPerfLogDeactivate(stageLog->stageInfo[stage].eventLog, event);CHKERRQ(ierr); 867 } 868 } 869 PetscFunctionReturn(0); 870 } 871 872 #undef __FUNCT__ 873 #define __FUNCT__ "PetscLogEventActivateClass" 874 /*@ 875 PetscLogEventActivateClass - Activates event logging for a PETSc object class. 876 877 Not Collective 878 879 Input Parameter: 880 . classid - The event class, for example MAT_CLASSID, SNES_CLASSID, etc. 881 882 Level: developer 883 884 .keywords: log, event, activate, class 885 .seealso: PetscInfoActivate(),PetscInfo(),PetscInfoAllow(),PetscLogEventDeactivateClass(), PetscLogEventActivate(),PetscLogEventDeactivate() 886 @*/ 887 PetscErrorCode PetscLogEventActivateClass(PetscClassId classid) 888 { 889 PetscStageLog stageLog; 890 int stage; 891 PetscErrorCode ierr; 892 893 PetscFunctionBegin; 894 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 895 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 896 ierr = EventPerfLogActivateClass(stageLog->stageInfo[stage].eventLog, stageLog->eventLog, classid);CHKERRQ(ierr); 897 PetscFunctionReturn(0); 898 } 899 900 #undef __FUNCT__ 901 #define __FUNCT__ "PetscLogEventDeactivateClass" 902 /*@ 903 PetscLogEventDeactivateClass - Deactivates event logging for a PETSc object class. 904 905 Not Collective 906 907 Input Parameter: 908 . classid - The event class, for example MAT_CLASSID, SNES_CLASSID, etc. 909 910 Level: developer 911 912 .keywords: log, event, deactivate, class 913 .seealso: PetscInfoActivate(),PetscInfo(),PetscInfoAllow(),PetscLogEventActivateClass(), PetscLogEventActivate(),PetscLogEventDeactivate() 914 @*/ 915 PetscErrorCode PetscLogEventDeactivateClass(PetscClassId classid) 916 { 917 PetscStageLog stageLog; 918 int stage; 919 PetscErrorCode ierr; 920 921 PetscFunctionBegin; 922 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 923 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 924 ierr = EventPerfLogDeactivateClass(stageLog->stageInfo[stage].eventLog, stageLog->eventLog, classid);CHKERRQ(ierr); 925 PetscFunctionReturn(0); 926 } 927 928 /*MC 929 PetscLogEventBegin - Logs the beginning of a user event. 930 931 Synopsis: 932 #include "petsclog.h" 933 PetscErrorCode PetscLogEventBegin(int e,PetscObject o1,PetscObject o2,PetscObject o3,PetscObject o4) 934 935 Not Collective 936 937 Input Parameters: 938 + e - integer associated with the event obtained from PetscLogEventRegister() 939 - o1,o2,o3,o4 - objects associated with the event, or 0 940 941 942 Fortran Synopsis: 943 void PetscLogEventBegin(int e,PetscErrorCode ierr) 944 945 Usage: 946 .vb 947 PetscLogEvent USER_EVENT; 948 PetscLogDouble user_event_flops; 949 PetscLogEventRegister("User event",0,&USER_EVENT); 950 PetscLogEventBegin(USER_EVENT,0,0,0,0); 951 [code segment to monitor] 952 PetscLogFlops(user_event_flops); 953 PetscLogEventEnd(USER_EVENT,0,0,0,0); 954 .ve 955 956 Notes: 957 You need to register each integer event with the command 958 PetscLogEventRegister(). The source code must be compiled with 959 -DPETSC_USE_LOG, which is the default. 960 961 PETSc automatically logs library events if the code has been 962 compiled with -DPETSC_USE_LOG, and -log, -log_summary, or -log_all are 963 specified. PetscLogEventBegin() is intended for logging user events 964 to supplement this PETSc information. 965 966 Level: intermediate 967 968 .seealso: PetscLogEventRegister(), PetscLogEventEnd(), PetscLogFlops() 969 970 .keywords: log, event, begin 971 M*/ 972 973 /*MC 974 PetscLogEventEnd - Log the end of a user event. 975 976 Synopsis: 977 #include "petsclog.h" 978 PetscErrorCode PetscLogEventEnd(int e,PetscObject o1,PetscObject o2,PetscObject o3,PetscObject o4) 979 980 Not Collective 981 982 Input Parameters: 983 + e - integer associated with the event obtained with PetscLogEventRegister() 984 - o1,o2,o3,o4 - objects associated with the event, or 0 985 986 987 Fortran Synopsis: 988 void PetscLogEventEnd(int e,PetscErrorCode ierr) 989 990 Usage: 991 .vb 992 PetscLogEvent USER_EVENT; 993 PetscLogDouble user_event_flops; 994 PetscLogEventRegister("User event",0,&USER_EVENT,); 995 PetscLogEventBegin(USER_EVENT,0,0,0,0); 996 [code segment to monitor] 997 PetscLogFlops(user_event_flops); 998 PetscLogEventEnd(USER_EVENT,0,0,0,0); 999 .ve 1000 1001 Notes: 1002 You should also register each additional integer event with the command 1003 PetscLogEventRegister(). Source code must be compiled with 1004 -DPETSC_USE_LOG, which is the default. 1005 1006 PETSc automatically logs library events if the code has been 1007 compiled with -DPETSC_USE_LOG, and -log, -log_summary, or -log_all are 1008 specified. PetscLogEventEnd() is intended for logging user events 1009 to supplement this PETSc information. 1010 1011 Level: intermediate 1012 1013 .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogFlops() 1014 1015 .keywords: log, event, end 1016 M*/ 1017 1018 /*MC 1019 PetscLogEventBarrierBegin - Logs the time in a barrier before an event. 1020 1021 Synopsis: 1022 #include "petsclog.h" 1023 PetscErrorCode PetscLogEventBarrierBegin(int e,PetscObject o1,PetscObject o2,PetscObject o3,PetscObject o4,MPI_Comm comm) 1024 1025 Not Collective 1026 1027 Input Parameters: 1028 . e - integer associated with the event obtained from PetscLogEventRegister() 1029 . o1,o2,o3,o4 - objects associated with the event, or 0 1030 . comm - communicator the barrier takes place over 1031 1032 1033 Usage: 1034 .vb 1035 PetscLogEventBarrierBegin(VEC_NormBarrier,0,0,0,0,comm); 1036 MPI_Allreduce() 1037 PetscLogEventBarrierEnd(VEC_NormBarrier,0,0,0,0,comm); 1038 .ve 1039 1040 Notes: 1041 This is for logging the amount of time spent in a barrier for an event 1042 that requires synchronization. 1043 1044 Additional Notes: 1045 Synchronization events always come in pairs; for example, VEC_NormBarrier and 1046 VEC_NormComm = VEC_NormBarrier + 1 1047 1048 Level: advanced 1049 1050 .seealso: PetscLogEventRegister(), PetscLogEventEnd(), PetscLogFlops(), PetscLogEventBegin(), 1051 PetscLogEventBarrierEnd() 1052 1053 .keywords: log, event, begin, barrier 1054 M*/ 1055 1056 /*MC 1057 PetscLogEventBarrierEnd - Logs the time in a barrier before an event. 1058 1059 Synopsis: 1060 #include "petsclog.h" 1061 PetscErrorCode PetscLogEventBarrierEnd(int e,PetscObject o1,PetscObject o2,PetscObject o3,PetscObject o4,MPI_Comm comm) 1062 1063 Logically Collective on MPI_Comm 1064 1065 Input Parameters: 1066 . e - integer associated with the event obtained from PetscLogEventRegister() 1067 . o1,o2,o3,o4 - objects associated with the event, or 0 1068 . comm - communicator the barrier takes place over 1069 1070 1071 Usage: 1072 .vb 1073 PetscLogEventBarrierBegin(VEC_NormBarrier,0,0,0,0,comm); 1074 MPI_Allreduce() 1075 PetscLogEventBarrierEnd(VEC_NormBarrier,0,0,0,0,comm); 1076 .ve 1077 1078 Notes: 1079 This is for logging the amount of time spent in a barrier for an event 1080 that requires synchronization. 1081 1082 Additional Notes: 1083 Synchronization events always come in pairs; for example, VEC_NormBarrier and 1084 VEC_NormComm = VEC_NormBarrier + 1 1085 1086 Level: advanced 1087 1088 .seealso: PetscLogEventRegister(), PetscLogEventEnd(), PetscLogFlops(), PetscLogEventBegin(), 1089 PetscLogEventBarrierBegin() 1090 1091 .keywords: log, event, begin, barrier 1092 M*/ 1093 1094 #undef __FUNCT__ 1095 #define __FUNCT__ "PetscLogEventGetId" 1096 /*@C 1097 PetscLogEventGetId - Returns the event id when given the event name. 1098 1099 Not Collective 1100 1101 Input Parameter: 1102 . name - The event name 1103 1104 Output Parameter: 1105 . event - The event 1106 1107 Level: intermediate 1108 1109 .seealso: PetscLogEventBegin(), PetscLogEventEnd(), PetscLogStageGetId() 1110 @*/ 1111 PetscErrorCode PetscLogEventGetId(const char name[], PetscLogEvent *event) 1112 { 1113 PetscStageLog stageLog; 1114 PetscErrorCode ierr; 1115 1116 PetscFunctionBegin; 1117 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 1118 ierr = EventRegLogGetEvent(stageLog->eventLog, name, event);CHKERRQ(ierr); 1119 PetscFunctionReturn(0); 1120 } 1121 1122 1123 /*------------------------------------------------ Output Functions -------------------------------------------------*/ 1124 #undef __FUNCT__ 1125 #define __FUNCT__ "PetscLogDump" 1126 /*@C 1127 PetscLogDump - Dumps logs of objects to a file. This file is intended to 1128 be read by bin/petscview. This program no longer exists. 1129 1130 Collective on PETSC_COMM_WORLD 1131 1132 Input Parameter: 1133 . name - an optional file name 1134 1135 Options Database Keys: 1136 + -log - Prints basic log information (for code compiled with PETSC_USE_LOG) 1137 - -log_all - Prints extensive log information (for code compiled with PETSC_USE_LOG) 1138 1139 Usage: 1140 .vb 1141 PetscInitialize(...); 1142 PetscLogBegin(); or PetscLogAllBegin(); 1143 ... code ... 1144 PetscLogDump(filename); 1145 PetscFinalize(); 1146 .ve 1147 1148 Notes: 1149 The default file name is 1150 $ Log.<rank> 1151 where <rank> is the processor number. If no name is specified, 1152 this file will be used. 1153 1154 Level: advanced 1155 1156 .keywords: log, dump 1157 .seealso: PetscLogBegin(), PetscLogAllBegin(), PetscLogView() 1158 @*/ 1159 PetscErrorCode PetscLogDump(const char sname[]) 1160 { 1161 PetscStageLog stageLog; 1162 PetscEventPerfInfo *eventInfo; 1163 FILE *fd; 1164 char file[PETSC_MAX_PATH_LEN], fname[PETSC_MAX_PATH_LEN]; 1165 PetscLogDouble flops, _TotalTime; 1166 PetscMPIInt rank; 1167 int action, object, curStage; 1168 PetscLogEvent event; 1169 PetscErrorCode ierr; 1170 1171 PetscFunctionBegin; 1172 /* Calculate the total elapsed time */ 1173 PetscTime(_TotalTime); 1174 _TotalTime -= petsc_BaseTime; 1175 /* Open log file */ 1176 ierr = MPI_Comm_rank(PETSC_COMM_WORLD, &rank);CHKERRQ(ierr); 1177 if (sname) sprintf(file, "%s.%d", sname, rank); 1178 else sprintf(file, "Log.%d", rank); 1179 ierr = PetscFixFilename(file, fname);CHKERRQ(ierr); 1180 ierr = PetscFOpen(PETSC_COMM_WORLD, fname, "w", &fd);CHKERRQ(ierr); 1181 if ((!rank) && (!fd)) SETERRQ1(PETSC_COMM_SELF,PETSC_ERR_FILE_OPEN, "Cannot open file: %s", fname); 1182 /* Output totals */ 1183 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "Total Flops %14e %16.8e\n", petsc_TotalFlops, _TotalTime);CHKERRQ(ierr); 1184 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "Clock Resolution %g\n", 0.0);CHKERRQ(ierr); 1185 /* Output actions */ 1186 if (petsc_logActions) { 1187 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "Actions accomplished %d\n", petsc_numActions);CHKERRQ(ierr); 1188 for (action = 0; action < petsc_numActions; action++) { 1189 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "%g %d %d %d %d %d %d %g %g %g\n", 1190 petsc_actions[action].time, petsc_actions[action].action, (int)petsc_actions[action].event, (int)petsc_actions[action].classid, petsc_actions[action].id1, 1191 petsc_actions[action].id2, petsc_actions[action].id3, petsc_actions[action].flops, petsc_actions[action].mem, petsc_actions[action].maxmem);CHKERRQ(ierr); 1192 } 1193 } 1194 /* Output objects */ 1195 if (petsc_logObjects) { 1196 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "Objects created %d destroyed %d\n", petsc_numObjects, petsc_numObjectsDestroyed);CHKERRQ(ierr); 1197 for (object = 0; object < petsc_numObjects; object++) { 1198 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "Parent ID: %d Memory: %d\n", petsc_objects[object].parent, (int) petsc_objects[object].mem);CHKERRQ(ierr); 1199 if (!petsc_objects[object].name[0]) { 1200 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd,"No Name\n");CHKERRQ(ierr); 1201 } else { 1202 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "Name: %s\n", petsc_objects[object].name);CHKERRQ(ierr); 1203 } 1204 if (petsc_objects[object].info[0] != 0) { 1205 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "No Info\n");CHKERRQ(ierr); 1206 } else { 1207 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "Info: %s\n", petsc_objects[object].info);CHKERRQ(ierr); 1208 } 1209 } 1210 } 1211 /* Output events */ 1212 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "Event log:\n");CHKERRQ(ierr); 1213 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 1214 ierr = PetscIntStackTop(stageLog->stack, &curStage);CHKERRQ(ierr); 1215 eventInfo = stageLog->stageInfo[curStage].eventLog->eventInfo; 1216 for (event = 0; event < stageLog->stageInfo[curStage].eventLog->numEvents; event++) { 1217 if (eventInfo[event].time != 0.0) flops = eventInfo[event].flops/eventInfo[event].time; 1218 else flops = 0.0; 1219 ierr = PetscFPrintf(PETSC_COMM_WORLD, fd, "%d %16d %16g %16g %16g\n", event, eventInfo[event].count, 1220 eventInfo[event].flops, eventInfo[event].time, flops);CHKERRQ(ierr); 1221 } 1222 ierr = PetscFClose(PETSC_COMM_WORLD, fd);CHKERRQ(ierr); 1223 PetscFunctionReturn(0); 1224 } 1225 1226 #undef __FUNCT__ 1227 #define __FUNCT__ "PetscLogView" 1228 /*@C 1229 PetscLogViewer - Prints a summary of the logging. 1230 1231 Collective over MPI_Comm 1232 1233 Input Parameter: 1234 . viewer - an ASCII viewer 1235 1236 Options Database Keys: 1237 . -log_summary - Prints summary of log information (for code compiled with PETSC_USE_LOG) 1238 1239 Usage: 1240 .vb 1241 PetscInitialize(...); 1242 PetscLogBegin(); 1243 ... code ... 1244 PetscLogView(PetscViewer); 1245 PetscFinalize(...); 1246 .ve 1247 1248 Notes: 1249 By default the summary is printed to stdout. 1250 1251 Level: beginner 1252 1253 .keywords: log, dump, print 1254 .seealso: PetscLogBegin(), PetscLogDump() 1255 @*/ 1256 PetscErrorCode PetscLogView(PetscViewer viewer) 1257 { 1258 FILE *fd; 1259 PetscLogDouble zero = 0.0; 1260 PetscStageLog stageLog; 1261 PetscStageInfo *stageInfo = PETSC_NULL; 1262 PetscEventPerfInfo *eventInfo = PETSC_NULL; 1263 PetscClassPerfInfo *classInfo; 1264 char arch[128],hostname[128],username[128],pname[PETSC_MAX_PATH_LEN],date[128]; 1265 const char *name; 1266 PetscLogDouble locTotalTime, TotalTime, TotalFlops; 1267 PetscLogDouble numMessages, messageLength, avgMessLen, numReductions; 1268 PetscLogDouble stageTime, flops, flopr, mem, mess, messLen, red; 1269 PetscLogDouble fracTime, fracFlops, fracMessages, fracLength, fracReductions, fracMess, fracMessLen, fracRed; 1270 PetscLogDouble fracStageTime, fracStageFlops, fracStageMess, fracStageMessLen, fracStageRed; 1271 PetscLogDouble min, max, tot, ratio, avg, x, y; 1272 PetscLogDouble minf, maxf, totf, ratf, mint, maxt, tott, ratt, ratCt, totm, totml, totr; 1273 PetscMPIInt minCt, maxCt; 1274 PetscMPIInt size, rank; 1275 PetscBool *localStageUsed, *stageUsed; 1276 PetscBool *localStageVisible, *stageVisible; 1277 int numStages, localNumEvents, numEvents; 1278 int stage, lastStage, oclass; 1279 PetscLogEvent event; 1280 PetscErrorCode ierr; 1281 char version[256]; 1282 MPI_Comm comm; 1283 PetscInt nthreads; 1284 1285 PetscFunctionBegin; 1286 ierr = PetscObjectGetComm((PetscObject)viewer,&comm);CHKERRQ(ierr); 1287 if (!PetscLogBegin_PrivateCalled) SETERRQ(comm, PETSC_ERR_ORDER, "No call to PetscLogBegin() before PetscLogView()"); 1288 ierr = PetscViewerASCIIGetPointer(viewer,&fd);CHKERRQ(ierr); 1289 ierr = MPI_Comm_size(comm, &size);CHKERRQ(ierr); 1290 ierr = MPI_Comm_rank(comm, &rank);CHKERRQ(ierr); 1291 /* Pop off any stages the user forgot to remove */ 1292 lastStage = 0; 1293 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 1294 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 1295 while (stage >= 0) { 1296 lastStage = stage; 1297 ierr = PetscStageLogPop(stageLog);CHKERRQ(ierr); 1298 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 1299 } 1300 /* Get the total elapsed time */ 1301 PetscTime(locTotalTime); locTotalTime -= petsc_BaseTime; 1302 1303 ierr = PetscFPrintf(comm, fd, "************************************************************************************************************************\n");CHKERRQ(ierr); 1304 ierr = PetscFPrintf(comm, fd, "*** WIDEN YOUR WINDOW TO 120 CHARACTERS. Use 'enscript -r -fCourier9' to print this document ***\n");CHKERRQ(ierr); 1305 ierr = PetscFPrintf(comm, fd, "************************************************************************************************************************\n");CHKERRQ(ierr); 1306 ierr = PetscFPrintf(comm, fd, "\n---------------------------------------------- PETSc Performance Summary: ----------------------------------------------\n\n");CHKERRQ(ierr); 1307 ierr = PetscGetArchType(arch,sizeof(arch));CHKERRQ(ierr); 1308 ierr = PetscGetHostName(hostname,sizeof(hostname));CHKERRQ(ierr); 1309 ierr = PetscGetUserName(username,sizeof(username));CHKERRQ(ierr); 1310 ierr = PetscGetProgramName(pname,sizeof(pname));CHKERRQ(ierr); 1311 ierr = PetscGetDate(date,sizeof(date));CHKERRQ(ierr); 1312 ierr = PetscGetVersion(version,sizeof(version));CHKERRQ(ierr); 1313 if (size == 1) { 1314 ierr = PetscFPrintf(comm,fd,"%s on a %s named %s with %d processor, by %s %s\n", pname, arch, hostname, size, username, date);CHKERRQ(ierr); 1315 } else { 1316 ierr = PetscFPrintf(comm,fd,"%s on a %s named %s with %d processors, by %s %s\n", pname, arch, hostname, size, username, date);CHKERRQ(ierr); 1317 } 1318 ierr = PetscThreadCommGetNThreads(PETSC_COMM_WORLD,&nthreads);CHKERRQ(ierr); 1319 if (nthreads > 1) { 1320 ierr = PetscFPrintf(comm,fd,"With %d threads per MPI_Comm\n", (int)nthreads);CHKERRQ(ierr); 1321 } 1322 1323 ierr = PetscFPrintf(comm, fd, "Using %s\n", version);CHKERRQ(ierr); 1324 1325 /* Must preserve reduction count before we go on */ 1326 red = petsc_allreduce_ct + petsc_gather_ct + petsc_scatter_ct; 1327 1328 /* Calculate summary information */ 1329 ierr = PetscFPrintf(comm, fd, "\n Max Max/Min Avg Total \n");CHKERRQ(ierr); 1330 /* Time */ 1331 ierr = MPI_Allreduce(&locTotalTime, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1332 ierr = MPI_Allreduce(&locTotalTime, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1333 ierr = MPI_Allreduce(&locTotalTime, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1334 avg = (tot)/((PetscLogDouble) size); 1335 if (min != 0.0) ratio = max/min; 1336 else ratio = 0.0; 1337 ierr = PetscFPrintf(comm, fd, "Time (sec): %5.3e %10.5f %5.3e\n", max, ratio, avg);CHKERRQ(ierr); 1338 TotalTime = tot; 1339 /* Objects */ 1340 avg = (PetscLogDouble) petsc_numObjects; 1341 ierr = MPI_Allreduce(&avg, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1342 ierr = MPI_Allreduce(&avg, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1343 ierr = MPI_Allreduce(&avg, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1344 avg = (tot)/((PetscLogDouble) size); 1345 if (min != 0.0) ratio = max/min; 1346 else ratio = 0.0; 1347 ierr = PetscFPrintf(comm, fd, "Objects: %5.3e %10.5f %5.3e\n", max, ratio, avg);CHKERRQ(ierr); 1348 /* Flops */ 1349 ierr = MPI_Allreduce(&petsc_TotalFlops, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1350 ierr = MPI_Allreduce(&petsc_TotalFlops, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1351 ierr = MPI_Allreduce(&petsc_TotalFlops, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1352 avg = (tot)/((PetscLogDouble) size); 1353 if (min != 0.0) ratio = max/min; 1354 else ratio = 0.0; 1355 ierr = PetscFPrintf(comm, fd, "Flops: %5.3e %10.5f %5.3e %5.3e\n", max, ratio, avg, tot);CHKERRQ(ierr); 1356 TotalFlops = tot; 1357 /* Flops/sec -- Must talk to Barry here */ 1358 if (locTotalTime != 0.0) flops = petsc_TotalFlops/locTotalTime; 1359 else flops = 0.0; 1360 ierr = MPI_Allreduce(&flops, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1361 ierr = MPI_Allreduce(&flops, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1362 ierr = MPI_Allreduce(&flops, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1363 avg = (tot)/((PetscLogDouble) size); 1364 if (min != 0.0) ratio = max/min; 1365 else ratio = 0.0; 1366 ierr = PetscFPrintf(comm, fd, "Flops/sec: %5.3e %10.5f %5.3e %5.3e\n", max, ratio, avg, tot);CHKERRQ(ierr); 1367 /* Memory */ 1368 ierr = PetscMallocGetMaximumUsage(&mem);CHKERRQ(ierr); 1369 if (mem > 0.0) { 1370 ierr = MPI_Allreduce(&mem, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1371 ierr = MPI_Allreduce(&mem, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1372 ierr = MPI_Allreduce(&mem, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1373 avg = (tot)/((PetscLogDouble) size); 1374 if (min != 0.0) ratio = max/min; 1375 else ratio = 0.0; 1376 ierr = PetscFPrintf(comm, fd, "Memory: %5.3e %10.5f %5.3e\n", max, ratio, tot);CHKERRQ(ierr); 1377 } 1378 /* Messages */ 1379 mess = 0.5*(petsc_irecv_ct + petsc_isend_ct + petsc_recv_ct + petsc_send_ct); 1380 ierr = MPI_Allreduce(&mess, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1381 ierr = MPI_Allreduce(&mess, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1382 ierr = MPI_Allreduce(&mess, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1383 avg = (tot)/((PetscLogDouble) size); 1384 if (min != 0.0) ratio = max/min; 1385 else ratio = 0.0; 1386 ierr = PetscFPrintf(comm, fd, "MPI Messages: %5.3e %10.5f %5.3e %5.3e\n", max, ratio, avg, tot);CHKERRQ(ierr); 1387 numMessages = tot; 1388 /* Message Lengths */ 1389 mess = 0.5*(petsc_irecv_len + petsc_isend_len + petsc_recv_len + petsc_send_len); 1390 ierr = MPI_Allreduce(&mess, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1391 ierr = MPI_Allreduce(&mess, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1392 ierr = MPI_Allreduce(&mess, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1393 if (numMessages != 0) avg = (tot)/(numMessages); 1394 else avg = 0.0; 1395 if (min != 0.0) ratio = max/min; 1396 else ratio = 0.0; 1397 ierr = PetscFPrintf(comm, fd, "MPI Message Lengths: %5.3e %10.5f %5.3e %5.3e\n", max, ratio, avg, tot);CHKERRQ(ierr); 1398 messageLength = tot; 1399 /* Reductions */ 1400 ierr = MPI_Allreduce(&red, &min, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1401 ierr = MPI_Allreduce(&red, &max, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1402 ierr = MPI_Allreduce(&red, &tot, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1403 if (min != 0.0) ratio = max/min; 1404 else ratio = 0.0; 1405 ierr = PetscFPrintf(comm, fd, "MPI Reductions: %5.3e %10.5f\n", max, ratio);CHKERRQ(ierr); 1406 numReductions = red; /* wrong because uses count from process zero */ 1407 ierr = PetscFPrintf(comm, fd, "\nFlop counting convention: 1 flop = 1 real number operation of type (multiply/divide/add/subtract)\n");CHKERRQ(ierr); 1408 ierr = PetscFPrintf(comm, fd, " e.g., VecAXPY() for real vectors of length N --> 2N flops\n");CHKERRQ(ierr); 1409 ierr = PetscFPrintf(comm, fd, " and VecAXPY() for complex vectors of length N --> 8N flops\n");CHKERRQ(ierr); 1410 1411 /* Get total number of stages -- 1412 Currently, a single processor can register more stages than another, but stages must all be registered in order. 1413 We can removed this requirement if necessary by having a global stage numbering and indirection on the stage ID. 1414 This seems best accomplished by assoicating a communicator with each stage. 1415 */ 1416 ierr = MPI_Allreduce(&stageLog->numStages, &numStages, 1, MPI_INT, MPI_MAX, comm);CHKERRQ(ierr); 1417 ierr = PetscMalloc(numStages * sizeof(PetscBool), &localStageUsed);CHKERRQ(ierr); 1418 ierr = PetscMalloc(numStages * sizeof(PetscBool), &stageUsed);CHKERRQ(ierr); 1419 ierr = PetscMalloc(numStages * sizeof(PetscBool), &localStageVisible);CHKERRQ(ierr); 1420 ierr = PetscMalloc(numStages * sizeof(PetscBool), &stageVisible);CHKERRQ(ierr); 1421 if (numStages > 0) { 1422 stageInfo = stageLog->stageInfo; 1423 for (stage = 0; stage < numStages; stage++) { 1424 if (stage < stageLog->numStages) { 1425 localStageUsed[stage] = stageInfo[stage].used; 1426 localStageVisible[stage] = stageInfo[stage].perfInfo.visible; 1427 } else { 1428 localStageUsed[stage] = PETSC_FALSE; 1429 localStageVisible[stage] = PETSC_TRUE; 1430 } 1431 } 1432 ierr = MPI_Allreduce(localStageUsed, stageUsed, numStages, MPIU_BOOL, MPI_LOR, comm);CHKERRQ(ierr); 1433 ierr = MPI_Allreduce(localStageVisible, stageVisible, numStages, MPIU_BOOL, MPI_LAND, comm);CHKERRQ(ierr); 1434 for (stage = 0; stage < numStages; stage++) { 1435 if (stageUsed[stage]) { 1436 ierr = PetscFPrintf(comm, fd, "\nSummary of Stages: ----- Time ------ ----- Flops ----- --- Messages --- -- Message Lengths -- -- Reductions --\n");CHKERRQ(ierr); 1437 ierr = PetscFPrintf(comm, fd, " Avg %%Total Avg %%Total counts %%Total Avg %%Total counts %%Total \n");CHKERRQ(ierr); 1438 break; 1439 } 1440 } 1441 for (stage = 0; stage < numStages; stage++) { 1442 if (!stageUsed[stage]) continue; 1443 if (localStageUsed[stage]) { 1444 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.time, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1445 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.flops, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1446 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numMessages, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1447 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.messageLength, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1448 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numReductions, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1449 name = stageInfo[stage].name; 1450 } else { 1451 ierr = MPI_Allreduce(&zero, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1452 ierr = MPI_Allreduce(&zero, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1453 ierr = MPI_Allreduce(&zero, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1454 ierr = MPI_Allreduce(&zero, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1455 ierr = MPI_Allreduce(&zero, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1456 name = ""; 1457 } 1458 mess *= 0.5; messLen *= 0.5; red /= size; 1459 if (TotalTime != 0.0) fracTime = stageTime/TotalTime; else fracTime = 0.0; 1460 if (TotalFlops != 0.0) fracFlops = flops/TotalFlops; else fracFlops = 0.0; 1461 /* Talk to Barry if (stageTime != 0.0) flops = (size*flops)/stageTime; else flops = 0.0; */ 1462 if (numMessages != 0.0) fracMessages = mess/numMessages; else fracMessages = 0.0; 1463 if (numMessages != 0.0) avgMessLen = messLen/numMessages; else avgMessLen = 0.0; 1464 if (messageLength != 0.0) fracLength = messLen/messageLength; else fracLength = 0.0; 1465 if (numReductions != 0.0) fracReductions = red/numReductions; else fracReductions = 0.0; 1466 ierr = 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", 1467 stage, name, stageTime/size, 100.0*fracTime, flops, 100.0*fracFlops, 1468 mess, 100.0*fracMessages, avgMessLen, 100.0*fracLength, red, 100.0*fracReductions);CHKERRQ(ierr); 1469 } 1470 } 1471 1472 ierr = PetscFPrintf(comm, fd,"\n------------------------------------------------------------------------------------------------------------------------\n");CHKERRQ(ierr); 1473 ierr = PetscFPrintf(comm, fd, "See the 'Profiling' chapter of the users' manual for details on interpreting output.\n");CHKERRQ(ierr); 1474 ierr = PetscFPrintf(comm, fd, "Phase summary info:\n");CHKERRQ(ierr); 1475 ierr = PetscFPrintf(comm, fd, " Count: number of times phase was executed\n");CHKERRQ(ierr); 1476 ierr = PetscFPrintf(comm, fd, " Time and Flops: Max - maximum over all processors\n");CHKERRQ(ierr); 1477 ierr = PetscFPrintf(comm, fd, " Ratio - ratio of maximum to minimum over all processors\n");CHKERRQ(ierr); 1478 ierr = PetscFPrintf(comm, fd, " Mess: number of messages sent\n");CHKERRQ(ierr); 1479 ierr = PetscFPrintf(comm, fd, " Avg. len: average message length (bytes)\n");CHKERRQ(ierr); 1480 ierr = PetscFPrintf(comm, fd, " Reduct: number of global reductions\n");CHKERRQ(ierr); 1481 ierr = PetscFPrintf(comm, fd, " Global: entire computation\n");CHKERRQ(ierr); 1482 ierr = PetscFPrintf(comm, fd, " Stage: stages of a computation. Set stages with PetscLogStagePush() and PetscLogStagePop().\n");CHKERRQ(ierr); 1483 ierr = PetscFPrintf(comm, fd, " %%T - percent time in this phase %%F - percent flops in this phase\n");CHKERRQ(ierr); 1484 ierr = PetscFPrintf(comm, fd, " %%M - percent messages in this phase %%L - percent message lengths in this phase\n");CHKERRQ(ierr); 1485 ierr = PetscFPrintf(comm, fd, " %%R - percent reductions in this phase\n");CHKERRQ(ierr); 1486 ierr = PetscFPrintf(comm, fd, " Total Mflop/s: 10e-6 * (sum of flops over all processors)/(max time over all processors)\n");CHKERRQ(ierr); 1487 ierr = PetscFPrintf(comm, fd, "------------------------------------------------------------------------------------------------------------------------\n");CHKERRQ(ierr); 1488 1489 #if defined(PETSC_USE_DEBUG) 1490 ierr = PetscFPrintf(comm, fd, "\n\n");CHKERRQ(ierr); 1491 ierr = PetscFPrintf(comm, fd, " ##########################################################\n");CHKERRQ(ierr); 1492 ierr = PetscFPrintf(comm, fd, " # #\n");CHKERRQ(ierr); 1493 ierr = PetscFPrintf(comm, fd, " # WARNING!!! #\n");CHKERRQ(ierr); 1494 ierr = PetscFPrintf(comm, fd, " # #\n");CHKERRQ(ierr); 1495 ierr = PetscFPrintf(comm, fd, " # This code was compiled with a debugging option, #\n");CHKERRQ(ierr); 1496 ierr = PetscFPrintf(comm, fd, " # To get timing results run ./configure #\n");CHKERRQ(ierr); 1497 ierr = PetscFPrintf(comm, fd, " # using --with-debugging=no, the performance will #\n");CHKERRQ(ierr); 1498 ierr = PetscFPrintf(comm, fd, " # be generally two or three times faster. #\n");CHKERRQ(ierr); 1499 ierr = PetscFPrintf(comm, fd, " # #\n");CHKERRQ(ierr); 1500 ierr = PetscFPrintf(comm, fd, " ##########################################################\n\n\n");CHKERRQ(ierr); 1501 #endif 1502 #if defined(PETSC_USE_COMPLEX) && !defined(PETSC_USE_FORTRAN_KERNELS) 1503 ierr = PetscFPrintf(comm, fd, "\n\n");CHKERRQ(ierr); 1504 ierr = PetscFPrintf(comm, fd, " ##########################################################\n");CHKERRQ(ierr); 1505 ierr = PetscFPrintf(comm, fd, " # #\n");CHKERRQ(ierr); 1506 ierr = PetscFPrintf(comm, fd, " # WARNING!!! #\n");CHKERRQ(ierr); 1507 ierr = PetscFPrintf(comm, fd, " # #\n");CHKERRQ(ierr); 1508 ierr = PetscFPrintf(comm, fd, " # The code for various complex numbers numerical #\n");CHKERRQ(ierr); 1509 ierr = PetscFPrintf(comm, fd, " # kernels uses C++, which generally is not well #\n");CHKERRQ(ierr); 1510 ierr = PetscFPrintf(comm, fd, " # optimized. For performance that is about 4-5 times #\n");CHKERRQ(ierr); 1511 ierr = PetscFPrintf(comm, fd, " # faster, specify --with-fortran-kernels=1 #\n");CHKERRQ(ierr); 1512 ierr = PetscFPrintf(comm, fd, " # when running ./configure.py. #\n");CHKERRQ(ierr); 1513 ierr = PetscFPrintf(comm, fd, " # #\n");CHKERRQ(ierr); 1514 ierr = PetscFPrintf(comm, fd, " ##########################################################\n\n\n");CHKERRQ(ierr); 1515 #endif 1516 1517 /* Report events */ 1518 ierr = PetscFPrintf(comm, fd,"Event Count Time (sec) Flops --- Global --- --- Stage --- Total\n");CHKERRQ(ierr); 1519 ierr = 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");CHKERRQ(ierr); 1520 ierr = PetscFPrintf(comm,fd,"------------------------------------------------------------------------------------------------------------------------\n");CHKERRQ(ierr); 1521 1522 /* Problem: The stage name will not show up unless the stage executed on proc 1 */ 1523 for (stage = 0; stage < numStages; stage++) { 1524 if (!stageVisible[stage]) continue; 1525 if (localStageUsed[stage]) { 1526 ierr = PetscFPrintf(comm, fd, "\n--- Event Stage %d: %s\n\n", stage, stageInfo[stage].name);CHKERRQ(ierr); 1527 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.time, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1528 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.flops, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1529 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numMessages, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1530 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.messageLength, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1531 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numReductions, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1532 } else { 1533 ierr = PetscFPrintf(comm, fd, "\n--- Event Stage %d: Unknown\n\n", stage);CHKERRQ(ierr); 1534 ierr = MPI_Allreduce(&zero, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1535 ierr = MPI_Allreduce(&zero, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1536 ierr = MPI_Allreduce(&zero, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1537 ierr = MPI_Allreduce(&zero, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1538 ierr = MPI_Allreduce(&zero, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1539 } 1540 mess *= 0.5; messLen *= 0.5; red /= size; 1541 1542 /* Get total number of events in this stage -- 1543 Currently, a single processor can register more events than another, but events must all be registered in order, 1544 just like stages. We can removed this requirement if necessary by having a global event numbering and indirection 1545 on the event ID. This seems best accomplished by assoicating a communicator with each stage. 1546 1547 Problem: If the event did not happen on proc 1, its name will not be available. 1548 Problem: Event visibility is not implemented 1549 */ 1550 if (localStageUsed[stage]) { 1551 eventInfo = stageLog->stageInfo[stage].eventLog->eventInfo; 1552 localNumEvents = stageLog->stageInfo[stage].eventLog->numEvents; 1553 } else localNumEvents = 0; 1554 ierr = MPI_Allreduce(&localNumEvents, &numEvents, 1, MPI_INT, MPI_MAX, comm);CHKERRQ(ierr); 1555 for (event = 0; event < numEvents; event++) { 1556 if (localStageUsed[stage] && (event < stageLog->stageInfo[stage].eventLog->numEvents) && (eventInfo[event].depth == 0)) { 1557 if ((eventInfo[event].count > 0) && (eventInfo[event].time > 0.0)) flopr = eventInfo[event].flops; 1558 else flopr = 0.0; 1559 1560 ierr = MPI_Allreduce(&flopr, &minf, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1561 ierr = MPI_Allreduce(&flopr, &maxf, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1562 ierr = MPI_Allreduce(&eventInfo[event].flops, &totf, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1563 ierr = MPI_Allreduce(&eventInfo[event].time, &mint, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1564 ierr = MPI_Allreduce(&eventInfo[event].time, &maxt, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1565 ierr = MPI_Allreduce(&eventInfo[event].time, &tott, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1566 ierr = MPI_Allreduce(&eventInfo[event].numMessages, &totm, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1567 ierr = MPI_Allreduce(&eventInfo[event].messageLength, &totml, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1568 ierr = MPI_Allreduce(&eventInfo[event].numReductions, &totr, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1569 ierr = MPI_Allreduce(&eventInfo[event].count, &minCt, 1, MPI_INT, MPI_MIN, comm);CHKERRQ(ierr); 1570 ierr = MPI_Allreduce(&eventInfo[event].count, &maxCt, 1, MPI_INT, MPI_MAX, comm);CHKERRQ(ierr); 1571 name = stageLog->eventLog->eventInfo[event].name; 1572 } else { 1573 flopr = 0.0; 1574 ierr = MPI_Allreduce(&flopr, &minf, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1575 ierr = MPI_Allreduce(&flopr, &maxf, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1576 ierr = MPI_Allreduce(&zero, &totf, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1577 ierr = MPI_Allreduce(&zero, &mint, 1, MPIU_PETSCLOGDOUBLE, MPI_MIN, comm);CHKERRQ(ierr); 1578 ierr = MPI_Allreduce(&zero, &maxt, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, comm);CHKERRQ(ierr); 1579 ierr = MPI_Allreduce(&zero, &tott, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1580 ierr = MPI_Allreduce(&zero, &totm, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1581 ierr = MPI_Allreduce(&zero, &totml, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1582 ierr = MPI_Allreduce(&zero, &totr, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 1583 ierr = MPI_Allreduce(&ierr, &minCt, 1, MPI_INT, MPI_MIN, comm);CHKERRQ(ierr); 1584 ierr = MPI_Allreduce(&ierr, &maxCt, 1, MPI_INT, MPI_MAX, comm);CHKERRQ(ierr); 1585 name = ""; 1586 } 1587 if (mint < 0.0) { 1588 ierr = 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); 1589 mint = 0; 1590 } 1591 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); 1592 totm *= 0.5; totml *= 0.5; totr /= size; 1593 1594 if (maxCt != 0) { 1595 if (minCt != 0) ratCt = ((PetscLogDouble) maxCt)/minCt; else ratCt = 0.0; 1596 if (mint != 0.0) ratt = maxt/mint; else ratt = 0.0; 1597 if (minf != 0.0) ratf = maxf/minf; else ratf = 0.0; 1598 if (TotalTime != 0.0) fracTime = tott/TotalTime; else fracTime = 0.0; 1599 if (TotalFlops != 0.0) fracFlops = totf/TotalFlops; else fracFlops = 0.0; 1600 if (stageTime != 0.0) fracStageTime = tott/stageTime; else fracStageTime = 0.0; 1601 if (flops != 0.0) fracStageFlops = totf/flops; else fracStageFlops = 0.0; 1602 if (numMessages != 0.0) fracMess = totm/numMessages; else fracMess = 0.0; 1603 if (messageLength != 0.0) fracMessLen = totml/messageLength; else fracMessLen = 0.0; 1604 if (numReductions != 0.0) fracRed = totr/numReductions; else fracRed = 0.0; 1605 if (mess != 0.0) fracStageMess = totm/mess; else fracStageMess = 0.0; 1606 if (messLen != 0.0) fracStageMessLen = totml/messLen; else fracStageMessLen = 0.0; 1607 if (red != 0.0) fracStageRed = totr/red; else fracStageRed = 0.0; 1608 if (totm != 0.0) totml /= totm; else totml = 0.0; 1609 if (maxt != 0.0) flopr = totf/maxt; else flopr = 0.0; 1610 if (fracStageTime > 1.00) ierr = PetscFPrintf(comm, fd,"Warning -- total time of even greater than time of entire stage -- something is wrong with the timer\n");CHKERRQ(ierr); 1611 ierr = PetscFPrintf(comm, fd, 1612 "%-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", 1613 name, maxCt, ratCt, maxt, ratt, maxf, ratf, totm, totml, totr, 1614 100.0*fracTime, 100.0*fracFlops, 100.0*fracMess, 100.0*fracMessLen, 100.0*fracRed, 1615 100.0*fracStageTime, 100.0*fracStageFlops, 100.0*fracStageMess, 100.0*fracStageMessLen, 100.0*fracStageRed, 1616 PetscAbsReal(flopr/1.0e6));CHKERRQ(ierr); 1617 } 1618 } 1619 } 1620 1621 /* Memory usage and object creation */ 1622 ierr = PetscFPrintf(comm, fd, "------------------------------------------------------------------------------------------------------------------------\n");CHKERRQ(ierr); 1623 ierr = PetscFPrintf(comm, fd, "\n");CHKERRQ(ierr); 1624 ierr = PetscFPrintf(comm, fd, "Memory usage is given in bytes:\n\n");CHKERRQ(ierr); 1625 1626 /* Right now, only stages on the first processor are reported here, meaning only objects associated with 1627 the global communicator, or MPI_COMM_SELF for proc 1. We really should report global stats and then 1628 stats for stages local to processor sets. 1629 */ 1630 /* We should figure out the longest object name here (now 20 characters) */ 1631 ierr = PetscFPrintf(comm, fd, "Object Type Creations Destructions Memory Descendants' Mem.\n");CHKERRQ(ierr); 1632 ierr = PetscFPrintf(comm, fd, "Reports information only for process 0.\n");CHKERRQ(ierr); 1633 for (stage = 0; stage < numStages; stage++) { 1634 if (localStageUsed[stage]) { 1635 classInfo = stageLog->stageInfo[stage].classLog->classInfo; 1636 ierr = PetscFPrintf(comm, fd, "\n--- Event Stage %d: %s\n\n", stage, stageInfo[stage].name);CHKERRQ(ierr); 1637 for (oclass = 0; oclass < stageLog->stageInfo[stage].classLog->numClasses; oclass++) { 1638 if ((classInfo[oclass].creations > 0) || (classInfo[oclass].destructions > 0)) { 1639 ierr = PetscFPrintf(comm, fd, "%20s %5d %5d %11.0f %g\n", stageLog->classLog->classInfo[oclass].name, 1640 classInfo[oclass].creations, classInfo[oclass].destructions, classInfo[oclass].mem, 1641 classInfo[oclass].descMem);CHKERRQ(ierr); 1642 } 1643 } 1644 } else { 1645 ierr = PetscFPrintf(comm, fd, "\n--- Event Stage %d: Unknown\n\n", stage);CHKERRQ(ierr); 1646 } 1647 } 1648 1649 ierr = PetscFree(localStageUsed);CHKERRQ(ierr); 1650 ierr = PetscFree(stageUsed);CHKERRQ(ierr); 1651 ierr = PetscFree(localStageVisible);CHKERRQ(ierr); 1652 ierr = PetscFree(stageVisible);CHKERRQ(ierr); 1653 1654 /* Information unrelated to this particular run */ 1655 ierr = PetscFPrintf(comm, fd, "========================================================================================================================\n");CHKERRQ(ierr); 1656 PetscTime(y); 1657 PetscTime(x); 1658 PetscTime(y); PetscTime(y); PetscTime(y); PetscTime(y); PetscTime(y); 1659 PetscTime(y); PetscTime(y); PetscTime(y); PetscTime(y); PetscTime(y); 1660 ierr = PetscFPrintf(comm,fd,"Average time to get PetscTime(): %g\n", (y-x)/10.0);CHKERRQ(ierr); 1661 /* MPI information */ 1662 if (size > 1) { 1663 MPI_Status status; 1664 PetscMPIInt tag; 1665 MPI_Comm newcomm; 1666 1667 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 1668 PetscTime(x); 1669 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 1670 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 1671 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 1672 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 1673 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 1674 PetscTime(y); 1675 ierr = PetscFPrintf(comm, fd, "Average time for MPI_Barrier(): %g\n", (y-x)/5.0);CHKERRQ(ierr); 1676 ierr = PetscCommDuplicate(comm,&newcomm, &tag);CHKERRQ(ierr); 1677 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 1678 if (rank) { 1679 ierr = MPI_Recv(0, 0, MPI_INT, rank-1, tag, newcomm, &status);CHKERRQ(ierr); 1680 ierr = MPI_Send(0, 0, MPI_INT, (rank+1)%size, tag, newcomm);CHKERRQ(ierr); 1681 } else { 1682 PetscTime(x); 1683 ierr = MPI_Send(0, 0, MPI_INT, 1, tag, newcomm);CHKERRQ(ierr); 1684 ierr = MPI_Recv(0, 0, MPI_INT, size-1, tag, newcomm, &status);CHKERRQ(ierr); 1685 PetscTime(y); 1686 ierr = PetscFPrintf(comm,fd,"Average time for zero size MPI_Send(): %g\n", (y-x)/size);CHKERRQ(ierr); 1687 } 1688 ierr = PetscCommDestroy(&newcomm);CHKERRQ(ierr); 1689 } 1690 ierr = PetscOptionsView(viewer);CHKERRQ(ierr); 1691 1692 /* Machine and compile information */ 1693 #if defined(PETSC_USE_FORTRAN_KERNELS) 1694 ierr = PetscFPrintf(comm, fd, "Compiled with FORTRAN kernels\n");CHKERRQ(ierr); 1695 #else 1696 ierr = PetscFPrintf(comm, fd, "Compiled without FORTRAN kernels\n");CHKERRQ(ierr); 1697 #endif 1698 #if defined(PETSC_USE_REAL_SINGLE) 1699 ierr = PetscFPrintf(comm, fd, "Compiled with single precision PetscScalar and PetscReal\n");CHKERRQ(ierr); 1700 #elif defined(PETSC_USE_LONGDOUBLE) 1701 ierr = PetscFPrintf(comm, fd, "Compiled with long double precision PetscScalar and PetscReal\n");CHKERRQ(ierr); 1702 #endif 1703 1704 #if defined(PETSC_USE_REAL_MAT_SINGLE) 1705 ierr = PetscFPrintf(comm, fd, "Compiled with single precision matrices\n");CHKERRQ(ierr); 1706 #else 1707 ierr = PetscFPrintf(comm, fd, "Compiled with full precision matrices (default)\n");CHKERRQ(ierr); 1708 #endif 1709 ierr = PetscFPrintf(comm, fd, "sizeof(short) %d sizeof(int) %d sizeof(long) %d sizeof(void*) %d sizeof(PetscScalar) %d sizeof(PetscInt) %d\n", 1710 (int) sizeof(short), (int) sizeof(int), (int) sizeof(long), (int) sizeof(void*),(int) sizeof(PetscScalar),(int) sizeof(PetscInt));CHKERRQ(ierr); 1711 1712 ierr = PetscFPrintf(comm, fd, "Configure run at: %s\n",petscconfigureruntime);CHKERRQ(ierr); 1713 ierr = PetscFPrintf(comm, fd, "Configure options: %s",petscconfigureoptions);CHKERRQ(ierr); 1714 ierr = PetscFPrintf(comm, fd, "%s", petscmachineinfo);CHKERRQ(ierr); 1715 ierr = PetscFPrintf(comm, fd, "%s", petsccompilerinfo);CHKERRQ(ierr); 1716 ierr = PetscFPrintf(comm, fd, "%s", petsccompilerflagsinfo);CHKERRQ(ierr); 1717 ierr = PetscFPrintf(comm, fd, "%s", petsclinkerinfo);CHKERRQ(ierr); 1718 1719 /* Cleanup */ 1720 ierr = PetscFPrintf(comm, fd, "\n");CHKERRQ(ierr); 1721 ierr = PetscStageLogPush(stageLog, lastStage);CHKERRQ(ierr); 1722 PetscFunctionReturn(0); 1723 } 1724 1725 #undef __FUNCT__ 1726 #define __FUNCT__ "PetscLogPrintDetailed" 1727 /*@C 1728 PetscLogPrintDetailed - Each process prints the times for its own events 1729 1730 Collective over MPI_Comm 1731 1732 Input Parameter: 1733 + comm - The MPI communicator (only one processor prints output) 1734 - file - [Optional] The output file name 1735 1736 Options Database Keys: 1737 . -log_summary_detailed - Prints summary of log information (for code compiled with PETSC_USE_LOG) 1738 1739 Usage: 1740 .vb 1741 PetscInitialize(...); 1742 PetscLogBegin(); 1743 ... code ... 1744 PetscLogPrintDetailed(MPI_Comm,filename); 1745 PetscFinalize(...); 1746 .ve 1747 1748 Notes: 1749 By default the summary is printed to stdout. 1750 1751 Level: beginner 1752 1753 .keywords: log, dump, print 1754 .seealso: PetscLogBegin(), PetscLogDump(), PetscLogView() 1755 @*/ 1756 PetscErrorCode PetscLogPrintDetailed(MPI_Comm comm, const char filename[]) 1757 { 1758 FILE *fd = PETSC_STDOUT; 1759 PetscStageLog stageLog; 1760 PetscStageInfo *stageInfo = PETSC_NULL; 1761 PetscEventPerfInfo *eventInfo = PETSC_NULL; 1762 const char *name = PETSC_NULL; 1763 PetscLogDouble TotalTime; 1764 PetscLogDouble stageTime, flops, flopr, mess, messLen, red; 1765 PetscLogDouble maxf, totf, maxt, tott, totm, totml, totr = 0.0; 1766 PetscMPIInt maxCt; 1767 PetscBool *stageUsed; 1768 PetscBool *stageVisible; 1769 int numStages, numEvents; 1770 int stage; 1771 PetscLogEvent event; 1772 PetscErrorCode ierr; 1773 1774 PetscFunctionBegin; 1775 if (!PetscLogBegin_PrivateCalled) SETERRQ(comm, PETSC_ERR_ORDER, "No call to PetscLogBegin() before PetscLogPrintDetailed()"); 1776 /* Pop off any stages the user forgot to remove */ 1777 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 1778 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 1779 while (stage >= 0) { 1780 ierr = PetscStageLogPop(stageLog);CHKERRQ(ierr); 1781 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 1782 } 1783 /* Get the total elapsed time */ 1784 PetscTime(TotalTime); TotalTime -= petsc_BaseTime; 1785 /* Open the summary file */ 1786 if (filename) { 1787 ierr = PetscFOpen(comm, filename, "w", &fd);CHKERRQ(ierr); 1788 } 1789 1790 ierr = PetscFPrintf(comm, fd, "************************************************************************************************************************\n");CHKERRQ(ierr); 1791 ierr = PetscFPrintf(comm, fd, "*** WIDEN YOUR WINDOW TO 120 CHARACTERS. Use 'enscript -r -fCourier9' to print this document ***\n");CHKERRQ(ierr); 1792 ierr = PetscFPrintf(comm, fd, "************************************************************************************************************************\n");CHKERRQ(ierr); 1793 1794 1795 numStages = stageLog->numStages; 1796 ierr = PetscMalloc(numStages * sizeof(PetscBool), &stageUsed);CHKERRQ(ierr); 1797 ierr = PetscMalloc(numStages * sizeof(PetscBool), &stageVisible);CHKERRQ(ierr); 1798 if (numStages > 0) { 1799 stageInfo = stageLog->stageInfo; 1800 for (stage = 0; stage < numStages; stage++) { 1801 if (stage < stageLog->numStages) { 1802 stageUsed[stage] = stageInfo[stage].used; 1803 stageVisible[stage] = stageInfo[stage].perfInfo.visible; 1804 } else { 1805 stageUsed[stage] = PETSC_FALSE; 1806 stageVisible[stage] = PETSC_TRUE; 1807 } 1808 } 1809 } 1810 1811 /* Report events */ 1812 ierr = PetscFPrintf(comm, fd,"Event Count Time (sec) Flops/sec \n");CHKERRQ(ierr); 1813 ierr = PetscFPrintf(comm, fd," Mess Avg len Reduct \n");CHKERRQ(ierr); 1814 ierr = PetscFPrintf(comm,fd,"-----------------------------------------------------------------------------------\n");CHKERRQ(ierr); 1815 /* Problem: The stage name will not show up unless the stage executed on proc 1 */ 1816 for (stage = 0; stage < numStages; stage++) { 1817 if (!stageVisible[stage]) continue; 1818 if (stageUsed[stage]) { 1819 ierr = PetscSynchronizedFPrintf(comm, fd, "\n--- Event Stage %d: %s\n\n", stage, stageInfo[stage].name);CHKERRQ(ierr); 1820 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.time, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, PETSC_COMM_SELF);CHKERRQ(ierr); 1821 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.flops, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, PETSC_COMM_SELF);CHKERRQ(ierr); 1822 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numMessages, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, PETSC_COMM_SELF);CHKERRQ(ierr); 1823 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.messageLength, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, PETSC_COMM_SELF);CHKERRQ(ierr); 1824 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numReductions, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, PETSC_COMM_SELF);CHKERRQ(ierr); 1825 } 1826 mess *= 0.5; messLen *= 0.5; 1827 1828 /* Get total number of events in this stage -- 1829 */ 1830 if (stageUsed[stage]) { 1831 eventInfo = stageLog->stageInfo[stage].eventLog->eventInfo; 1832 numEvents = stageLog->stageInfo[stage].eventLog->numEvents; 1833 } else numEvents = 0; 1834 1835 for (event = 0; event < numEvents; event++) { 1836 if (stageUsed[stage] && (event < stageLog->stageInfo[stage].eventLog->numEvents)) { 1837 if ((eventInfo[event].count > 0) && (eventInfo[event].time > 0.0)) flopr = eventInfo[event].flops/eventInfo[event].time; 1838 else flopr = 0.0; 1839 1840 ierr = MPI_Allreduce(&flopr, &maxf, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, PETSC_COMM_SELF);CHKERRQ(ierr); 1841 ierr = MPI_Allreduce(&eventInfo[event].flops, &totf, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, PETSC_COMM_SELF);CHKERRQ(ierr); 1842 ierr = MPI_Allreduce(&eventInfo[event].time, &maxt, 1, MPIU_PETSCLOGDOUBLE, MPI_MAX, PETSC_COMM_SELF);CHKERRQ(ierr); 1843 ierr = MPI_Allreduce(&eventInfo[event].time, &tott, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, PETSC_COMM_SELF);CHKERRQ(ierr); 1844 ierr = MPI_Allreduce(&eventInfo[event].numMessages, &totm, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, PETSC_COMM_SELF);CHKERRQ(ierr); 1845 ierr = MPI_Allreduce(&eventInfo[event].messageLength, &totml, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, PETSC_COMM_SELF);CHKERRQ(ierr); 1846 totr = eventInfo[event].numReductions; 1847 ierr = MPI_Allreduce(&eventInfo[event].count, &maxCt, 1, MPI_INT, MPI_MAX, PETSC_COMM_SELF);CHKERRQ(ierr); 1848 name = stageLog->eventLog->eventInfo[event].name; 1849 totm *= 0.5; totml *= 0.5; 1850 } 1851 1852 if (maxCt != 0) { 1853 if (totm != 0.0) totml /= totm; 1854 else totml = 0.0; 1855 ierr = PetscSynchronizedFPrintf(comm, fd,"%-16s %7d %5.4e %3.2e %2.1e %2.1e %2.1e\n",name, maxCt, maxt, maxf, totm, totml, totr);CHKERRQ(ierr); 1856 } 1857 } 1858 } 1859 ierr = PetscSynchronizedFlush(comm);CHKERRQ(ierr); 1860 1861 ierr = PetscFree(stageUsed);CHKERRQ(ierr); 1862 ierr = PetscFree(stageVisible);CHKERRQ(ierr); 1863 1864 ierr = PetscFClose(comm, fd);CHKERRQ(ierr); 1865 PetscFunctionReturn(0); 1866 } 1867 1868 /*----------------------------------------------- Counter Functions -------------------------------------------------*/ 1869 #undef __FUNCT__ 1870 #define __FUNCT__ "PetscGetFlops" 1871 /*@C 1872 PetscGetFlops - Returns the number of flops used on this processor 1873 since the program began. 1874 1875 Not Collective 1876 1877 Output Parameter: 1878 flops - number of floating point operations 1879 1880 Notes: 1881 A global counter logs all PETSc flop counts. The user can use 1882 PetscLogFlops() to increment this counter to include flops for the 1883 application code. 1884 1885 PETSc automatically logs library events if the code has been 1886 compiled with -DPETSC_USE_LOG (which is the default), and -log, 1887 -log_summary, or -log_all are specified. PetscLogFlops() is 1888 intended for logging user flops to supplement this PETSc 1889 information. 1890 1891 Level: intermediate 1892 1893 .keywords: log, flops, floating point operations 1894 1895 .seealso: PetscGetTime(), PetscLogFlops() 1896 @*/ 1897 PetscErrorCode PetscGetFlops(PetscLogDouble *flops) 1898 { 1899 PetscFunctionBegin; 1900 *flops = petsc_TotalFlops; 1901 PetscFunctionReturn(0); 1902 } 1903 1904 #undef __FUNCT__ 1905 #define __FUNCT__ "PetscLogObjectState" 1906 PetscErrorCode PetscLogObjectState(PetscObject obj, const char format[], ...) 1907 { 1908 PetscErrorCode ierr; 1909 size_t fullLength; 1910 va_list Argp; 1911 1912 PetscFunctionBegin; 1913 if (!petsc_logObjects) PetscFunctionReturn(0); 1914 va_start(Argp, format); 1915 ierr = PetscVSNPrintf(petsc_objects[obj->id].info, 64,format,&fullLength, Argp);CHKERRQ(ierr); 1916 va_end(Argp); 1917 PetscFunctionReturn(0); 1918 } 1919 1920 1921 /*MC 1922 PetscLogFlops - Adds floating point operations to the global counter. 1923 1924 Synopsis: 1925 #include "petsclog.h" 1926 PetscErrorCode PetscLogFlops(PetscLogDouble f) 1927 1928 Not Collective 1929 1930 Input Parameter: 1931 . f - flop counter 1932 1933 1934 Usage: 1935 .vb 1936 PetscLogEvent USER_EVENT; 1937 PetscLogEventRegister("User event",0,&USER_EVENT); 1938 PetscLogEventBegin(USER_EVENT,0,0,0,0); 1939 [code segment to monitor] 1940 PetscLogFlops(user_flops) 1941 PetscLogEventEnd(USER_EVENT,0,0,0,0); 1942 .ve 1943 1944 Notes: 1945 A global counter logs all PETSc flop counts. The user can use 1946 PetscLogFlops() to increment this counter to include flops for the 1947 application code. 1948 1949 PETSc automatically logs library events if the code has been 1950 compiled with -DPETSC_USE_LOG (which is the default), and -log, 1951 -log_summary, or -log_all are specified. PetscLogFlops() is 1952 intended for logging user flops to supplement this PETSc 1953 information. 1954 1955 Level: intermediate 1956 1957 .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogEventEnd(), PetscGetFlops() 1958 1959 .keywords: log, flops, floating point operations 1960 M*/ 1961 1962 /*MC 1963 PetscPreLoadBegin - Begin a segment of code that may be preloaded (run twice) 1964 to get accurate timings 1965 1966 Synopsis: 1967 #include "petsclog.h" 1968 void PetscPreLoadBegin(PetscBool flag,char *name); 1969 1970 Not Collective 1971 1972 Input Parameter: 1973 + flag - PETSC_TRUE to run twice, PETSC_FALSE to run once, may be overridden 1974 with command line option -preload true or -preload false 1975 - name - name of first stage (lines of code timed separately with -log_summary) to 1976 be preloaded 1977 1978 Usage: 1979 .vb 1980 PetscPreLoadBegin(PETSC_TRUE,"first stage); 1981 lines of code 1982 PetscPreLoadStage("second stage"); 1983 lines of code 1984 PetscPreLoadEnd(); 1985 .ve 1986 1987 Notes: Only works in C/C++, not Fortran 1988 1989 Flags available within the macro. 1990 + PetscPreLoadingUsed - true if we are or have done preloading 1991 . PetscPreLoadingOn - true if it is CURRENTLY doing preload 1992 . PetscPreLoadIt - 0 for the first computation (with preloading turned off it is only 0) 1 for the second 1993 - PetscPreLoadMax - number of times it will do the computation, only one when preloading is turned on 1994 The first two variables are available throughout the program, the second two only between the PetscPreLoadBegin() 1995 and PetscPreLoadEnd() 1996 1997 Level: intermediate 1998 1999 .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadEnd(), PetscPreLoadStage() 2000 2001 Concepts: preloading 2002 Concepts: timing^accurate 2003 Concepts: paging^eliminating effects of 2004 2005 2006 M*/ 2007 2008 /*MC 2009 PetscPreLoadEnd - End a segment of code that may be preloaded (run twice) 2010 to get accurate timings 2011 2012 Synopsis: 2013 #include "petsclog.h" 2014 void PetscPreLoadEnd(void); 2015 2016 Not Collective 2017 2018 Usage: 2019 .vb 2020 PetscPreLoadBegin(PETSC_TRUE,"first stage); 2021 lines of code 2022 PetscPreLoadStage("second stage"); 2023 lines of code 2024 PetscPreLoadEnd(); 2025 .ve 2026 2027 Notes: only works in C/C++ not fortran 2028 2029 Level: intermediate 2030 2031 .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadBegin(), PetscPreLoadStage() 2032 2033 M*/ 2034 2035 /*MC 2036 PetscPreLoadStage - Start a new segment of code to be timed separately. 2037 to get accurate timings 2038 2039 Synopsis: 2040 #include "petsclog.h" 2041 void PetscPreLoadStage(char *name); 2042 2043 Not Collective 2044 2045 Usage: 2046 .vb 2047 PetscPreLoadBegin(PETSC_TRUE,"first stage); 2048 lines of code 2049 PetscPreLoadStage("second stage"); 2050 lines of code 2051 PetscPreLoadEnd(); 2052 .ve 2053 2054 Notes: only works in C/C++ not fortran 2055 2056 Level: intermediate 2057 2058 .seealso: PetscLogEventRegister(), PetscLogEventBegin(), PetscLogEventEnd(), PetscPreLoadBegin(), PetscPreLoadEnd() 2059 2060 M*/ 2061 2062 #undef __FUNCT__ 2063 #define __FUNCT__ "PetscLogViewPython" 2064 /*@ 2065 PetscLogViewPython - Saves logging information in a Python format. 2066 2067 Collective on PetscViewer 2068 2069 Input Paramter: 2070 . viewer - viewer to save Python data 2071 2072 Level: intermediate 2073 2074 @*/ 2075 PetscErrorCode PetscLogViewPython(PetscViewer viewer) 2076 { 2077 FILE *fd; 2078 PetscLogDouble zero = 0.0; 2079 PetscStageLog stageLog; 2080 PetscStageInfo *stageInfo = PETSC_NULL; 2081 PetscEventPerfInfo *eventInfo = PETSC_NULL; 2082 const char *name; 2083 char stageName[2048]; 2084 char eventName[2048]; 2085 PetscLogDouble locTotalTime, TotalTime = 0, TotalFlops = 0; 2086 PetscLogDouble numMessages = 0, messageLength = 0, avgMessLen, numReductions = 0; 2087 PetscLogDouble stageTime, flops, mem, mess, messLen, red; 2088 PetscLogDouble fracTime, fracFlops, fracMessages, fracLength; 2089 PetscLogDouble fracReductions; 2090 PetscLogDouble tot,avg,x,y,*mydata; 2091 PetscMPIInt maxCt; 2092 PetscMPIInt size, rank, *mycount; 2093 PetscBool *localStageUsed, *stageUsed; 2094 PetscBool *localStageVisible, *stageVisible; 2095 int numStages, localNumEvents, numEvents; 2096 int stage, lastStage; 2097 PetscLogEvent event; 2098 PetscErrorCode ierr; 2099 PetscInt i; 2100 MPI_Comm comm; 2101 2102 PetscFunctionBegin; 2103 ierr = PetscObjectGetComm((PetscObject)viewer,&comm);CHKERRQ(ierr); 2104 if (!PetscLogBegin_PrivateCalled) SETERRQ(comm, PETSC_ERR_ORDER, "No call to PetscLogBegin() before PetscLogViewPython()"); 2105 ierr = MPI_Comm_size(comm, &size);CHKERRQ(ierr); 2106 ierr = MPI_Comm_rank(comm, &rank);CHKERRQ(ierr); 2107 ierr = PetscMalloc(size*sizeof(PetscLogDouble), &mydata);CHKERRQ(ierr); 2108 ierr = PetscMalloc(size*sizeof(PetscMPIInt), &mycount);CHKERRQ(ierr); 2109 ierr = PetscViewerASCIIGetPointer(viewer,&fd);CHKERRQ(ierr); 2110 2111 /* Pop off any stages the user forgot to remove */ 2112 lastStage = 0; 2113 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 2114 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 2115 while (stage >= 0) { 2116 lastStage = stage; 2117 ierr = PetscStageLogPop(stageLog);CHKERRQ(ierr); 2118 ierr = PetscStageLogGetCurrent(stageLog, &stage);CHKERRQ(ierr); 2119 } 2120 /* Get the total elapsed time */ 2121 PetscTime(locTotalTime); locTotalTime -= petsc_BaseTime; 2122 2123 ierr = PetscFPrintf(comm, fd, "\n#------ PETSc Performance Summary ----------\n\n");CHKERRQ(ierr); 2124 ierr = PetscFPrintf(comm, fd, "Nproc = %d\n",size);CHKERRQ(ierr); 2125 2126 /* Must preserve reduction count before we go on */ 2127 red = (petsc_allreduce_ct + petsc_gather_ct + petsc_scatter_ct)/((PetscLogDouble) size); 2128 2129 /* Calculate summary information */ 2130 2131 /* Time */ 2132 ierr = MPI_Gather(&locTotalTime,1,MPIU_PETSCLOGDOUBLE,mydata,1,MPIU_PETSCLOGDOUBLE,0,comm);CHKERRQ(ierr); 2133 if (!rank) { 2134 ierr = PetscFPrintf(comm, fd, "Time = [ ");CHKERRQ(ierr); 2135 tot = 0.0; 2136 for (i=0; i<size; i++) { 2137 tot += mydata[i]; 2138 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2139 } 2140 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2141 avg = (tot)/((PetscLogDouble) size); 2142 TotalTime = tot; 2143 } 2144 2145 /* Objects */ 2146 avg = (PetscLogDouble) petsc_numObjects; 2147 ierr = MPI_Gather(&avg,1,MPIU_PETSCLOGDOUBLE,mydata,1,MPIU_PETSCLOGDOUBLE,0,comm);CHKERRQ(ierr); 2148 if (!rank) { 2149 ierr = PetscFPrintf(comm, fd, "Objects = [ ");CHKERRQ(ierr); 2150 for (i=0; i<size; i++) { 2151 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2152 } 2153 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2154 } 2155 2156 /* Flops */ 2157 ierr = MPI_Gather(&petsc_TotalFlops,1,MPIU_PETSCLOGDOUBLE,mydata,1,MPIU_PETSCLOGDOUBLE,0,comm);CHKERRQ(ierr); 2158 if (!rank) { 2159 ierr = PetscFPrintf(comm, fd, "Flops = [ ");CHKERRQ(ierr); 2160 tot = 0.0; 2161 for (i=0; i<size; i++) { 2162 tot += mydata[i]; 2163 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2164 } 2165 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2166 TotalFlops = tot; 2167 } 2168 2169 /* Memory */ 2170 ierr = PetscMallocGetMaximumUsage(&mem);CHKERRQ(ierr); 2171 ierr = MPI_Gather(&mem,1,MPIU_PETSCLOGDOUBLE,mydata,1,MPIU_PETSCLOGDOUBLE,0,comm);CHKERRQ(ierr); 2172 if (!rank) { 2173 ierr = PetscFPrintf(comm, fd, "Memory = [ ");CHKERRQ(ierr); 2174 for (i=0; i<size; i++) { 2175 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2176 } 2177 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2178 } 2179 2180 /* Messages */ 2181 mess = 0.5*(petsc_irecv_ct + petsc_isend_ct + petsc_recv_ct + petsc_send_ct); 2182 ierr = MPI_Gather(&mess,1,MPIU_PETSCLOGDOUBLE,mydata,1,MPIU_PETSCLOGDOUBLE,0,comm);CHKERRQ(ierr); 2183 if (!rank) { 2184 ierr = PetscFPrintf(comm, fd, "MPIMessages = [ ");CHKERRQ(ierr); 2185 tot = 0.0; 2186 for (i=0; i<size; i++) { 2187 tot += mydata[i]; 2188 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2189 } 2190 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2191 numMessages = tot; 2192 } 2193 2194 /* Message Lengths */ 2195 mess = 0.5*(petsc_irecv_len + petsc_isend_len + petsc_recv_len + petsc_send_len); 2196 ierr = MPI_Gather(&mess,1,MPIU_PETSCLOGDOUBLE,mydata,1,MPIU_PETSCLOGDOUBLE,0,comm);CHKERRQ(ierr); 2197 if (!rank) { 2198 ierr = PetscFPrintf(comm, fd, "MPIMessageLengths = [ ");CHKERRQ(ierr); 2199 tot = 0.0; 2200 for (i=0; i<size; i++) { 2201 tot += mydata[i]; 2202 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2203 } 2204 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2205 messageLength = tot; 2206 } 2207 2208 /* Reductions */ 2209 ierr = MPI_Gather(&red,1,MPIU_PETSCLOGDOUBLE,mydata,1,MPIU_PETSCLOGDOUBLE,0,comm);CHKERRQ(ierr); 2210 if (!rank) { 2211 ierr = PetscFPrintf(comm, fd, "MPIReductions = [ ");CHKERRQ(ierr); 2212 tot = 0.0; 2213 for (i=0; i<size; i++) { 2214 tot += mydata[i]; 2215 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2216 } 2217 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2218 numReductions = tot; 2219 } 2220 2221 /* Get total number of stages -- 2222 Currently, a single processor can register more stages than another, but stages must all be registered in order. 2223 We can removed this requirement if necessary by having a global stage numbering and indirection on the stage ID. 2224 This seems best accomplished by assoicating a communicator with each stage. 2225 */ 2226 ierr = MPI_Allreduce(&stageLog->numStages, &numStages, 1, MPI_INT, MPI_MAX, comm);CHKERRQ(ierr); 2227 ierr = PetscMalloc(numStages * sizeof(PetscBool), &localStageUsed);CHKERRQ(ierr); 2228 ierr = PetscMalloc(numStages * sizeof(PetscBool), &stageUsed);CHKERRQ(ierr); 2229 ierr = PetscMalloc(numStages * sizeof(PetscBool), &localStageVisible);CHKERRQ(ierr); 2230 ierr = PetscMalloc(numStages * sizeof(PetscBool), &stageVisible);CHKERRQ(ierr); 2231 if (numStages > 0) { 2232 stageInfo = stageLog->stageInfo; 2233 for (stage = 0; stage < numStages; stage++) { 2234 if (stage < stageLog->numStages) { 2235 localStageUsed[stage] = stageInfo[stage].used; 2236 localStageVisible[stage] = stageInfo[stage].perfInfo.visible; 2237 } else { 2238 localStageUsed[stage] = PETSC_FALSE; 2239 localStageVisible[stage] = PETSC_TRUE; 2240 } 2241 } 2242 ierr = MPI_Allreduce(localStageUsed, stageUsed, numStages, MPIU_BOOL, MPI_LOR, comm);CHKERRQ(ierr); 2243 ierr = MPI_Allreduce(localStageVisible, stageVisible, numStages, MPIU_BOOL, MPI_LAND, comm);CHKERRQ(ierr); 2244 for (stage = 0; stage < numStages; stage++) { 2245 if (stageUsed[stage]) { 2246 ierr = PetscFPrintf(comm, fd, "\n#Summary of Stages: ----- Time ------ ----- Flops ----- --- Messages --- -- Message Lengths -- -- Reductions --\n");CHKERRQ(ierr); 2247 ierr = PetscFPrintf(comm, fd, "# Avg %%Total Avg %%Total counts %%Total Avg %%Total counts %%Total \n");CHKERRQ(ierr); 2248 break; 2249 } 2250 } 2251 for (stage = 0; stage < numStages; stage++) { 2252 if (!stageUsed[stage]) continue; 2253 if (localStageUsed[stage]) { 2254 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.time, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2255 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.flops, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2256 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numMessages, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2257 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.messageLength, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2258 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numReductions, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2259 name = stageInfo[stage].name; 2260 } else { 2261 ierr = MPI_Allreduce(&zero, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2262 ierr = MPI_Allreduce(&zero, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2263 ierr = MPI_Allreduce(&zero, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2264 ierr = MPI_Allreduce(&zero, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2265 ierr = MPI_Allreduce(&zero, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2266 name = ""; 2267 } 2268 mess *= 0.5; messLen *= 0.5; red /= size; 2269 if (TotalTime != 0.0) fracTime = stageTime/TotalTime; else fracTime = 0.0; 2270 if (TotalFlops != 0.0) fracFlops = flops/TotalFlops; else fracFlops = 0.0; 2271 /* Talk to Barry if (stageTime != 0.0) flops = (size*flops)/stageTime; else flops = 0.0; */ 2272 if (numMessages != 0.0) fracMessages = mess/numMessages; else fracMessages = 0.0; 2273 if (numMessages != 0.0) avgMessLen = messLen/numMessages; else avgMessLen = 0.0; 2274 if (messageLength != 0.0) fracLength = messLen/messageLength; else fracLength = 0.0; 2275 if (numReductions != 0.0) fracReductions = red/numReductions; else fracReductions = 0.0; 2276 ierr = PetscFPrintf(comm, fd, "# "); 2277 ierr = 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", 2278 stage, name, stageTime/size, 100.0*fracTime, flops, 100.0*fracFlops, 2279 mess, 100.0*fracMessages, avgMessLen, 100.0*fracLength, red, 100.0*fracReductions);CHKERRQ(ierr); 2280 } 2281 } 2282 2283 /* Report events */ 2284 ierr = PetscFPrintf(comm,fd,"\n# Event\n");CHKERRQ(ierr); 2285 ierr = PetscFPrintf(comm,fd,"# ------------------------------------------------------\n");CHKERRQ(ierr); 2286 ierr = PetscFPrintf(comm,fd,"class Stage(object):\n");CHKERRQ(ierr); 2287 ierr = PetscFPrintf(comm,fd," def __init__(self, name, time, flops, numMessages, messageLength, numReductions):\n");CHKERRQ(ierr); 2288 ierr = PetscFPrintf(comm,fd," # The time and flops represent totals across processes, whereas reductions are only counted once\n");CHKERRQ(ierr); 2289 ierr = PetscFPrintf(comm,fd," self.name = name\n");CHKERRQ(ierr); 2290 ierr = PetscFPrintf(comm,fd," self.time = time\n");CHKERRQ(ierr); 2291 ierr = PetscFPrintf(comm,fd," self.flops = flops\n");CHKERRQ(ierr); 2292 ierr = PetscFPrintf(comm,fd," self.numMessages = numMessages\n");CHKERRQ(ierr); 2293 ierr = PetscFPrintf(comm,fd," self.messageLength = messageLength\n");CHKERRQ(ierr); 2294 ierr = PetscFPrintf(comm,fd," self.numReductions = numReductions\n");CHKERRQ(ierr); 2295 ierr = PetscFPrintf(comm,fd," self.event = {}\n");CHKERRQ(ierr); 2296 ierr = PetscFPrintf(comm,fd, "class Dummy(object):\n");CHKERRQ(ierr); 2297 ierr = PetscFPrintf(comm,fd, " pass\n");CHKERRQ(ierr); 2298 /* Problem: The stage name will not show up unless the stage executed on proc 1 */ 2299 for (stage = 0; stage < numStages; stage++) { 2300 if (!stageVisible[stage]) continue; 2301 if (localStageUsed[stage]) { 2302 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.time, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2303 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.flops, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2304 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numMessages, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2305 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.messageLength, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2306 ierr = MPI_Allreduce(&stageInfo[stage].perfInfo.numReductions, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2307 } else { 2308 ierr = PetscFPrintf(comm, fd, "\n--- Event Stage %d: Unknown\n\n", stage);CHKERRQ(ierr); 2309 ierr = MPI_Allreduce(&zero, &stageTime, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2310 ierr = MPI_Allreduce(&zero, &flops, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2311 ierr = MPI_Allreduce(&zero, &mess, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2312 ierr = MPI_Allreduce(&zero, &messLen, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2313 ierr = MPI_Allreduce(&zero, &red, 1, MPIU_PETSCLOGDOUBLE, MPI_SUM, comm);CHKERRQ(ierr); 2314 } 2315 mess *= 0.5; messLen *= 0.5; red /= size; 2316 2317 /* Get total number of events in this stage -- 2318 Currently, a single processor can register more events than another, but events must all be registered in order, 2319 just like stages. We can removed this requirement if necessary by having a global event numbering and indirection 2320 on the event ID. This seems best accomplished by assoicating a communicator with each stage. 2321 2322 Problem: If the event did not happen on proc 1, its name will not be available. 2323 Problem: Event visibility is not implemented 2324 */ 2325 2326 { 2327 size_t len, c; 2328 2329 ierr = PetscStrcpy(stageName, stageInfo[stage].name);CHKERRQ(ierr); 2330 ierr = PetscStrlen(stageName, &len);CHKERRQ(ierr); 2331 for (c = 0; c < len; ++c) { 2332 if (stageName[c] == ' ') stageName[c] = '_'; 2333 } 2334 } 2335 if (!rank) { 2336 ierr = PetscFPrintf(comm, fd, "%s = Stage('%s', %g, %g, %g, %g, %g)\n", stageName, stageName, stageTime, flops, mess, messLen, red);CHKERRQ(ierr); 2337 } 2338 2339 if (localStageUsed[stage]) { 2340 eventInfo = stageLog->stageInfo[stage].eventLog->eventInfo; 2341 localNumEvents = stageLog->stageInfo[stage].eventLog->numEvents; 2342 } else localNumEvents = 0; 2343 2344 ierr = MPI_Allreduce(&localNumEvents, &numEvents, 1, MPI_INT, MPI_MAX, comm);CHKERRQ(ierr); 2345 for (event = 0; event < numEvents; event++) { 2346 PetscBool hasEvent = PETSC_TRUE; 2347 PetscMPIInt tmpI; 2348 PetscLogDouble tmpR; 2349 2350 if (localStageUsed[stage] && (event < stageLog->stageInfo[stage].eventLog->numEvents) && (eventInfo[event].depth == 0)) { 2351 size_t len, c; 2352 2353 ierr = MPI_Allreduce(&eventInfo[event].count, &maxCt, 1, MPI_INT, MPI_MAX, comm);CHKERRQ(ierr); 2354 ierr = PetscStrcpy(eventName, stageLog->eventLog->eventInfo[event].name);CHKERRQ(ierr); 2355 ierr = PetscStrlen(eventName, &len);CHKERRQ(ierr); 2356 for (c = 0; c < len; ++c) { 2357 if (eventName[c] == ' ') eventName[c] = '_'; 2358 } 2359 } else { 2360 ierr = MPI_Allreduce(&ierr, &maxCt, 1, MPI_INT, MPI_MAX, comm);CHKERRQ(ierr); 2361 eventName[0] = 0; 2362 hasEvent = PETSC_FALSE; 2363 } 2364 2365 if (maxCt != 0) { 2366 ierr = PetscFPrintf(comm, fd,"#\n");CHKERRQ(ierr); 2367 if (!rank) { 2368 ierr = PetscFPrintf(comm, fd, "%s = Dummy()\n",eventName);CHKERRQ(ierr); 2369 ierr = PetscFPrintf(comm, fd, "%s.event['%s'] = %s\n",stageName,eventName,eventName);CHKERRQ(ierr); 2370 } 2371 /* Count */ 2372 if (hasEvent) tmpI = eventInfo[event].count; 2373 else tmpI = 0; 2374 ierr = MPI_Gather(&tmpI,1, MPI_INT, mycount, 1, MPI_INT, 0, comm);CHKERRQ(ierr); 2375 ierr = PetscFPrintf(comm, fd, "%s.Count = [ ", eventName);CHKERRQ(ierr); 2376 if (!rank) { 2377 for (i=0; i<size; i++) { 2378 ierr = PetscFPrintf(comm, fd, " %7d,",mycount[i]);CHKERRQ(ierr); 2379 } 2380 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2381 } 2382 /* Time */ 2383 if (hasEvent) tmpR = eventInfo[event].time; 2384 else tmpR = 0.0; 2385 ierr = MPI_Gather(&tmpR, 1, MPIU_PETSCLOGDOUBLE, mydata, 1, MPIU_PETSCLOGDOUBLE, 0, comm);CHKERRQ(ierr); 2386 if (!rank) { 2387 ierr = PetscFPrintf(comm, fd, "%s.Time = [ ", eventName);CHKERRQ(ierr); 2388 for (i=0; i<size; i++) { 2389 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2390 } 2391 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2392 } 2393 if (hasEvent) tmpR = eventInfo[event].time2; 2394 else tmpR = 0.0; 2395 ierr = MPI_Gather(&tmpR, 1, MPIU_PETSCLOGDOUBLE, mydata, 1, MPIU_PETSCLOGDOUBLE, 0, comm);CHKERRQ(ierr); 2396 if (!rank) { 2397 ierr = PetscFPrintf(comm, fd, "%s.Time2 = [ ", eventName);CHKERRQ(ierr); 2398 for (i=0; i<size; i++) { 2399 ierr = PetscFPrintf(comm, fd, " %5.3e,", mydata[i]);CHKERRQ(ierr); 2400 } 2401 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2402 } 2403 /* Flops */ 2404 if (hasEvent) tmpR = eventInfo[event].flops; 2405 else tmpR = 0.0; 2406 ierr = MPI_Gather(&tmpR, 1, MPIU_PETSCLOGDOUBLE, mydata, 1, MPIU_PETSCLOGDOUBLE, 0, comm);CHKERRQ(ierr); 2407 if (!rank) { 2408 ierr = PetscFPrintf(comm, fd, "%s.Flops = [ ", eventName);CHKERRQ(ierr); 2409 for (i=0; i<size; i++) { 2410 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2411 } 2412 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2413 } 2414 if (hasEvent) tmpR = eventInfo[event].flops2; 2415 else tmpR = 0.0; 2416 ierr = MPI_Gather(&tmpR, 1, MPIU_PETSCLOGDOUBLE, mydata, 1, MPIU_PETSCLOGDOUBLE, 0, comm);CHKERRQ(ierr); 2417 if (!rank) { 2418 ierr = PetscFPrintf(comm, fd, "%s.Flops2 = [ ", eventName);CHKERRQ(ierr); 2419 for (i=0; i<size; i++) { 2420 ierr = PetscFPrintf(comm, fd, " %5.3e,", mydata[i]);CHKERRQ(ierr); 2421 } 2422 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2423 } 2424 /* Num Messages */ 2425 if (hasEvent) tmpR = eventInfo[event].numMessages; 2426 else tmpR = 0.0; 2427 ierr = MPI_Gather(&tmpR, 1, MPIU_PETSCLOGDOUBLE, mydata, 1, MPIU_PETSCLOGDOUBLE, 0, comm);CHKERRQ(ierr); 2428 ierr = PetscFPrintf(comm, fd, "%s.NumMessages = [ ", eventName);CHKERRQ(ierr); 2429 if (!rank) { 2430 for (i=0; i<size; i++) { 2431 ierr = PetscFPrintf(comm, fd, " %7.1e,",mydata[i]);CHKERRQ(ierr); 2432 } 2433 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2434 } 2435 /* Message Length */ 2436 if (hasEvent) tmpR = eventInfo[event].messageLength; 2437 else tmpR = 0.0; 2438 ierr = MPI_Gather(&tmpR, 1, MPIU_PETSCLOGDOUBLE, mydata, 1, MPIU_PETSCLOGDOUBLE, 0, comm);CHKERRQ(ierr); 2439 if (!rank) { 2440 ierr = PetscFPrintf(comm, fd, "%s.MessageLength = [ ", eventName);CHKERRQ(ierr); 2441 for (i=0; i<size; i++) { 2442 ierr = PetscFPrintf(comm, fd, " %5.3e,",mydata[i]);CHKERRQ(ierr); 2443 } 2444 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2445 } 2446 /* Num Reductions */ 2447 if (hasEvent) tmpR = eventInfo[event].numReductions; 2448 else tmpR = 0.0; 2449 ierr = MPI_Gather(&tmpR, 1, MPIU_PETSCLOGDOUBLE, mydata, 1, MPIU_PETSCLOGDOUBLE, 0, comm);CHKERRQ(ierr); 2450 ierr = PetscFPrintf(comm, fd, "%s.NumReductions = [ ", eventName);CHKERRQ(ierr); 2451 if (!rank) { 2452 for (i=0; i<size; i++) { 2453 ierr = PetscFPrintf(comm, fd, " %7.1e,",mydata[i]);CHKERRQ(ierr); 2454 } 2455 ierr = PetscFPrintf(comm, fd, "]\n");CHKERRQ(ierr); 2456 } 2457 } 2458 } 2459 } 2460 2461 /* Right now, only stages on the first processor are reported here, meaning only objects associated with 2462 the global communicator, or MPI_COMM_SELF for proc 1. We really should report global stats and then 2463 stats for stages local to processor sets. 2464 */ 2465 for (stage = 0; stage < numStages; stage++) { 2466 if (!localStageUsed[stage]) { 2467 ierr = PetscFPrintf(comm, fd, "\n--- Event Stage %d: Unknown\n\n", stage);CHKERRQ(ierr); 2468 } 2469 } 2470 2471 ierr = PetscFree(localStageUsed);CHKERRQ(ierr); 2472 ierr = PetscFree(stageUsed);CHKERRQ(ierr); 2473 ierr = PetscFree(localStageVisible);CHKERRQ(ierr); 2474 ierr = PetscFree(stageVisible);CHKERRQ(ierr); 2475 ierr = PetscFree(mydata);CHKERRQ(ierr); 2476 ierr = PetscFree(mycount);CHKERRQ(ierr); 2477 2478 /* Information unrelated to this particular run */ 2479 ierr = PetscFPrintf(comm, fd, "# ========================================================================================================================\n");CHKERRQ(ierr); 2480 PetscTime(y); 2481 PetscTime(x); 2482 PetscTime(y); PetscTime(y); PetscTime(y); PetscTime(y); PetscTime(y); 2483 PetscTime(y); PetscTime(y); PetscTime(y); PetscTime(y); PetscTime(y); 2484 ierr = PetscFPrintf(comm,fd,"AveragetimetogetPetscTime = %g\n", (y-x)/10.0);CHKERRQ(ierr); 2485 /* MPI information */ 2486 if (size > 1) { 2487 MPI_Status status; 2488 PetscMPIInt tag; 2489 MPI_Comm newcomm; 2490 2491 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 2492 PetscTime(x); 2493 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 2494 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 2495 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 2496 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 2497 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 2498 PetscTime(y); 2499 ierr = PetscFPrintf(comm, fd, "AveragetimeforMPI_Barrier = %g\n", (y-x)/5.0);CHKERRQ(ierr); 2500 ierr = PetscCommDuplicate(comm,&newcomm, &tag);CHKERRQ(ierr); 2501 ierr = MPI_Barrier(comm);CHKERRQ(ierr); 2502 if (rank) { 2503 ierr = MPI_Recv(0, 0, MPI_INT, rank-1, tag, newcomm, &status);CHKERRQ(ierr); 2504 ierr = MPI_Send(0, 0, MPI_INT, (rank+1)%size, tag, newcomm);CHKERRQ(ierr); 2505 } else { 2506 PetscTime(x); 2507 ierr = MPI_Send(0, 0, MPI_INT, 1, tag, newcomm);CHKERRQ(ierr); 2508 ierr = MPI_Recv(0, 0, MPI_INT, size-1, tag, newcomm, &status);CHKERRQ(ierr); 2509 PetscTime(y); 2510 ierr = PetscFPrintf(comm,fd,"AveragetimforzerosizeMPI_Send = %g\n", (y-x)/size);CHKERRQ(ierr); 2511 } 2512 ierr = PetscCommDestroy(&newcomm);CHKERRQ(ierr); 2513 } 2514 2515 /* Cleanup */ 2516 ierr = PetscFPrintf(comm, fd, "\n");CHKERRQ(ierr); 2517 ierr = PetscStageLogPush(stageLog, lastStage);CHKERRQ(ierr); 2518 PetscFunctionReturn(0); 2519 } 2520 2521 #else /* end of -DPETSC_USE_LOG section */ 2522 2523 #undef __FUNCT__ 2524 #define __FUNCT__ "PetscLogObjectState" 2525 PetscErrorCode PetscLogObjectState(PetscObject obj, const char format[], ...) 2526 { 2527 PetscFunctionBegin; 2528 PetscFunctionReturn(0); 2529 } 2530 2531 #endif /* PETSC_USE_LOG*/ 2532 2533 2534 PetscClassId PETSC_LARGEST_CLASSID = PETSC_SMALLEST_CLASSID; 2535 PetscClassId PETSC_OBJECT_CLASSID = 0; 2536 2537 #undef __FUNCT__ 2538 #define __FUNCT__ "PetscClassIdRegister" 2539 /*@C 2540 PetscClassIdRegister - Registers a new class name for objects and logging operations in an application code. 2541 2542 Not Collective 2543 2544 Input Parameter: 2545 . name - The class name 2546 2547 Output Parameter: 2548 . oclass - The class id or classid 2549 2550 Level: developer 2551 2552 .keywords: log, class, register 2553 2554 @*/ 2555 PetscErrorCode PetscClassIdRegister(const char name[],PetscClassId *oclass) 2556 { 2557 #if defined(PETSC_USE_LOG) 2558 PetscStageLog stageLog; 2559 PetscInt stage; 2560 PetscErrorCode ierr; 2561 #endif 2562 2563 PetscFunctionBegin; 2564 *oclass = ++PETSC_LARGEST_CLASSID; 2565 #if defined(PETSC_USE_LOG) 2566 ierr = PetscLogGetStageLog(&stageLog);CHKERRQ(ierr); 2567 ierr = PetscClassRegLogRegister(stageLog->classLog, name, *oclass);CHKERRQ(ierr); 2568 for (stage = 0; stage < stageLog->numStages; stage++) { 2569 ierr = ClassPerfLogEnsureSize(stageLog->stageInfo[stage].classLog, stageLog->classLog->numClasses);CHKERRQ(ierr); 2570 } 2571 #endif 2572 PetscFunctionReturn(0); 2573 } 2574