Subject: [clisp-list] Large performance decrease observed with timing loop

From: Adam Warner <[email-masked]>
Date: Sat Jun 8 15:01:17 2002

Hi all,

Just posting some information about some large clisp slowdowns I have
observed simply by increasing a timing loop. The slowdowns are not
restricted to clisp (CMUCL performance decreases twice as fast as would
be expected with linear scaling).

Here's code that I just wrote to (inefficiently) concatenate the
matching elements in a list of strings:

;This takes as input two or more lists of strings and concatenates the relevant strings
;Setting merged to first args starts off the string concatenation + sets the correct number of elements

(defun merge-list-strings (&rest args)
  (let ((index 0) (element 0) (merged (first args)))
    (loop for index from 0 to (1- (length (first args))) do
	  (dolist (element (rest args))
	    (setf (nth index merged) (concatenate 'string (nth index merged) (nth index element)))))
    merged))

clisp --version
GNU CLISP 2.27 (released 2001-07-17) (built on cyberhq.internal.cyberhqz.com [192.168.0.2])

To demonstrate that the code at least works:
[2]> (merge-list-strings '("abc" "123") '("def" "456") '("ghi" "789"))
("abcdefghi" "123456789")

I then attempt a quick uncompiled speed test:
(time
  (loop for i from 1 to 1000 do
    (merge-list-strings '("abc" "123") '("def" "456") '("ghi" "789"))))

Runs fine:
Real time: 0.578641 sec.
Run time: 0.57 sec.
Space: 24115568 Bytes
GC: 46, GC time: 0.17 sec.

It's a bit too quick so I decide to boost the loop from 1000 to 10000
before compiling. I expect the code will take around 5 seconds to run.
Instead it takes 60 seconds!

Real time: 60.821857 sec.
Run time: 60.09 sec.
Space: 2401123568 Bytes
GC: 4991, GC time: 22.71 sec.

If the loop is increased to 20000 I would expect the code to take around
120 seconds to complete. Instead it takes 484 seconds:

Real time: 484.73895 sec.
Run time: 482.83 sec.
Space: 9602243568 Bytes
GC: 21642, GC time: 341.11 sec.

Note that this is 850 times slower than the 1000 loop even though the
loop was only increased by a factor of 20.

The whole time lisp.run is running it's only consuming about 0.7% of
available memory according to top.

Note the time spent in garbage collection: On the first run 30% of the
time is spend in GC. In the second run 37% of the time is spend it GC.
By the third run 70% of the time is spent in GC.

Regards,
Adam

---

From: "Pierpaolo BERNARDI" <[email-masked]>
Date: Sun Jun 9 09:15:02 2002

From: "Adam Warner" <[email-masked]>

>     (loop for index from 0 to (1- (length (first args))) do

      from 0 below (length ...)       

> I then attempt a quick uncompiled speed test:

I cannot fathom the reason you did this.   

BTW, had you compiled the function, you 
would have probably obtained some useful 
warnings.

Try this:

(defun merge-list-strings (&rest args)
  (let ((accs (make-list (length (first args)) :initial-element '())))
    (loop for arg in args
          do (loop for string in arg
                   for acc on accs
                   do (push string (car acc))))
    (mapcar (lambda (l)
              (apply #'concatenate 'string l))
            accs)))

P.

---

From: Adam Warner <[email-masked]>
Date: Sun Jun 9 17:03:09 2002

> I cannot fathom the reason you did this.   

I cannot fathom the obtuseness of your reply. I did it to get a ballpark
idea of how slow the function was. When I increased the loop I was
surprised to discover how many times slower the code ran.

> would have probably obtained some useful 

Well I can delete the index and element from the let and still get the
same result without any warnings:

(defun merge-list-strings (&rest args)
  (let ((merged (first args)))
    (loop for index from 0 to (1- (length (first args))) do
          (dolist (element (rest args))
            (setf (nth index merged) (concatenate 'string (nth index
merged) (nth index element)))))
    merged))

(compile 'merge-list-strings)
MERGE-LIST-STRINGS ;
NIL ;
NIL

I increase the loop ten-fold and the performance decreases 120-fold.

Did I discover a legitimate performance problem with clisp? Each time
the function executes I cannot see why the garbage it generates has to
be preserved. Thus I can't see why the loop gets slower and slower until
most of the time is spent in GC.

Thank you for your contribution which does scale linearly. BTW it
generates the wrong result:

[2]> (merge-list-strings '("abc" "123") '("def" "456") '("ghi" "789"))
("ghidefabc" "789456123")

But that's not the point. The point is to understand why performance
decreases so markedly with my version and whether this is unavoidable.

Regards,
Adam

---

From: "Pierpaolo BERNARDI" <[email-masked]>
Date: Sun Jun 9 18:25:02 2002

> generates the wrong result:

Just add a NREVERSE:

              (apply #'concatenate 'string (nreverse l)))

> decreases so markedly with my version and whether this is unavoidable.

I showed you how to avoid it.  

Now look closely at your version. Then at mine.  
Notice the differences.

P.

---

From: Adam Warner <[email-masked]>
Date: Sun Jun 9 19:51:02 2002

> I showed you how to avoid it.  

Well you showed me how to create superior code. I just though that my
inefficient code was causing a compiler slowdown. I wasn't looking for
superior code. I thought I was highlighting an issue with the clisp
compiler. Turned out I was wrong.

But thank you Bernardi and Don. I managed to get your names right this
time :-)

> Now look closely at your version. Then at mine.  

That's fine. The problem was I suspected those differences were critical
in understanding what was causing the compiler slowdown. But it turned
out my code just kept generating larger lists instead of the same list
each time.

Regards,
Adam