Subject: [clisp-list] Lots o' garbage ...

From: "John K. Hinsdale" <[email-masked]>
Date: Mon Sep 16 13:17:03 2002

I've got a program that accesses a database and retrieves about 40,000
records (using the Oracle client lib I announced recently).

It's pretty sluggish - the same program written in perl DBI takes
about 1/20 th the time (i.e., it's 20x as long in Lisp).  I'm
surprised to see this and I'm trying to figure out why.

I think it is that my library is doing lots of consing and generating
a LOT of garbage for Lisp's GC to deal with (more on this below) So
I'm wondering: what's a good way to find the places in my code where
I'm consing and generating garbage?  Is there a "consing profiler"
type tool to do that?  I just read the chapter entitled "Speed" in
Graham's book "ANSI Common Lisp" and it says what functions to avoid
calling a lot, but I would rather be able to focus in on the hot spots
instead of having to laboriously rework all my newly debugged code ;)

Why do I think it's spending its time GC'ing?  I built CLISP with
gprof enabled, i.e., profiled at the "C" level, and my program gives
the top funcitons as:

    Each sample counts as 0.01 seconds.
      %   cumulative   self              self     total           
     time   seconds   seconds    calls   s/call   s/call  name    
     29.45     28.07    28.07     1498     0.02     0.04  gar_col_normal
     22.95     49.95    21.88  4556398     0.00     0.00  gc_mark
     12.16     61.54    11.59 139359175     0.00     0.00  objsize
      6.62     67.85     6.31 11624570     0.00     0.00  interpret_bytecode_
      1.54     69.32     1.47  2372121     0.00     0.00  allocate_iarray
      1.41     70.66     1.34 25267275     0.00     0.00  funcall
      1.31     71.91     1.25 10240813     0.00     0.00  funcall_closure
      0.87     72.74     0.83   355825     0.00     0.00  convert_from_foreign
      0.86     73.56     0.82 15026462     0.00     0.00  funcall_subr

Adding the first three lines, it appears to be spending over 60% of
its time doing GC.

Also notice the 25 million calls to "funcall" -- I tried to elminate
that by proclaiming ALL my Oracle package functions as "inline" as
well as "(declare (optimize (speed 3)))" etc.  I also built CLISP with
C compilation flags for maximum optimization (-O4)

Any ideas?  I know 40,000 records may seem a lot, but in database land
it really is not; the perl lib is 20x faster and I think I am doing
something naive with repsect to memory use (garbage). I'm trying to
figure out how to home in on where.

---
John Hinsdale, Alma Mater Software, Inc., Tarrytown, NY 10591-3710 USA
[email-masked] | http://www.alma.com/staff/hin | +1 914 631 4690

---

From: Kaz Kylheku <[email-masked]>
Date: Mon Sep 16 15:02:05 2002

> gprof enabled, i.e., profiled at the "C" level, and my program gives

[ snip ]

> Adding the first three lines, it appears to be spending over 60% of

There exists a freeware profiler for Lisp that is written in Lisp
and portable among implementations. Do a Google search for 
"lisp metering". CCLAN has this package; give it a try.

The Common Lisp TIME form may also be useful. Identify 
some code that you think is spending a lot of time, then
wrap it with (time ...). Then if you think you are on the
right trail, descend into the sub-expressions.

> C compilation flags for maximum optimization (-O4)

Note that incrementing beyond -O3 makes no difference. The GNU info
manual, at least, only describes the effect of -O0 through -O3.

---

From: "John K. Hinsdale" <[email-masked]>
Date: Mon Sep 16 15:10:02 2002

> There exists a freeware profiler for Lisp that is written in Lisp and
 > portable among implementations. Do a Google search for "lisp
 > metering". CCLAN has this package; give it a try.

