This is the mail archive of the guile@cygnus.com mailing list for the guile project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]

Re: Dramatic speed drop-off bug, part 2


Jon Trowbridge <trow@emccta.com> writes:


[snip: slowdowns]

> 
> I've continued to explore the problem, and it appears to be tied to
> garbage collection.
> 
> In my extended guile, I define and execute the following procedure:
> (define (loop)
>    (execute-a-trivial-simulator-command)
>    (display (gc-stats))
>    (newline)
>    (loop))
> 
> The execute-a-trivial-simulator-command just constructs a smob-ified
> version of a small, simple C++ object and returns it... there is
> nothing fancy going on in that code, and it is small enough to
> carefully inspect for errors, buffer overflows, etc. --- which I have
> done.  As far as I can discern, there is nothing dangerous or tricky
> in there.
> 
> This works fine for a large number of iterations, until I get the
> following (I've broken up the lines and added whitespace to make the
> display less convoluted):

[a little snippage] 
> ((gc-time-taken . 45) (cells-allocated . 41282)
>  (cell-heap-size . 98304) (bytes-malloced . 4294925671) ***** Yikes!
>  (gc-malloc-threshold . 2147421210)                     ***** Double Yikes!
>  (cell-heap-segments (1077948424 . 1077686280) (1078485000 . 1077960712)))

Ick. It looks like scm_mallocated is being underflowed. It could be
the simple case that scm_done_malloc is being called with too large a
size, or that an smob free function isn't returning an accurate value,
so you might want to make sure that you're returning the correct
values from your smob free functions (this should be the amount of
malloc storage freed).

> 
> Notice how when the bytes-malloced and gc-malloc-threshold suddenly
> get huge, the gc-time-taken starts going up by about 42 units per
> iteration.  Letting the loop keep running, this value stays constant.
>
> When I run this test and get the slow-down effect, the change in
> gc-time-taken per iteration (after slow-down) is always
> constant... but it is a different value each time.  It seems to range
> between 25-50.  Also, this slow-down seems to be a one-shot
> affair... I can let the slowed-down loop run for a very long time, and
> the differences stay constant.

Not that it's really relevant (since smobs are likely the offending
parties), but this is to be expected. What happens with a large
bytes_mallocated like that is that every call to scm_must_malloc
causes a gc. Since the gc is scanning&sweeping pretty much the same
objects every time (- whatever's created by the execute-foo command),
the time should be around the same.

> BTW, if I terminate the loop with ctrl-c and get back into the shell,
> typing (gc) always returns immediately.  But the execution of any
> scheme program (even simple ones that have nothing to do with my
> simulation extensions) is dramatically slowed down.

This happens when you gc almost constantly ;)

-- 
Greg