Issues using statprof (no samples taken)

Issues using statprof (no samples taken)

[Boris Zbarsky]

I'm having a bit of a problem with using statprof.  I checked it out 
from CVS (:pserver:anonymous@cvs.savannah.gnu.org:/sources/guile 
CVSROOT, guile/guile-statprof module).  I left it in the checkout tree, 
and am using GUILE_LOAD_PATH to point to the files.

I am using guile 1.6.8 on Mac OS X, installed via Macports.

A simple test program that looks like this:

  (use-modules (ice-9 statprof))
  (debug-enable 'debug)
  (trap-enable 'traps)
  (statprof-reset 0 500)
  (statprof-start)
  (something-to-profile)
  (statprof-stop)
  (statprof-display)

works just fine when run as:

   env GUILE_LOAD_PATH=/path/to/statprof guile16 -s ~/test.scm

and outputs profiling information.

However, what I really want to profile is a gnucash report.  If I add 
the relevant lines to the gnucash report (use-modules, debug-enable, 
trap-enable at toplevel, the rest around the part I actually want to 
profile), and run gnucash with the GUILE_LOAD_PATH set, then 
statprof-display errors out.  It does this because statprof-sample-count 
is 0 (so it ends up with a divide-by-0 error).

The operation I'm trying to profile in gnucash takes about 40 seconds, 
so sampling at 0.5ms as above should certainly be producing samples. 
Statprof is certainly being found, since the statprof-start calls don't 
error out.

Any ideas as to where I should look for what's going on here and why no 
samples are being taken?  Could it have something to do with the way 
guile is loaded by the gnucash binary?  Or with something the binary 
itself is doing?

Thank you in advance for any help,
Boris

Re: Issues using statprof (no samples taken)

[Ludovic Courtès]

Hello,

Boris Zbarsky <bzbarsky@MIT.EDU> writes:

> I'm having a bit of a problem with using statprof.  I checked it out
> from CVS (:pserver:anonymous@cvs.savannah.gnu.org:/sources/guile
> CVSROOT, guile/guile-statprof module).  I left it in the checkout
> tree, and am using GUILE_LOAD_PATH to point to the files.

Beware, Guile's CVS repository is no longer used, so software in there
is essentially unmaintained.

As far as `statprof' is concerned, I would recommend using the one
available in Guile-Lib, since it's been maintained there for some time:
http://home.gna.org/guile-lib/ .  I've used it successfully with 1.8 in
the past.

> I am using guile 1.6.8 on Mac OS X, installed via Macports.

Is there any particular reason why you don't use 1.8.x?

> Any ideas as to where I should look for what's going on here and why
> no samples are being taken?  Could it have something to do with the
> way guile is loaded by the gnucash binary?  Or with something the
> binary itself is doing?

Can you check whether SIGPROF is actually delivered and whether
`profile-signal-handler' gets called, e.g., by adding a `(display
"foo\n")' call there?

Thanks,
Ludo'.

Re: Issues using statprof (no samples taken)

[Boris Zbarsky]

Ludovic Courtès wrote:
> Beware, Guile's CVS repository is no longer used, so software in there
> is essentially unmaintained.
> 
> As far as `statprof' is concerned, I would recommend using the one
> available in Guile-Lib, since it's been maintained there for some time:
> http://home.gna.org/guile-lib/

Thanks for that pointer!  I'd seen documentation for this version of 
statprof at http://wingolog.org/software/guile-lib/statprof/ but that 
didn't have any links to the guile-lib download.  It might be worth 
updating 
http://www.gnu.org/software/guile/docs/faq/guile-faq.html#Is-there-a-Scheme-code-profiler-that-works-with-Guile_003f 
with the new location, maybe.

Unfortunately, this version still has the issue I ran into.

>> I am using guile 1.6.8 on Mac OS X, installed via Macports.
> 
> Is there any particular reason why you don't use 1.8.x?

Yes.  As my original mail said, 1.6.8 is what gnucash is compiled 
against and uses in this case, and I'm trying .  I don't see an obvious 
way to change that without trying to recompile gnucash with some sort of 
modifications, which I'd rather avoid having to mess with if I can.

> Can you check whether SIGPROF is actually delivered and whether
> `profile-signal-handler' gets called, e.g., by adding a `(display
> "foo\n")' call there?

profile-signal-handler is not getting called.  I do see a SIGPROF 
delivered to the gnucash-bin process (using 'handle SIGPROF stop' in gdb 
after attaching to the gnucash-bin process), but only once during the 
entire report generation.  I also see scm_setitimer called in gdb at a 
point in the scheme code that matches the call to (statprof-start), and 
I see it called again at the point that matches (statprof-stop).  The 
single SIGPROF delivered comes soon after that first setitimer call.

