[Openmcl-devel] Why is with-output-to-string so slow?

[Ron Garret]

On Oct 27, 2010, at 8:26 PM, Gary Byers wrote:

> For more typical uses (such as '(format nil ...)', where anywhere from several
> dozen to a few hundred characters get written to a short-lived STRING-OUTPUT-STREAM
> and recycling can take effect, is the stream-creation overhead significant ?  I
> don't think so.

? (time
 (dotimes (i 1000000) (format nil "~A" i)))
(DOTIMES (I 1000000) (FORMAT NIL "~A" I)) took 3,964,478 microseconds (3.964478 seconds) to run 
                    with 2 available CPU cores.
During that period, 3,927,968 microseconds (3.927968 seconds) were spent in user mode
                    39,486 microseconds (0.039486 seconds) were spent in system mode
112,210 microseconds (0.112210 seconds) was spent in GC.
 79,999,315 bytes of memory allocated.
 39 minor page faults, 0 major page faults, 0 swaps.
NIL

? (time
 (let ((s (make-string-output-stream)))
   (dotimes (i 1000000)
     (format s "~A" i)
     (get-output-stream-string s))))
(LET ((S (MAKE-STRING-OUTPUT-STREAM))) (DOTIMES (I 1000000) (FORMAT S "~A" I) (GET-OUTPUT-STREAM-STRING S))) took 1,154,212 microseconds (1.154212 seconds) to run 
                    with 2 available CPU cores.
During that period, 1,145,682 microseconds (1.145682 seconds) were spent in user mode
                    14,882 microseconds (0.014882 seconds) were spent in system mode
44,226 microseconds (0.044226 seconds) was spent in GC.
 31,998,912 bytes of memory allocated.
NIL

Four times slower seems significant to me.  But what do I know?

I note in passing that only about 5% of the extra time that the first version takes was spent in GC, and it only allocates 48 extra bytes per iteration.  So where all this extra time is being spent is actually still a mystery to me.  But creating one string output stream and reusing it is a workable solution for me so no need to explain it any further.

Thanks for taking the time to write this detailed response.

rg