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

[Hoehle, Joerg-C. <Joe...@t-...>]

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 slowdow=
n.

My application is working with :start and :end keywords (sort of a
sliding window technique) on a large buffer (130KB), using functions
like STRING-=3D, 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 . 29=
3)
  (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) 10000=
00))
;*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)))
=09(when (> diff *treshold*)
=09  (vector-push-extend (cons diff start) *stats*))))))

(defparameter *item* " 13b;")
(defun testf (len)
  (let ((s (make-string (* (length *item*) len))))
    (loop repeat len
=09  for pos from 0 by (length *item*)
=09  do (replace s *item* :start1 pos))
    s))
(defun testp (iter s len)
  (let ((result 0))
    (dotimes (i iter result)
      (dotimes (j len)
=09(incf result (or (my-parse-integer s :start (* #.(length *item*) j) :jun=
k-allowed t)
=09=09=09 (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=3DCHARAC=
TER.

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

Thanks for your attention,
=09J=F6rg H=F6hle.
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.