So sounds like something is capturing the SIGPROF, I guess, so we never 
get that first sample and never reset the profiling timer.

I don't see any obvious sigaction() or signal() calls in the gnucash 
source tree, unfortunately.  Maybe they're hidden away in some sort of 
API calls gnucash makes...  Is there any way to tell in gdb which signal 
handler is actually getting called for the signal?  Or something else I 
should grep for in the gnucash source?

Thank you again,
Boris

Re: Issues using statprof (no samples taken)

[Ludovic Courtès]

Hi,

Boris Zbarsky <bzbarsky@MIT.EDU> writes:

> profile-signal-handler is not getting called.  I do see a SIGPROF
> delivered to the gnucash-bin process (using 'handle SIGPROF stop' in
> gdb after attaching to the gnucash-bin process), but only once during
> the entire report generation.  I also see scm_setitimer called in gdb
> at a point in the scheme code that matches the call to
> (statprof-start), and I see it called again at the point that matches
> (statprof-stop).  The single SIGPROF delivered comes soon after that
> first setitimer call.

GDB supposedly shows all SIGPROFs that are raised, so if it shows only
one, then something's wrong.  Can you check the arguments passed to
`setitimer(2)' to make sure it makes sense?  Perhaps you could also try
increasing the sampling frequency, although that's arguably not
required.

Another (remote) possibility could be that the Scheme-level handler is
not called, even though the C handler in libguile is called, since
Scheme-level signal handlers are actually asyncs (info "(guile)
Asyncs").  You can try to force the execution of asyncs by adding a call
like "(select '() '() '() 0)" (technically, it invokes `SCM_TICK', which
runs asyncs).

One last thing would be to check whether `HAVE_SIGACTION' is defined in
Guile's <config.h> on your platform, to see which version of
`scm_sigaction_for_thread ()' is used.

Thanks,
Ludo'.

Re: Issues using statprof (no samples taken)

[Boris Zbarsky]

Ludovic Courtès wrote:
> GDB supposedly shows all SIGPROFs that are raised, so if it shows only
> one, then something's wrong.

Sure.  The wrong thing is that profile-signal-handler is not called, so 
never resets the timer, so no more SIGPROFs.  Unless I'm misreading the 
code.

> Can you check the arguments passed to `setitimer(2)' to make sure it makes sense?

I can't check the values in the structs it's passed, unfortunately (no 
symbols here for guile or the libc).

> Perhaps you could also try
> increasing the sampling frequency, although that's arguably not
> required.

I'm sampling every 500us, so I doubt that's the issue.  The task I'm 
profiling takes 20 seconds.

> Another (remote) possibility could be that the Scheme-level handler is
> not called, even though the C handler in libguile is called, since
> Scheme-level signal handlers are actually asyncs (info "(guile)
> Asyncs").  You can try to force the execution of asyncs by adding a call
> like "(select '() '() '() 0)" (technically, it invokes `SCM_TICK', which
> runs asyncs).

Where would I add that?  For that matter, what's the C handler in 
libguile?  I should be able to breakpoint on that and see whether it's 
called, hopefully...

Note that I'm just using the statprof.scm from guile-lib

> One last thing would be to check whether `HAVE_SIGACTION' is defined in
> Guile's <config.h> on your platform, to see which version of
> `scm_sigaction_for_thread ()' is used.

Yes, HAVE_SIGACTION is defined (to 1).

-Boris

Re: Issues using statprof (no samples taken)

[Ludovic Courtès]

Hello,

Boris Zbarsky <bzbarsky@MIT.EDU> writes:

> Sure.  The wrong thing is that profile-signal-handler is not called,
> so never resets the timer, so no more SIGPROFs.  Unless I'm misreading
> the code.

Oh, right.

> I can't check the values in the structs it's passed, unfortunately (no
> symbols here for guile or the libc).

Maybe with `strace(1)' or similar?

>> Another (remote) possibility could be that the Scheme-level handler is
>> not called, even though the C handler in libguile is called, since
>> Scheme-level signal handlers are actually asyncs (info "(guile)
>> Asyncs").  You can try to force the execution of asyncs by adding a call
>> like "(select '() '() '() 0)" (technically, it invokes `SCM_TICK', which
>> runs asyncs).
>
> Where would I add that?

In some Scheme code that is run regularly.

BTW, is Gnucash multithreaded?

> For that matter, what's the C handler in
> libguile?  I should be able to breakpoint on that and see whether it's
> called, hopefully...

