[Openmcl-devel] I knew format was slow, but this slow ??
Sven Van Caekenberghe
sven at beta9.be
Thu Oct 2 12:05:25 PDT 2003
On Thursday, October 2, 2003, at 08:45 PM, Gary Byers wrote:
>
> On Thu, 2 Oct 2003, Sven Van Caekenberghe wrote:
>
>> On Thursday, October 2, 2003, at 07:32 PM, Gary Byers wrote:
>>
>>> On Thu, 2 Oct 2003, Sven Van Caekenberghe wrote:
>>>
>>>> I knew format was slow, but can it be really this slow ??
>>>>
>>>> Note that the difference between 10 and 100 iterations in the first
>>>> loop results not in a 10-fold difference in time, but a 100-fold
>>>> difference - so its gets exponentially slower !
>>>>
>>>> The write-string version is almost a 1000 times faster, is this
>>>> still
>>>> normal ? Also note the extreme differences in memory allocation.
>>>
>>> Not that it should be (very) relevant, but what was the value of
>>> *PRINT-PRETTY* when you tried this ? Of (the even less relevant)
>>> *PRINT-CIRCLE* ?
>>
>> ? *print-pretty*
>> T
>> ? *print-circle*
>> NIL
>
> Just setting up the context for the pretty printer (that's also used
> for
> circularity detection) is the culprit here. I suppose that it's bad
> enough when there are format directives involved, but if you're just
> trying to use FORMAT to write a string to a stream, it's really, really
> bad (as you saw.)
>
> If there aren't any format directives (#\~) in the control string, I
> -think- that *PRINT-PRETTY* can be ignored (and obviously circularity
> detection isn't an issue.) Assuming that that assumption's correct
> (and that things like misering aren't an issue), it would pay to check
> for that before sailing off into the pretty printer. There's a COND
> near the end of the FORMAT definition (in "ccl:lib;format.lisp") that
> could be changed to:
>
> (cond
> ((NOT (POSITION #\~ CONTROL-STRING))
> (WRITE-STRING CONTROL-STRING STREAM))
> ((and (or *print-pretty* *print-circle*)
> (not (typep stream 'xp-stream)))
> (maybe-initiate-xp-printing
> #'(lambda (s o)
> (do-sub-format-1 s o))
> stream format-arguments))
> (t
> [ ...])
>
> There might be slightly better ways to do that, but it seems like it'd
> be worthwhile to only invoke the pretty printer if pretty-printing
> -might-
> do something ...
>
Gary,
I just redid my tests in a fresh image, and yes things went much
better! Then I remembered that I often set *print-pretty* and
*print-length*, and yes that makes everything very slow again. So your
hunch was right. Well I spent the afternoon optimizing my serialization
code, which is always a good thing ;-)
[sven at voyager:~]$ openmcl
Welcome to OpenMCL Version (Beta: Darwin) 0.13.6!
? (time (with-open-file (out #p"home:Desktop;test.txt" :direction
:output :if-exists :overwrite)
(dotimes (i 10)
(dotimes (j 128)
(format out "01234567")))))
(WITH-OPEN-FILE (OUT #4P"home:Desktop;test.txt" :DIRECTION :OUTPUT
:IF-EXISTS :OVERWRITE) (DOTIMES (I 10) (DOTIMES (J 128) (FORMAT OUT
"01234567")))) took 430 milliseconds (0.430 seconds) to run.
Of that, 20 milliseconds (0.020 seconds) were spent in user mode
0 milliseconds (0.000 seconds) were spent in system mode
410 milliseconds (0.410 seconds) were spent executing other OS
processes.
3,064 bytes of memory allocated.
NIL
? (time (with-open-file (out #p"home:Desktop;test.txt" :direction
:output :if-exists :overwrite)
(dotimes (i 100)
(dotimes (j 128)
(format out "01234567")))))
(WITH-OPEN-FILE (OUT #4P"home:Desktop;test.txt" :DIRECTION :OUTPUT
:IF-EXISTS :OVERWRITE) (DOTIMES (I 100) (DOTIMES (J 128) (FORMAT OUT
"01234567")))) took 206 milliseconds (0.206 seconds) to run.
Of that, 130 milliseconds (0.130 seconds) were spent in user mode
0 milliseconds (0.000 seconds) were spent in system mode
76 milliseconds (0.076 seconds) were spent executing other OS
processes.
768 bytes of memory allocated.
NIL
? (time (with-open-file (out #p"home:Desktop;test.txt" :direction
:output :if-exists :overwrite)
(dotimes (i 100)
(dotimes (j 128)
(write-string "01234567" out)))))
(WITH-OPEN-FILE (OUT #4P"home:Desktop;test.txt" :DIRECTION :OUTPUT
:IF-EXISTS :OVERWRITE) (DOTIMES (I 100) (DOTIMES (J 128) (WRITE-STRING
"01234567" OUT)))) took 161 milliseconds (0.161 seconds) to run.
Of that, 80 milliseconds (0.080 seconds) were spent in user mode
0 milliseconds (0.000 seconds) were spent in system mode
81 milliseconds (0.081 seconds) were spent executing other OS
processes.
768 bytes of memory allocated.
NIL
? (setf *print-pretty* t *print-length* 32)
32
? (time (with-open-file (out #p"home:Desktop;test.txt" :direction
:output :if-exists :overwrite)
(dotimes (i 10)
(dotimes (j 128)
(format out "01234567")))))
(WITH-OPEN-FILE (OUT #4P"home:Desktop;test.txt" :DIRECTION :OUTPUT
:IF-EXISTS
:OVERWRITE)
(DOTIMES (I 10)
(DOTIMES (J 128)
(FORMAT OUT "01234567")))) took 901 milliseconds (0.901 seconds)
to run.
Of that, 750 milliseconds (0.750 seconds) were spent in user mode
0 milliseconds (0.000 seconds) were spent in system mode
151 milliseconds (0.151 seconds) were spent executing other OS
processes.
1,000,056 bytes of memory allocated.
NIL
? (time (with-open-file (out #p"home:Desktop;test.txt" :direction
:output :if-exists :overwrite)
(dotimes (i 100)
(dotimes (j 128)
(format out "01234567")))))
(WITH-OPEN-FILE (OUT #4P"home:Desktop;test.txt" :DIRECTION :OUTPUT
:IF-EXISTS
:OVERWRITE)
(DOTIMES (I 100)
(DOTIMES (J 128)
(FORMAT OUT
"01234567")))) took 77,889 milliseconds (77.889 seconds)
to run.
Of that, 72,420 milliseconds (72.420 seconds) were spent in user mode
0 milliseconds (0.000 seconds) were spent in system mode
5,469 milliseconds (5.469 seconds) were spent executing other
OS processes.
2,514 milliseconds (2.514 seconds) was spent in GC.
93,238,128 bytes of memory allocated.
NIL
_______________________________________________
Openmcl-devel mailing list
Openmcl-devel at clozure.com
http://clozure.com/cgi-bin/mailman/listinfo/openmcl-devel
More information about the Openmcl-devel
mailing list