Thank you very much for fixing the errors I introduced and improving the code. I have put it into branch barry/fix-xml-logging and merged to next for testing.
I do have one concern, when I run on src/snes/examples/tutorials/ex19.c with no options (see attached result)
joe.xml
Description: XML document
it lists a MatAssemblyEnd() as a top-level event (but not a MatAssemblyBegin()) but there is no MatAssemblyEnd() at the top level, they should all be occurring inside the SNESSolve() and when I run in the debugger all the MatAssemblyEnd() occur within the SNESSolve(). I am not sure why it incorrectly locates the MatAssemblyEnd() as a top level event? Thanks again Barry > On Jul 8, 2016, at 7:59 AM, Koos Huijssen <[email protected]> wrote: > > Dear Barry, > > I found some time to fix the issues with the nested timers. The attached > patch file should work on commit > > c03b0cd 2016-07-07 | Merge branch > 'stefano_zampini/hypre-ams-zerointerior-feature' > > What I have found is the following: > > - There were some issues with the merging of the code into the Petsc code > base. I have reviewed the merge and fixed this (mainly the section around > depth/maxdepth determination). > - There was indeed a fundamental issue, concerning a wrong assumption that > the PetscLogEvent id =0 was reserved for the overall 'awake' root event. As > it was also used for a normal event, this normal event was mistakenly > considered as the root event which caused some trouble. I fixed the code. The > issue of the single-event example giving a crash is now resolved as well. > - When running snes/examples/tutorial/ex56, I found that a timer in > DMPlexDistribute was not properly ended. If fixed this. > > With regard to the latter I wonder why the 'standard' timer events did not > notice the fact that the DMPLEX_Distribute was not closed and that it should > count as the event with the longest evaluation time. Could it be that the > logging disregards any timers that are still open? I was thinking of > including a warning message in the nested timers for any open timers at the > time of the log generation, but I haven't done that for now. > > One thing that is still open is the fact that the nested timers are only > considering the timings of the events as far as they are logged in the Main > Stage. Timings in other stages are simply ignored. For instance, with the > example snes/examples/tutorial/ex56.c, we will only get meaningful nested > timing information from the ascii_xml viewer if we set log_stages = > PETSC_FALSE on line 13. For now, I see three possible approaches to resolve > this: > - Tell the users that they should turn off stages in their code if they would > like to use the nested timers. Given the fact that the nested timer > functionality basically makes the stages obsolete, this could be a future > option. > - After the Main Stage is pushed in PetscLogInitialize, disable the > PetscLogStagePush() and PetscLogStagePop() functionality if the ascii_xml > viewer is selected for output. > - Adjust the xmllogevent functions to consider the eventPerfInfo array of all > stages that are in use. This is however a complex code adjustment which I > would not prefer to do, also given the fact that the staging functionality is > not relevant for the nested timers. > > Please let me know what you think of the above. Could you please include the > patch in the Petsc code? > > With kind regards, > > Koos Huijssen > __________________________________________ > > VORtech BV - Scientific software engineers > __________________________________________ > > Dr.ir. Koos Huijssen > > P.O. Box 260 > 2600 AG Delft > The Netherlands > > phone +31(0)15-285 0125 > mobile +31(0)6-3333 0803 > email [email protected] > web www.vortech.nl > > -----Oorspronkelijk bericht----- > Van: Barry Smith [mailto:[email protected]] > Verzonden: maandag 6 juni 2016 17:21 > Aan: Koos Huijssen > CC: Richard Mills; [email protected]; Klaij, Christiaan > Onderwerp: Re: [petsc-dev] Nested event logging and human friendly output > > > Whenever you can get to it is fine. > > Thanks > > Barry > >> On Jun 6, 2016, at 8:14 AM, Koos Huijssen <[email protected]> wrote: >> >> Dear Barry, >> >> Thanks for notifying us of these issues. There seems to be quite a few >> fundamental issues with the nested timer functionality and the xml output. >> We will have to check the case, reproduce the problems and start looking >> into the code. However, currently we are unable to do so. We may be able to >> look into the issue in a month or so. Would that be okay for you? If so, >> then we will come back on the issue in the beginning of July. >> >> With kind regards, >> >> Koos >> >> From: Barry Smith [mailto:[email protected]] >> Sent: zondag 5 juni 2016 1:19 >> To: Koos Huijssen <[email protected]>; Richard Mills >> <[email protected]> >> Cc: [email protected]; Klaij, Christiaan <[email protected]> >> Subject: Re: [petsc-dev] Nested event logging and human friendly >> output >> >> >> We are having some major problems with your xml nested logging on a >> slightly more complicated example and I've been trying to debug it with no >> success. So I went back to my original commit >> bb1d7374b64f295b2ed5ff23b89435d65e905a54 and found something I was not >> expecting. When I run src/snes/examples/tutorials/ex19 with logging it >> generates the attached image. Which is wrong, note that >> SNESJacobianEvaluate, KSPSolve etc are embedded in the SNES solver but this >> is not properly displayed. Shouldn't they be in one level from the >> SNESSolve? Is this a bug, a feature? Or ...? >> >> Thanks for any information, >> >> Barry >> >> The major problem we are seeing with the nested logging is in the >> branch mark/snes-ex56c when we run src/snes/examples/tutorials/ex56 >> with >> >> petscmpiexec -n 1 ./ex56 -dm_refine 2 -ne 8 -alpha 1.e-3 -two_solves >> false -petscspace_poly_tensor -petscspace_order 1 -ksp_type cg >> -ksp_monitor_short -ksp_rtol 1.e-8 -pc_type gamg -pc_gamg_type agg >> -pc_gamg_agg_nsmooths 1 -pc_gamg_coarse_eq_limit 100 >> -pc_gamg_reuse_interpolation true -pc_gamg_square_graph 1 >> -pc_gamg_threshold 0.0 -ksp_converged_reason -use_mat_nearnullspace >> true -mg_levels_ksp_max_it 2 -mg_levels_ksp_type chebyshev >> -mg_levels_esteig_ksp_type cg -mg_levels_esteig_ksp_max_it 10 >> -mg_levels_ksp_chebyshev_esteig 0,0.05,0,1.05 -mg_levels_pc_type sor >> -mat_block_size 3 -petscpartitioner_type chaco -log_view >> ascii:ex56-intel2016_knl_fast_64ranks_ne8_dmrefine3_log.xml:ascii_xml >> >> it messes up the nesting and has total nonsense for the numerical values of >> time, for example in the different events, while the traditional >> -log_summary prints out reasonable results. It seems somehow either to be >> not gathering the data properly into the nested event data structures you >> have or not properly processing the data to generate the xml. I tried >> debugging but the logic is unclear to me. >> >> Simple programs such as: >> ierr = PetscLogEventRegister("Event1",0,&event1);CHKERRQ(ierr); >> >> ierr = PetscLogEventBegin(event1,0,0,0,0);CHKERRQ(ierr); >> ierr = PetscSleep(1.0);CHKERRQ(ierr); >> ierr = PetscLogEventEnd(event1,0,0,0,0);CHKERRQ(ierr); >> >> produce: >> >> [0]PETSC ERROR: Petsc has generated inconsistent data [0]PETSC ERROR: >> Depth 2 > maxdepth + 1 1 [0]PETSC ERROR: See >> http://www.mcs.anl.gov/petsc/documentation/faq.html for trouble shooting. >> [0]PETSC ERROR: Petsc Development GIT revision: v3.7.1-405-gbb23584 >> GIT Date: 2016-06-04 11:37:36 -0500 [0]PETSC ERROR: ./ex30 on a >> arch-xmllog named Barrys-MacBook-Pro.local by barrysmith Sat Jun 4 >> 18:13:00 2016 [0]PETSC ERROR: Configure options --download-chaco >> --with-mpi-dir=/Users/barrysmith/libraries PETSC_ARCH=arch-xmllog >> [0]PETSC ERROR: #1 PetscCreateLogTreeNested() line 719 in >> /Users/barrysmith/Src/petsc/src/sys/logging/xmllogevent.c >> >> ierr = PetscLogEventRegister("Event1",0,&event1);CHKERRQ(ierr); >> ierr = PetscLogEventRegister("Event2",0,&event2);CHKERRQ(ierr); >> ierr = PetscLogEventRegister("Event3",0,&event3);CHKERRQ(ierr); >> >> ierr = PetscLogEventBegin(event1,0,0,0,0);CHKERRQ(ierr); >> ierr = PetscSleep(1.0);CHKERRQ(ierr); >> ierr = PetscLogEventBegin(event2,0,0,0,0);CHKERRQ(ierr); >> ierr = PetscSleep(1.0);CHKERRQ(ierr); >> ierr = PetscLogEventBegin(event3,0,0,0,0);CHKERRQ(ierr); >> ierr = PetscSleep(1.0);CHKERRQ(ierr); >> ierr = PetscLogEventEnd(event3,0,0,0,0);CHKERRQ(ierr); >> ierr = PetscLogEventEnd(event2,0,0,0,0);CHKERRQ(ierr); >> ierr = PetscLogEventEnd(event1,0,0,0,0);CHKERRQ(ierr); >> >> doesn't crash but doesn't nest event2 and 3 in one but does nest 3 into 2. >> >> If seems that the ordering of the event values mater, if I change the >> registration order to >> >> ierr = PetscLogEventRegister("Event2",0,&event2);CHKERRQ(ierr); >> ierr = PetscLogEventRegister("Event1",0,&event1);CHKERRQ(ierr); >> ierr = PetscLogEventRegister("Event3",0,&event3);CHKERRQ(ierr); >> >> then it crashes with >> >> [0]PETSC ERROR: Petsc has generated inconsistent data [0]PETSC ERROR: >> Depth 2 > maxdepth + 1 1 [0]PETSC ERROR: See >> http://www.mcs.anl.gov/petsc/documentation/faq.html for trouble shooting. >> [0]PETSC ERROR: Petsc Development GIT revision: v3.7.1-405-gbb23584 >> GIT Date: 2016-06-04 11:37:36 -0500 [0]PETSC ERROR: ./ex30 on a >> arch-xmllog named Barrys-MacBook-Pro.local by barrysmith Sat Jun 4 >> 18:17:40 2016 [0]PETSC ERROR: Configure options --download-chaco >> --with-mpi-dir=/Users/barrysmith/libraries PETSC_ARCH=arch-xmllog >> [0]PETSC ERROR: #1 PetscCreateLogTreeNested() line 719 in >> /Users/barrysmith/Src/petsc/src/sys/logging/xmllogevent.c >> [0]PETSC ERROR: #2 PetscLogView_Nested() line 1399 in >> /Users/barrysmith/Src/petsc/src/sys/logging/xmllogevent.c >> >> >> >> Possibly related issue: If you run an example that has nothing that is >> actually logged but attempt to use the -log_view it crashes, there is some >> implicit assumption in your generation of the xml that some values will be >> non-empty. >> >> >> >> >> >> >> On Sep 18, 2<image002.png>015, at 10:09 PM, Barry Smith <[email protected]> >> wrote: >> >> >> Thank you for contributing the nested logging. I have incorporated >> into the PETSc branch barry/xml-nested-logging if you look at >> https://bitbucket.org/petsc/petsc/commits/bb1d7374b64f295b2ed5ff23b894 >> 35d65e905a54?at=masteryou can see exactly what I have incorporated >> into PETSc. I will merge it into next for portability testing in the >> next couple of days. I expect over time as I understand it better I >> will be able to improve its integration with PETSc. Currently to >> generate the nested logging it is as simple to use as -log_view >> :filename.xml:ascii_xml >> >> Thanks again, >> >> Barry >> >> >> >> >> >> >> On Sep 14, 2015, at 7:45 AM, Koos Huijssen <[email protected]> wrote: >> >> Dear PETSc development team, >> >> We have developed an extension of the PETSc event logging facilities that >> has the following advanced features: >> >> - It allows logging of events in the form of a nested tree. So if some >> function is called from multiple locations in the code, these instances are >> distinguished. This in contrast with the standard event logger, which only >> logs the amount of total call time. >> - It allows the output report to be formatted in XML format. This >> output can then be viewed in a human-friendly form in a web browser with the >> use of the XSL Transformation script performance_xml2html.xsl. The html >> features an nested timings tree that can be expanded and collapsed as >> desired. >> >> This tool has been very useful for us to analyze the code and pinpoint >> performance bottle necks. We think that it can be useful for others as well, >> and therefore we are providing the code here for integration in the open >> source distribution of PETSc. >> >> For more information I refer to the included manual. We have also provided a >> test program and a makefile for convenience. The test program can be run >> using MPI with for instance 3-6 processes. >> >> I apologize for not using the git repo to submit the developed code. I also >> apologize for not adhering to the PETSc coding standards (or at least not as >> far as I know), but I hope that it is not too far off.. Apart from the whole >> capital/underscore standardization stuff one issue may require special >> attention, namely the (ab)use of the format PETSc_VIEWER_ASCII_IMPL for >> signaling the XML format in XMLViewer.c. I couldn't find an already existing >> and better fitting format, but it could be necessary to add a new format >> here for this purpose. >> >> Can you take it up from here and realize the integration of the code in the >> PETSc distribution? >> >> With kind regards, >> >> Koos Huijssen >> >> -- >> ____________________________________________________________________ >> >> VORtech BV - Scientific software engineers >> ____________________________________________________________________ >> >> Dr.ir. Koos Huijssen >> >> P.O. Box 260 >> 2600 AG Delft >> The Netherlands >> >> phone +31(0)15-285 0125 >> mobile +31(0)6-3333 0803 >> email [email protected] >> web www.vortech.nl >> ____________________________________________________________________ >> >> <timers.tar.gz> >> >> > > <0001-ascii_xml-logging-fixes-to-nested-tree-generation-an.patch>