It's `take_signal ()' (scmsigs.c), at least in 1.8.x.

Hope this helps,
Ludo'.

Re: Issues using statprof (no samples taken)

[Boris Zbarsky]

Ludovic Courtès wrote:
>> I can't check the values in the structs it's passed, unfortunately (no
>> symbols here for guile or the libc).
> 
> Maybe with `strace(1)' or similar?

Unfortunately, that just shows the pointer to the struct, not the value 
in the struct itself....

>>> Another (remote) possibility could be that the Scheme-level handler is
>>> not called, even though the C handler in libguile is called, since
>>> Scheme-level signal handlers are actually asyncs (info "(guile)
>>> Asyncs").  You can try to force the execution of asyncs by adding a call
>>> like "(select '() '() '() 0)" (technically, it invokes `SCM_TICK', which
>>> runs asyncs).
>> Where would I add that?
> 
> In some Scheme code that is run regularly.

I tried adding that call to code that certainly runs repeatedly between 
statprof-start and statprof-stop (the code that handles updating the 
gnucash progress bar, in fact), but that doesn't seem to help.

> BTW, is Gnucash multithreaded?

I'm not sure.  It does update the UI during execution of guile code 
(progress indicator, and so forth), but that could also be accomplished 
if the guile interpreter makes some sort of periodic callbacks into the 
embedding.  They link to pthread, but don't seem to really use it for 
anything...

>> For that matter, what's the C handler in
>> libguile?  I should be able to breakpoint on that and see whether it's
>> called, hopefully...
> 
> It's `take_signal ()' (scmsigs.c), at least in 1.8.x.

Yeah, that's called for SIGPROF in this case.  But the scheme handler is 
still not called, even with the (select '() '() '() 0) calls as above.

-Boris

Re: Issues using statprof (no samples taken)

[Ludovic Courtès]

Hi,

Boris Zbarsky <bzbarsky@MIT.EDU> writes:

> Ludovic Courtès wrote:

>> Maybe with `strace(1)' or similar?
>
> Unfortunately, that just shows the pointer to the struct, not the
> value in the struct itself....

Under GNU/Linux it does the right thing.  :-)

> I tried adding that call to code that certainly runs repeatedly
> between statprof-start and statprof-stop (the code that handles
> updating the gnucash progress bar, in fact), but that doesn't seem to
> help.

Are you sure that piece of code is ever called?  Is it called from an
"idle" handler or some such?

Another idea is that you could try modifying `statprof' so that it uses

  (setitimer ITIMER_REAL ...)

and

  (sigaction SIGALRM profile-signal-handler)

just to see if it makes a difference...

> I'm not sure.  It does update the UI during execution of guile code
> (progress indicator, and so forth), but that could also be
> accomplished if the guile interpreter makes some sort of periodic
> callbacks into the embedding.  They link to pthread, but don't seem to
> really use it for anything...

It may be that they use a single pthread (the "main" thread), and that
they handle events and timeouts via a GTK+ even loop.  Can you check
with GDB whether `pthread_create(3)' is ever called?

> Yeah, that's called for SIGPROF in this case.  But the scheme handler
> is still not called, even with the (select '() '() '() 0) calls as
> above.

That's weird, but I don't have any other idea.  Now, I'm thinking about
how 1.8 works, so it might be that there are subtle differences with
1.6.

Thanks,
Ludo'.

Re: Issues using statprof (no samples taken)

[Boris Zbarsky]

Ludovic Courtès wrote:
>>> Maybe with `strace(1)' or similar?
>> Unfortunately, that just shows the pointer to the struct, not the
>> value in the struct itself....
> 
> Under GNU/Linux it does the right thing.  :-)

Ah, cool.  I'll dig up my Linux machine at some point to double-check 
this if I exhaust all other possibilities.

>> I tried adding that call to code that certainly runs repeatedly
>> between statprof-start and statprof-stop (the code that handles
>> updating the gnucash progress bar, in fact), but that doesn't seem to
>> help.
> 
> Are you sure that piece of code is ever called?

Absolutely.  Adding display statements there prints stuff.

> Is it called from an "idle" handler or some such?

Not that I can tell.  More precisely, the code now looks more or less 
like this:

