[petsc-dev] Nested event logging and human friendly output

Mon Jun 6 08:14:33 CDT 2016

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:bsmith at mcs.anl.gov]
Sent: zondag 5 juni 2016 1:19
To: Koos Huijssen <koos.huijssen at vortech.nl>; Richard Mills <richardtmills at gmail.com>
Cc: petsc-dev at mcs.anl.gov; Klaij, Christiaan <C.Klaij at marin.nl>
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[cid:image002.png at 01D1C006.1C194550]015, at 10:09 PM, Barry Smith <bsmith at mcs.anl.gov<mailto:bsmith at mcs.anl.gov>> 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/bb1d7374b64f295b2ed5ff23b89435d65e905a54?at=master you 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 <koos.huijssen at vortech.nl<mailto:koos.huijssen at vortech.nl>> 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 koos.huijssen at vortech.nl<mailto:koos.huijssen at vortech.nl>
web   www.vortech.nl<http://www.vortech.nl>
____________________________________________________________________

<timers.tar.gz>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mcs.anl.gov/pipermail/petsc-dev/attachments/20160606/acf1173e/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image002.png
Type: image/png
Size: 304572 bytes
Desc: image002.png
URL: <http://lists.mcs.anl.gov/pipermail/petsc-dev/attachments/20160606/acf1173e/attachment.png>