Subject: [clisp-list] parse-integer slowdown & make-string /= make-array of 'character

From: "Hoehle, Joerg-Cyril" <[email-masked]>
Date: Wed Feb 26 07:06:09 2003

Hi,

I've been hit by a problem where my application suddenly takes ages to
complete (several hundreds of seconds) with CLISP 2.30 (both Linux and
MS-Windows), whereas it only took ~30 seconds with clisp-2.28
(MS-Windows).

PARSE-INTEGER is involved in the tremendous slowdown. Missing an :END
argument, it appears to take time depending on (- (length buffer)
&start). I observed nothing like this with clisp-2.28.

It also appears that MAKE-STRING is very different from MAKE-ARRAY
:element-type 'character. Using strings from MAKE-STRING is fast with
PARSE-INTEGER, while strings from MAKE-ARRAY exhibit the tremendous slowdown.

My application is working with :start and :end keywords (sort of a
sliding window technique) on a large buffer (130KB), using functions
like STRING-=, PARSE-INTEGER, POSITION etc. which all accept these
keywords.

Below, I measure GET-INTERNAl-RUN/REAL-TIME around calls to
parse-integer.

;(space (testp 20 (testfS 13000) 10000)) ;use MAKE-STRING
;200_000 calls take 2 seconds, with only 5 computations >50 microsecs
SIMPLE-STRING                0         0          1    130008

;(space (testp 20 (testfA 13000) 10000)) ;use MAKE-ARRAY
;200_000 calls take 233 seconds
SIMPLE-STRING                0         0          1    520008

Using clisp-2.28 on MS-Windows, only 65 calls out of 238764 in my
application would return a time difference >0. The whole program
executes in 30 seconds.

Using clisp-2.30 on MS-Windows, 3777 out of 41400 calls would. I
interrupted the computation after 68 seconds because it had already
taken twice as much time as with 2.28. To complete, it would take a
lot more time (41400 << 238764).
(* 3777 0.015625) yields 59 seconds.

Using clisp-2.30 on Suse Linux 8.1, 150729 out of 156166 calls(!) did
take longer than 50 microseconds. I interrupted the job after 178
seconds. Compare this to using the testbed below, where parse-integer
usually takes 3-4 microseconds when operating on a string from MAKE-STRING.

The following subseq from my *stats* variable after running my
application on Linux shows how PARSE-INTEGER takes time highly
dependend on (- (length buffer) start): towards the end of buffer, it
takes 6 microseconds to be compared with 2 milliseconds towards the
beginning of the 130KB buffer.

CAR is elapsed time in microseconds, CDR is buffer :start position
  (39 . 127328) (38 . 127473) (35 . 127613) (35 . 127753) (32 . 127901)
  (30 . 128042) (28 . 128183) (26 . 128329) (23 . 128477) (21 . 128626)
  (19 . 128768) (18 . 128910) (17 . 129052) (16 . 129199) (15 . 129351)
  (15 . 129503) (13 . 129715) (12 . 129868) (11 . 130017) (9 . 130365)
  (7 . 130519) (7 . 130671) (6 . 130811) (2330 . 4) (2175 . 152) (2152 . 293)
  (2183 . 433) (2145 . 574) (2141 . 714) (2131 . 858) (2123 . 998)
  (2128 . 1138) (2119 . 1287) (2117 . 1435) (2112 . 1577) (2143 . 1717)
  (2120 . 1857) (2108 . 2000) (2108 . 2144) (2134 . 2288) (2104 . 2431)
  (2097 . 2583) (2093 . 2723) (2096 . 2863) (2127 . 3003) (2095 . 3148)

; remember times >50 microseconds
(defparameter *treshold* (floor (* 50 internal-time-units-per-second) 1000000))
;*treshold*

(defvar *stats* (make-array 200 :fill-pointer 0 :adjustable t))
;(setf (fill-pointer *stats*) 0)
;(length *stats*)
;(subseq *stats* 0 500)

;(space (ignore-errors (ext:muffle-cerrors (run-analyses gesamt))))

(defun my-parse-integer (line &key (start 0) (end nil) junk-allowed)
  (let ((from (get-internal-run-time)))
    (prog1 (parse-integer line :start start :junk-allowed junk-allowed)
      (let ((diff (- (get-internal-run-time) from)))
	(when (> diff *treshold*)
	  (vector-push-extend (cons diff start) *stats*))))))

(defparameter *item* " 13b;")
(defun testf (len)
  (let ((s (make-string (* (length *item*) len))))
    (loop repeat len
	  for pos from 0 by (length *item*)
	  do (replace s *item* :start1 pos))
    s))
(defun testp (iter s len)
  (let ((result 0))
    (dotimes (i iter result)
      (dotimes (j len)
	(incf result (or (my-parse-integer s :start (* #.(length *item*) j) :junk-allowed t)
			 (error "Broken at ~D (~D) of ~D~%" j len i)))))))

Yet both types report as the same:
ANALYSE-LOG[480]> (describe (make-string 3))
"^@^@^@" is a simple 1 dimensional array (vector) of characters, of size 3.
ANALYSE-LOG[481]> (describe (make-array 3 :element-type 'character))
"^@^@^@" is a simple 1 dimensional array (vector) of characters, of size 3.
Similarly, (ARRAY-ELEMENT-TYPE x) -> CHARACTER

Both MS-windows builts using MSVC6 feature :UNICODE and :BASE-CHAR=CHARACTER.

What changed between 2.28 and 2.30, producing such a dramatic impact?

Thanks for your attention,
	Jörg Höhle.
It took me 2 days to track down a small reproducible test case and
realise that my testbed used MAKE-STRING, whereas my application uses
MAKE-ARRAY. Maybe compiling without UNICODE would have saved my days.

---

From: Sam Steingold <[email-masked]>
Date: Thu Feb 27 16:06:09 2003

> * In message <[email-masked]>
> * On the subject of "[clisp-list] parse-integer slowdown & make-string /= make-array of 'character"
> * Sent on Wed, 26 Feb 2003 16:05:10 +0100
> * Honorable "Hoehle, Joerg-Cyril" <[email-masked]> writes:
>

try SYS::STRING-INFO on the different strings.

> What changed between 2.28 and 2.30, producing such a dramatic impact?

2002-05-22 mutable small strings.

could you please profile your code with the CVS head?

-- 
Sam Steingold (http://www.podval.org/~sds) running RedHat8 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>
main(a){a="main(a){a=%c%s%c;printf(a,34,a,34);}";printf(a,34,a,34);}

---

From: Sam Steingold <[email-masked]>
Date: Fri Feb 28 08:27:16 2003

> PARSE-INTEGER, while strings from MAKE-ARRAY exhibit the tremendous slowdown.

On 2002-05-22 Bruno introduced mutable small strings.
This means that whenever you parse a string, you call
unpack_sstring_alloca(), which involves a copy_16bit_32bit() or
copy_8bit_32bit() call for a "small string" (8-bit or 16-bit).

It appears that we need to eliminate all calls to
unpack_sstring_alloca() and replace them with SstringDispatch(),
which does not carry the same overhead.

-- 
Sam Steingold (http://www.podval.org/~sds) running RedHat8 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>
A slave dreams not of Freedom, but of owning his own slaves.