Hi Barry, I did some analysis on the results, but I see nothing strange. The missing MatAssemblyBegin could be because its time falls under the threshold of 0.01% of the total runtime, in which case it is left out of the tree. I ran the same case, and I got both Begin/End operations, but both at 0% (so probably both dwindling around the 0.01% threshold). The MatAssemblyBegin/MatAssemblyEnd pair are part of the SNESSolve routine, but they are not located within the SNES_Solve log event. This event only registers the time spent in the solve routine in snes->ops->solve. If I set an event around the call to SNESSolve in ex19.c, they do appear within that event. Maybe something to do with MatInterpolate or DMInterpolate?
Since the log events have never been used in a nested logging before, it could be that this type of misunderstanding will occur more often whenever a log event is not one-to-one coupled to its routine but to a section within that routine. With kind regards, Koos From: Koos Huijssen Sent: donderdag 4 augustus 2016 22:12 To: Koos Huijssen <[email protected]> Subject: Fwd: [petsc-dev] Nested event logging and human friendly output Begin doorgestuurd bericht: Van: Barry Smith <[email protected]<mailto:[email protected]>> Datum: 17 juli 2016 04:44:04 CEST Aan: Koos Huijssen <[email protected]<mailto:[email protected]>> Kopie: Richard Mills <[email protected]<mailto:[email protected]>>, "[email protected]<mailto:[email protected]>" <[email protected]<mailto:[email protected]>>, "Klaij, Christiaan" <[email protected]<mailto:[email protected]>>, "Bas van 't Hof" <[email protected]<mailto:[email protected]>> Onderwerp: Antw.: [petsc-dev] Nested event logging and human friendly output 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> 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]<mailto:[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]<mailto:[email protected]> web www.vortech.nl<http://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]<mailto:[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]<mailto:[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]<mailto:[email protected]>>; Richard Mills <[email protected]<mailto:[email protected]>> Cc: [email protected]<mailto:[email protected]>; Klaij, Christiaan <[email protected]<mailto:[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]<mailto:[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]<mailto:[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]<mailto:[email protected]> web www.vortech.nl<http://www.vortech.nl> ____________________________________________________________________ <timers.tar.gz> <0001-ascii_xml-logging-fixes-to-nested-tree-generation-an.patch>
