Reporting cpu times to profile KSPSolve (and others)

[Matthew Knepley]

On Fri, May 9, 2008 at 1:09 AM, Dave May <dave.mayhem23 at gmail.com> wrote:
> Hey Matt,
>     All I want to be able to do is generate plots of |r|/|r0| vs cpu time. I
> presumed that such information is commonly required when profiling the
> performance of solvers, so I thought it might be something you'd consider
> adding support for.

Here is what I do right now: You could use any event (like KSPSolve)

    ALE::LogStagePush(stage);
    ierr = PetscLogEventBegin(restrictEvent,0,0,0,0);
    <Do stuff>
    ierr = PetscLogEventEnd(restrictEvent,0,0,0,0);
    ALE::LogStagePop(stage);
    StageLog     stageLog;
    EventPerfLog eventLog;

    ierr = PetscLogGetStageLog(&stageLog);
    ierr = StageLogGetEventPerfLog(stageLog, stage, &eventLog);
    EventPerfInfo eventInfo = eventLog->eventInfo[restrictEvent];

    CPPUNIT_ASSERT_EQUAL(eventInfo.count, 1);
    CPPUNIT_ASSERT_EQUAL((int) eventInfo.flops, 0);
    if (this->_debug) {
      ierr = PetscPrintf(this->_section->comm(), " Average time per
restrictPoint: %gs\n", eventInfo.time/(numPoints*this->_iters));
    }
    CPPUNIT_ASSERT((eventInfo.time <  maxTimePerRestrict * numPoints *
this->_iters));

I hesitate to add the history thing because it seems to put redundant
info into the
KSP, and it woul dbe meaningless if logging is turned off. Maybe there
should be a
history mechanism in the logging. Right now it is completely based
upon aggregation.

   Matt

> Cheers,
>     Dave
>
> On Fri, May 9, 2008 at 1:19 PM, Matthew Knepley <knepley at gmail.com> wrote:
> >
> >
> >
> > On Thu, May 8, 2008 at 10:09 PM, Dave May <dave.mayhem23 at gmail.com> wrote:
> > > Hey petsc folk,
> > >     What is the best way to obtain timing information to profile the
> > > performance
> > > of KSPSolve (or SNESSolve)? Currently I have written some specific KSP
> > > monitors,
> > > but it I think it would be useful to have access to this information all
> the
> > > time without
> > >  having to go through the monitor. It seems like each object should know
> how
> > > to time
> > > some of its operations.
> > >
> > > It would be very useful to have functions such as
> > >   KSPGetCPUTime(KSP ksp,PetscLogDouble *time)
> > >  to report the total solution time required by the KSPSolve() and
> > >   KSPGetCPUTimeHistory(KSP ksp,PetscLogDouble *time[],PetscInt *na)
> > > which is like KSPGetResidualHistory() but returns the accumulated cpu
> time
> > > for each
> > >  iterate
> > >
> > > It would also be useful to have a default KSP monitor which could report
> the
> > > time per iterate
> > > or accumulate time. For example something like
> > >   40 KSP Residual norm 1.519638506430e-01 Time 1.000000000000e-03
> > >    41 KSP Residual norm 1.510346481853e-01 Time 1.510346481853e-02
> > >
> > > Is there a better approach to what I've been doing and are there plans
> to
> > > add any
> > > additional features to help profile individual operations on each
> object?
> >
> > Maybe you could motivate it by giving a use case? So far, I have never
> needed
> > anything but the KSPSolve() event and stages to separately aggregate
> different
> > types of solves.
> >
> >   Matt
> >
> > > Cheers,
> > >     Dave
> > --
> > What most experimenters take for granted before they begin their
> > experiments is infinitely more interesting than any results to which
> > their experiments lead.
> > -- Norbert Wiener
> >
> >
>
>



-- 
What most experimenters take for granted before they begin their
experiments is infinitely more interesting than any results to which
their experiments lead.
-- Norbert Wiener