Help in understanding -log_summary output

[Barry Smith]

On Jul 28, 2008, at 12:16 AM, Rafael Santos Coelho wrote:

> Hi all
>
> Lately, I've been working on this article which covers the design  
> principles that guide the development of the PETSc library and also  
> the main functionalities it offers for the solution of PDEs. One of  
> the things I've pointed out are the profiling capabilities that  
> PETSc includes.
>
> I need some help to properly interpret the output from the '- 
> log_summary' command line option, especially its "phase summaries  
> section". I've read the documentation a few times but I still have  
> difficulties in grasping the meaning of the percentages of the  
> statistics (T, R, L and M). For instance, the following line
>
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Phase   Count      Time (sec)           Flops/ 
> sec                                                       --- Global  
> ---            --- Stage ---           Total
>                        Max    Ratio         Max    Ratio       
> Mess     Avg len    Reduct   %T %F %M %L %R %T %F %M %L %R Mflop/s
> -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> (...)
>
> --- Event Stage 5: KSPSolve 1
> MatMult   56   1.199e+00 1.1     5.3e+07 1.0     1.1e+03 4.2e+03 0.0e 
> +00  5   28    99   23  0   30   28   99   99    0    201
>
> (...)
>
>
> indicates that the 'MatMult' routine was called 56 times, a total of  
> 1.1e+03 messages were sent, with an average length of 4.2e+03 bytes,  
> and there were no global reductions, right?
>
> Now, what about the "--- Global ---" and "--- Stage ---" columns?  
> What do those percentages really say?

   Global gives the percentage of the  time/flops/messages/total  
message data/reductions in this event out of the TOTAL RUNTIME  
(basically from
PetscInitialize() to PETScFinalize(). So 5 percent of the total  
runtime was in this event and 99 percent of the messages (99 is  
rounded down from 100
so it is probably essentially 100%). The stage gives the percentage of  
these things out of the total of these things in that stage.  For  
example the MatMult()
is taking 30 percent of the time in the stage. (The numbers in the  
stage will be at least as large as in the global).

> Is it possible to estimate how much time the overall program  
> execution spent performing floating point operations and inter- 
> process communication by looking exclusively at the output?

   Not always, but sometimes pretty close. Looking just at the  
MatMult() line doesn't tell use how much of that time is
communication and how much is floating point. But if you know that  
MatMult() does ALL its communication inside VecScatterBegin/End() you
can say the communication time is the time inside VecScatterBegin/ 
End() and the floating point time is the MatMult() time minus
the VecScatter time. This assumes that the VecScatters are not being  
used for something else also. For example with the ASM preconditioners
there is also VecScatters. So if you used ASM you could not know how  
much time was spent in the multiply for communication but you would
know the communication time of the multiply AND ASM is the time in the  
scatters and the floating point time in the multiply AND ASM is the
time for multiply + asm - the time for the scatters.

    Barry

>
>
> Thanks in advance,
>
> Rafael
>
>
>
>