(statprof-reset 0 500 #t)
(statprof-start)
(set! foo (map (lambda (bar) (body)) myList))
(statprof-stop)
(statprof-display)

where (body) includes the (select) calls you suggested.

> Another idea is that you could try modifying `statprof' so that it uses
> 
>   (setitimer ITIMER_REAL ...)
> 
> and
> 
>   (sigaction SIGALRM profile-signal-handler)
> 
> just to see if it makes a difference...

That doesn't seem to have any effect.  Interestingly, if I change the 
setitimer call but NOT the sigaction call I see the program terminate 
with an uncaught SIGPROF...  So clearly the sigaction is having _some_ 
effect.  Just not that of calling the handler.  ;)

> It may be that they use a single pthread (the "main" thread), and that
> they handle events and timeouts via a GTK+ even loop.

Quite possible, yes.

> Can you check with GDB whether `pthread_create(3)' is ever called?

Yes, it is, with this stack:

(gdb) where
#0  0x91df0f80 in pthread_create ()
#1  0x016c5ac3 in g_thread_create_posix_impl ()
#2  0x01772f93 in g_thread_create_full ()
#3  0x0174686a in g_child_watch_source_init_multi_threaded ()
#4  0x01746a15 in g_child_watch_source_new ()
#5  0x01746a57 in g_child_watch_add_full ()
#6  0x01746b1f in g_child_watch_add ()
#7  0x003459f3 in gnc_spawn_process_async ()
#8  0x0033412b in _wrap_gnc_spawn_process_async ()
#9  0x0161a312 in scm_deval ()
#10 0x01616364 in scm_deval ()
#11 0x0161bc27 in scm_dapply ()
#12 0x01611ee7 in scm_apply ()
#13 0x01611c20 in scm_call_0 ()
#14 0x01602b2c in scm_dynamic_wind ()
#15 0x0161aa96 in scm_deval ()
#16 0x01615f6a in scm_deval ()
#17 0x01613727 in scm_i_eval_x ()
#18 0x016137fb in scm_primitive_eval_x ()
#19 0x01665cd6 in inner_eval_string ()
#20 0x0161de4d in scm_c_with_fluids ()
#21 0x0161dec6 in scm_c_with_fluid ()
#22 0x01637baf in scm_c_call_with_current_module ()
#23 0x01665d4a in scm_eval_string ()
#24 0x01665c5c in scm_c_eval_string ()
#25 0x00003961 in inner_main ()
#26 0x016331f9 in invoke_main_func ()
#27 0x016331a4 in scm_boot_guile_1 ()
#28 0x01632eb1 in scm_boot_guile ()
#29 0x000042a2 in main ()

That seems to be the only pthread_create call.  Looking through the 
gnucash source, the gnc-spawn-process-async call seems to be spinning up 
a separate process (well, thread in this case) to handle getting price 
quotes over the network...

-Boris

Re: Issues using statprof (no samples taken)

[Ludovic Courtès]

Hello,

Boris Zbarsky <bzbarsky@MIT.EDU> writes:

> That doesn't seem to have any effect.  Interestingly, if I change the
> setitimer call but NOT the sigaction call I see the program terminate
> with an uncaught SIGPROF...  So clearly the sigaction is having _some_
> effect.  Just not that of calling the handler.  ;)

Aaarg.

> That seems to be the only pthread_create call.  Looking through the
> gnucash source, the gnc-spawn-process-async call seems to be spinning
> up a separate process (well, thread in this case) to handle getting
> price quotes over the network...

Then it must be disappointed these days...  ;-)

Anyway, nothing to worry about.

However, it would help if you used 1.8, as I'm not sure exactly how 1.6
differs in that respect.  According to
https://bugs.gentoo.org/show_bug.cgi?id=165492 , it is feasible to just
switch to 1.8 and keep GnuCash happy.

Thanks,
Ludo'.

Re: Issues using statprof (no samples taken)

[Boris Zbarsky]

Ludovic Courtès wrote:
> Boris Zbarsky <bzbarsky@MIT.EDU> writes:
>> That doesn't seem to have any effect.  Interestingly, if I change the
>> setitimer call but NOT the sigaction call I see the program terminate
>> with an uncaught SIGPROF...  So clearly the sigaction is having _some_
>> effect.  Just not that of calling the handler.  ;)
> 
> Aaarg.

That's about how I feel.

> However, it would help if you used 1.8, as I'm not sure exactly how 1.6
> differs in that respect.  According to
> https://bugs.gentoo.org/show_bug.cgi?id=165492 , it is feasible to just
> switch to 1.8 and keep GnuCash happy.

I'll see if I can manage this, but 
http://wiki.gnucash.org/wiki/MacOSX/MacPortsDetail#guile_1.8.1 doesn't 
fill me with hope.  It'll certainly involve me hacking around in the 
Macports gnucash and recompiling it to look for "guile" as oppposed to 
"guile16" at the very least...  It also sounds like I'll need to compile 
guile 1.8 with some non-default options, at least according to those 
gentoo bug reports.  :(

-Boris