On Aug 4, 2016, at 5:01 PM, Koos Huijssen <koos.huijs...@vortech.nl> 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 <koos.huijs...@vortech.nl>
Subject: Fwd: [petsc-dev] Nested event logging and human friendly
output
Begin doorgestuurd bericht:
Van: Barry Smith <bsm...@mcs.anl.gov>
Datum: 17 juli 2016 04:44:04 CEST
Aan: Koos Huijssen <koos.huijs...@vortech.nl>
Kopie: Richard Mills <richardtmi...@gmail.com>,
"petsc-dev@mcs.anl.gov" <petsc-dev@mcs.anl.gov>, "Klaij, Christiaan"
<c.kl...@marin.nl>, "Bas van 't Hof" <bas.vant...@vortech.nl>
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 <koos.huijs...@vortech.nl> 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 koos.huijs...@vortech.nl
web
https://emea01.safelinks.protection.outlook.com/?url=www.vortech.nl&data=02%7C01%7Ckoos.huijssen%40vortech.nl%7Cf467bc9cbee84636730208d58b2c45c1%7C5fe8f8070fe44cdf8dc636475a0b8555%7C0%7C0%7C636567944636671153&sdata=TIwKTlC0%2FBVOWA6TXzQQKkPUcMYhsAmKagm0W9MXPg8%3D&reserved=0
-----Oorspronkelijk bericht-----
Van: Barry Smith [mailto:bsm...@mcs.anl.gov]
Verzonden: maandag 6 juni 2016 17:21
Aan: Koos Huijssen
CC: Richard Mills; petsc-dev@mcs.anl.gov; 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 <koos.huijs...@vortech.nl> 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:bsm...@mcs.anl.gov]
Sent: zondag 5 juni 2016 1:19
To: Koos Huijssen <koos.huijs...@vortech.nl>; Richard Mills
<richardtmi...@gmail.com>
Cc: petsc-dev@mcs.anl.gov; Klaij, Christiaan <c.kl...@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
https://emea01.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.mcs.anl.gov%2Fpetsc%2Fdocumentation%2Ffaq.html&data=02%7C01%7Ckoos.huijssen%40vortech.nl%7Cf467bc9cbee84636730208d58b2c45c1%7C5fe8f8070fe44cdf8dc636475a0b8555%7C0%7C0%7C636567944636671153&sdata=7qyvMdTARqZ%2Fj2F3dyI27vL4eaTUFZ9RJPonqdl5fcY%3D&reserved=0
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
https://emea01.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.mcs.anl.gov%2Fpetsc%2Fdocumentation%2Ffaq.html&data=02%7C01%7Ckoos.huijssen%40vortech.nl%7Cf467bc9cbee84636730208d58b2c45c1%7C5fe8f8070fe44cdf8dc636475a0b8555%7C0%7C0%7C636567944636671153&sdata=7qyvMdTARqZ%2Fj2F3dyI27vL4eaTUFZ9RJPonqdl5fcY%3D&reserved=0
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 <bsm...@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://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fbitbucket.org%2Fpetsc%2Fpetsc%2Fcommits%2Fbb1d7374b64f295b2ed5ff23b894&data=02%7C01%7Ckoos.huijssen%40vortech.nl%7Cf467bc9cbee84636730208d58b2c45c1%7C5fe8f8070fe44cdf8dc636475a0b8555%7C0%7C0%7C636567944636671153&sdata=FwS%2FOWxWFpeBNYTYWoROFjewhf304uPHdZKAYxQqGZA%3D&reserved=0
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 <koos.huijs...@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.huijs...@vortech.nl
web
https://emea01.safelinks.protection.outlook.com/?url=www.vortech.nl&data=02%7C01%7Ckoos.huijssen%40vortech.nl%7Cf467bc9cbee84636730208d58b2c45c1%7C5fe8f8070fe44cdf8dc636475a0b8555%7C0%7C0%7C636567944636671153&sdata=TIwKTlC0%2FBVOWA6TXzQQKkPUcMYhsAmKagm0W9MXPg8%3D&reserved=0
____________________________________________________________________
<timers.tar.gz>
<0001-ascii_xml-logging-fixes-to-nested-tree-generation-an.patch>
