There appears to be an error indicated by valgrind at:
ftp://ftp.mcs.anl.gov/pub/petsc/nightlylogs/archive/2016/08/04/examples_master_arch-linux-pkgs-valgrind_grind.log
Note that the nstPath[] arrays only seem to filled up to but not including
depth but the "same" loop has j<=depth. Could you please clarify how I should
fix this?
if (i<nTimers) {
for (j=0; j<tree[i].depth; j++) nstMyPath[j] =
tree[i].nstPath[j];
for (j=tree[i].depth; j<depth; j++) nstMyPath[j] = illegalEvent;
} else {
for (j=0; j<depth; j++) nstMyPath[j] = illegalEvent;
}
/* Communicate with other processes to obtain the next path and its depth
*/
ierr = MPIU_Allreduce(nstMyPath, nstPath, depth, MPI_INT, MPI_MIN,
comm);CHKERRQ(ierr);
for (j=depth-1; (int) j>=0; j--) {
if (nstPath[j]==illegalEvent) depth=j;
}
if (depth>0) {
/* If the path exists */
/* check whether the next path is the same as this process's next path
*/
same = PETSC_TRUE;
for (j=0; same && j<=depth; j++) { same = (same && nstMyPath[j] ==
nstPath[j]) ? PETSC_TRUE : PETSC_FALSE;}
> On Aug 4, 2016, at 5:01 PM, Koos Huijssen <[email protected]> wrote:
>
> 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]>
> Datum: 17 juli 2016 04:44:04 CEST
> Aan: Koos Huijssen <[email protected]>
> Kopie: Richard Mills <[email protected]>, "[email protected]"
> <[email protected]>, "Klaij, Christiaan" <[email protected]>, "Bas van 't
> Hof" <[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]> 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>