Yes, as I remarked I did Google for it, but got a moldy version
sitting at CMU.  Maybe I'll drop them a note and just have them link
to the version at CLOCC.

 > The Common Lisp TIME form may also be useful. Identify some code that
 > you think is spending a lot of time, then wrap it with (time

I'm sure now it was reckless consing.  In the hour or since I've
posted, I've had a very positive and fruitful experience with
"metering.lisp" and was able to weed out nearly half of my consing and
double the speed, with prospects for speeding it up pretty much to
however fast I really want it.  I just wanted to get rid of the really
dumb stuff first, esp. since I've posted it for general use.

One thing is puzzling me: I've got a "C" function that returns an
array of structures (yes, that again ... :).  The profiler is showing
it does lots of consing.  That doesn't make sense since I am passing
back from "C" an array of Lisp structures.  No cons-cells involved,
right?  The declaration  is:

   (def-call-out oracle_row_values
          (:arguments (db c-pointer))
          (:return-type (c-array-ptr (c-ptr sqlval))))

The reason this matters is that I cannot re-work this part.

 >> that by proclaiming ALL my Oracle package functions as "inline" as

Actually I'm still curious about this.  Does CLISP respect "inline"
declarations?

---

---

From: Marco Baringer <[email-masked]>
Date: Mon Sep 16 15:37:01 2002

> Actually I'm still curious about this.  Does CLISP respect "inline"

nope.

-- 
-Marco
Ring the bells that still can ring.
Forget your perfect offering.
There is a crack in everything.
That's how the light gets in.
     -Leonard Cohen

---

From: Sam Steingold <[email-masked]>
Date: Tue Sep 17 06:37:03 2002

> * In message <[email-masked]>
> * On the subject of "[clisp-list] Lots o' garbage ..."
> * Sent on Mon, 16 Sep 2002 16:16:40 -0400
> * Honorable "John K. Hinsdale" <[email-masked]> writes:
>

CLOCC/src/tools/metering.lisp
and CLISP built-in SPACE macro
(see <http://clisp.cons.org/impnotes.html#space>
<http://clisp.cons.org/impnotes/environment-dict.html#space>)

> Adding the first three lines, it appears to be spending over 60% of

this is ugly.  usually the biggest hog is interpret_bytecode_().

> C compilation flags for maximum optimization (-O4)

CLISP does respect INLINE declarations when you compile a file.
CLISP ignores OPTIMIZE.

Alas, CLISP FFI is not too efficient.

Joerg-Cyril posted several interesting rants on the matter, but is yet
to fix this.  Prod him!

-- 
Sam Steingold (http://www.podval.org/~sds) running RedHat7.3 GNU/Linux
<http://www.camera.org> <http://www.iris.org.il> <http://www.memri.org/>
<http://www.mideasttruth.com/> <http://www.palestine-central.com/links.html>
Your mousepad is incompatible with MS Windows - your HD will be reformatted.

---

From: "John K. Hinsdale" <[email-masked]>
Date: Tue Sep 17 06:51:01 2002

> CLOCC/src/tools/metering.lisp

Got that; it's been very useful.

 > and CLISP built-in SPACE macro

Thanks I'll play with it if it comes to that

 > this is ugly.  usually the biggest hog is interpret_bytecode_().

It would appear at first, but after more thought I'm not surprised or
worried.  What I was running was an empty loop that did nothing but
retrieve results from the database and throw them away.  OF COURSE it
is going to have lots of overhead, consing and throwing away.  It is
only doing the relatively useless work of moving data around.

The real application is actually be doing some computation (making a
report, doing a calcuation on the data) and then the proportion of
time in interpret_bytecode will probably be reasonable.  For this case
what I WANTED was to perversely exercise the library overhead so I
could try to eliminate it, and that has worked.

So things are not so bad as I made them appear: it is as much the
nature of the benchmark, which elicits an unrealistic amount of
overhead.  If I profile a real app had this much GC so, then yes that
would be ugly.  What is the accepted amount of GC people are happy
with anyway?

 > CLISP does respect INLINE declarations when you compile a file.

Then I am missing something.  When I include my .lisp file as part of
an external module, is it not compiled when it is built?  I saw no
difference in funcall overhead, nor did the metering.lisp output
appear to reflect inlining has having been done.  The way I did
inlining was to put 

	(procalim '(inline foo bar bar ...))

at the top of my package, listing every single function name defined
in the package.  How would I look at the compiler output to see if
inlining was done?  Maybe I will run a small experiment outside my
large file.

 > Joerg-Cyril posted several interesting rants on the matter, but is yet

It's not such a big problem for me, as after a few more tweaks today,
I expect the FFI/interfgace overhead to be trimmed down to a point
where it is a pretty small percentage of the overall work being done
relative to the application.

Thank you all for your help.

---

---

From: Sam Steingold <[email-masked]>
Date: Tue Sep 17 07:57:01 2002

> * In message <[email-masked]>
> * On the subject of "Re: [clisp-list] Lots o' garbage ..."
> * Sent on Tue, 17 Sep 2002 09:50:03 -0400

try DISASSEMBLE on a function that calls FOO.

-- 
Sam Steingold (http://www.podval.org/~sds) running RedHat7.3 GNU/Linux
<http://www.camera.org> <http://www.iris.org.il> <http://www.memri.org/>
<http://www.mideasttruth.com/> <http://www.palestine-central.com/links.html>
There's always free cheese in a mouse trap.