Re: May nearly have simple statistical profiler working (need help).

[Rob Browning]

Neil Jerram <address@hidden> writes:

> Actually, having looked at your code, I see that this could be the
> problem.  `(make-stack #t)' will give you a stack from the current
> code position right back up to the most recent `(start-stack ...)'
> expression.  For code executed from the REPL, this means everything
> back up to the `(start-stack 'repl-stack ...)' in scm-style-repl/-eval
> at line 2502 in boot-9.scm.
> 
> Apply frame traps, on the other hand, are active within the dynamic
> scope of the `with-traps' expression in error-catching-loop at line
> 2268.  So, since

I don't know if it matters, but I only use (trap-enable/disable
'apply-frame) where appropriate.  I don't fiddle with any other
evaluator/debugger options (well actually, I guess I do in my .guile
file...)

> and since error-catching-loop only calls its thunk inside with-traps,
> there will be a lot of applications for which the apply-frame trap
> will fire but which you'll never see in the stack from (make-stack
> #t).

I'm not sure this is an issue.  In my code the apply-frame trap is
only enabled whenever the profiler is active.  I turn it on in
statprof-start, and turn it off in statprof-stop.  (Actually, I also
turn it off during some critical sections inside the handlers, but
those should be balanced and transparent.)

> Another thing is that the apply-frame trap dispatch mechanism disables
> traps around the call to the trap handler.  So applications in and
> below the trap handler won't trap themselves but could be seen in a
> stack from (make-stack #t).

OK.  This I expected (though I coded defensively anyhow), but that's
not what confused me.

I found that (as an example) I saw accumulate-time counted 12 times by
the sampler (the profile timer thunk), but never by the apply-frame
handler.  That really confused me -- if you look at the code and
search for accumulate-time, it's only called in three places.

  - For the call from statprof-stop, statprof-stop is only called once
    in my test (at the end), so I'd be surprised to see accumulate
    time show up multiple (12) times in the sample count from that.

  - For the call from count-call, the sampler will only sample if
    inside-apply-trap? is false, and inside-apply-trap? is set to #t
    by count call in a section that's protected from the profiling
    timer (via mask-signals) right at the top.  So this call to
    accumulate-time should *never* show up in the sample count.

  -  For the call from profile-signal-handler, the handler is only
     reinstalled once the handler finishes so we don't have to worry
     about calls stacking, and if they're not stacking, I don't see
     how this call to accumulate time could ever end up on the stack
     for this profile handler to count.

So I don't know how I'm ending up with 12 samples of accumulate time.
(I'm not surprised I don't get any counts from the apply-frame handler
-- I tried to make sure that would be true...)

> What you need is consistent stack narrowing.  Instead of `(make-stack
> #t)', you can write `(make-stack #t INNER-PROC OUTER-PROC)'.
> INNER-PROC and OUTER-PROC are both procedures, and then make-stack
> basically cuts away all inner frames from the current code position up
> to and including INNER-PROC, and all outer frames from the
> `(start-stack ...)' down to and (I think) including OUTER-PROC.  (See
> comments in stacks.c for more details.)



> In fact I think you only need INNER-PROC.  In your
> `profile-signal-handler', you should do `(make-stack #t
> profile-signal-handler)' -- note that this obsoletes the
> (caller-stack-num 2) hack. Similarly, in `count-call', do
> `(make-stack #t count-call)' rather than creating the stack from the
> passed continuation.  Now you know that all your stacks extend from
> `(start-stack 'repl-stack ...)' down to the innermost non-profiling
> code.

Ahh.  That sounds far better.

> Finally, to solve the problem of apply-frame traps inbetween
> `with-traps' and `(start-stack 'repl-stack ...)', you could check in
> the apply-frame handler that (eq? (stack-id #t) 'repl-stack).
> (Outside 'repl-stack, I believe that (stack-id #t) returns #f.)

I'm not sure I quite understand the problem this fixes yet.

> (In future you might want to provide an interface like
> `(statprof-profile THUNK)' to do profiling for THUNK.  In this case,
> you could use the OUTER-PROC to specify statprof-profile itself, or
> perhaps THUNK; or you could start a new stack within the
> implementation of statprof-profile: `(start-stack 'profile-stack
> (THUNK))'.)

Right, not a bad idea really.  I'd kind of wanted to keep the
"start/stop anywhere" model, but I suppose that might not be critical.

> PS.  ISTR that Keisuke had some profiling code too; is your code
> related to his?

Nope.  AFAIK, I'm the only one working on a statistical profiler right
now.  I started trying to make an exact profiler, but I realized that
that wouldn't work the way I wanted for tail-recursive code.  The way
I was implementing the profiler, it would have killed tail-recursions
and explode the stack.  (Not a very non-intrusive profiler really :>).

Thanks very much for the feedback and help.

-- 
Rob Browning
rlb @defaultvalue.org, @linuxdevel.com, and @debian.org
Previously @cs.utexas.edu
GPG=1C58 8B2C FB5E 3F64 EA5C  64AE 78FE E5FE F0CB A0AD