Re: [Gcl-devel] Re: possible lisp reader enhancement/modification

[Matt Kaufmann]

Hi, Camm and Vadim --

OK, I've re-run the test with SYSTEM:*LISP-MAXPAGES* = 131,072.  The time was

5247.980u 19.580s 1:30:59.24 96.4%      0+0k 0+0io 5383pf+0w

as compared to the almost 3X faster Allegro dynamic runtime result of:

  real    32m40.528s
  user    32m21.530s
  sys     0m10.140s

What I don't understand, though, is that (si::gbc-time) returns 722440 at the
end of the run, and since Internal-time-units-per-second = 100, I would think
that this is 7224 seconds, which is more than the total run time!

I noticed that instead of 5414 occurrences of the string "[SGC" in the run
there are now only 1585.  So, that's progress.

Anyhow, here is the input file (which processes proprietary files that I can't
include, but shows some settings).  After that are excerpts from the log.

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

(value :q) ; exit ACL2 loop

(room t)

; Allocate extra room.
(sloop::sloop for (type . n) in
              '((hole . 500)   ; unchanged
                (relocatable . 750) ; was 500
                (cons . 60000) ; was 2917
                (fixnum . 250) ; was 100
                (bignum . 400) ; unchanged
                (symbol . 900) ; was 400
                (array . 40)   ; was unassigned
                (string . 2000); was 200
                (sfun . 60)    ; was 40
                )
              when n
              do
              (cond
               ((eq type 'HOLE)
                (si::set-hole-size n))
               ((eq type 'RELOCATABLE)
                (si::allocate-relocatable-pages n))
               (t (si::allocate type n t))))

(room t)

(si::gbc-time 0)

(format t "*** Internal time: ~s~%" (get-internal-run-time))

(format t "*** Internal-time-units-per-second: ~s~%" 
internal-time-units-per-second)

(lp) ; enter ACL2 read-eval-print loop

(ld "pkgs.lisp") ; some constant and package definitions

(certify-book "model-eq" ?) ; the main test

(value :q) ; exit ACL2 loop

(format t "*** Internal time: ~s~%" (get-internal-run-time))

(si::gbc-time)

(room t)

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Here are relevant excerpts from the log file, annotated with comments.

;;; Room before allocations.

2917/2917 82.5%CONS RATIO LONG-FLOAT COMPLEX STRUCTURE
 100/100   18.3%    FIXNUM SHORT-FLOAT CHARACTER RANDOM-STATE READTABLE NIL
 400/400   35.2%    SYMBOL STREAM
   1/2     37.2%    PACKAGE
   5/38    14.0%    ARRAY HASH-TABLE VECTOR BIT-VECTOR PATHNAME CCLOSURE 
FAT-STRING
 200/200   46.4%    STRING
 400/400    1.8%    CFUN BIGNUM
  40/40    56.7%    SFUN GFUN CFDATA SPICE NIL

   1/100            contiguous (1 blocks)
     857            hole
     500    0.1%    relocatable

 4063 pages for cells
 5421 total pages
119225 pages available
 6426 pages in heap but not gc'd + pages needed for gc marking
131072 maximum pages

;;; Room after allocations, but before run:

60000/60000 95.1%CONS RATIO LONG-FLOAT COMPLEX STRUCTURE
 250/250    7.3%    FIXNUM SHORT-FLOAT CHARACTER RANDOM-STATE READTABLE NIL
 900/900   15.6%    SYMBOL STREAM
   1/2     37.2%    PACKAGE
  40/40     1.5%    ARRAY HASH-TABLE VECTOR BIT-VECTOR PATHNAME CCLOSURE 
FAT-STRING
2000/2000   4.6%    STRING
 400/400    1.8%    CFUN BIGNUM
  60/60    37.8%    SFUN GFUN CFDATA SPICE NIL

   1/100          3 contiguous (1 blocks)
     480            hole
     750    0.0%  3 relocatable

63651 pages for cells
64882 total pages
59137 pages available
 7053 pages in heap but not gc'd + pages needed for gc marking
131072 maximum pages

;;; (si::gbc-time 0)
0

*** Internal time: 643

*** Internal-time-units-per-second: 100

*** Internal time: 524794

;;; (si::gbc-time)
722440

;;; Room after the run:

77000/77000 99.9%213CONS RATIO LONG-FLOAT COMPLEX STRUCTURE
 250/250   64.2% 72 FIXNUM SHORT-FLOAT CHARACTER RANDOM-STATE READTABLE NIL
 900/900   88.3%    SYMBOL STREAM
   1/2     64.1%    PACKAGE
  40/40     2.3% 60 ARRAY HASH-TABLE VECTOR BIT-VECTOR PATHNAME CCLOSURE 
FAT-STRING
2000/2000  21.9%    STRING
 400/400   58.0% 15 CFUN BIGNUM
  60/60    69.6%    SFUN GFUN CFDATA SPICE NIL

6615/7553       1136contiguous (14 blocks)
     179            hole
     1125  91.2%1136relocatable

80651 pages for cells
88570 total pages
34773 pages available
 7729 pages in heap but not gc'd + pages needed for gc marking
131072 maximum pages

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Any suggestions?

Thanks --
-- Matt
   cc: address@hidden, address@hidden, address@hidden
   From: "Camm Maguire" <address@hidden>
   Date: 20 Jul 2003 14:13:19 -0400
   User-Agent: Gnus/5.09 (Gnus v5.9.0) Emacs/21.2
   X-WSS-ID: 1304045F9912856-01-01
   Content-Type: text/plain;
    charset=iso-8859-1
   X-MIME-Autoconverted: from quoted-printable to 8bit by timon.amd.com id 
h6KIGlN16823

   Hi Matt!  I think Vadim is right.  The exhausted state kicks in by
   default if you have less than 10% of the total pages for the type
   free.  The percentage can be varied using 'allocate-growth.  I believe
   one can also continue from this point using 'allocate, though I don't
   yet know the details.  There is also a compile time define
   IGNORE_MAX_PAGES which will try to continue as far as possible.  But
   the bottom lne is that you need a larger memory image -- your total
   pages used are ~>= 90% of the total possible, and this is where the
   problems begin.

   Take care,

   "Matt Kaufmann" <address@hidden> writes:

   > Hi --
   > 
   > I'm at a bit of a loss.  I tried again, this time with more allocation 
done at
   > the start based on the result of (room) at the end of the previous run.  
But
   > this time I ran out of cons space:
   > 
   > Error: The storage for CONS is exhausted.
   >        Currently, 52275 pages are allocated.
   >        Use ALLOCATE to expand the space.
   > 
   > Below is the test file that I used, in case this gives you any ideas.  (The
   > main test is the call (certify-book "model-eq" ?), but I can't include 
input
   > file model-eq.lisp.)  Perhaps we have to build with more than 64K pages.
   > 
   > ++++++++++++++++++++++++++++++ test file ++++++++++++++++++++++++++++++
   > 
   > (value :q) ; exit ACL2 loop
   > 
   > (room)
   > 
   > ; Allocate extra room.
   > (sloop::sloop for (type . n) in
   >               '((hole . 500)   ; unchanged
   >                 (relocatable . 750) ; was 500
   >                 (cons . 40000) ; was 2917
   >                 (fixnum . 250) ; was 100
   >                 (bignum . 400) ; unchanged
   >                 (symbol . 900) ; was 400
   >                 (array . 40)   ; was unassigned
   >                 (string . 1000); was 200
   >                 (sfun . 60)    ; was 40
   >                 )
   >               when n
   >               do
   >               (cond
   >                ((eq type 'HOLE)
   >                 (si::set-hole-size n))
   >                ((eq type 'RELOCATABLE)
   >                 (si::allocate-relocatable-pages n))
   >                (t (si::allocate type n t))))
   > 
   > (room)
   > 
   > (si::gbc-time 0)
   > 
   > (format t "*** Internal time: ~s~%" (get-internal-run-time))
   > 
   > (format t "*** Internal-time-units-per-second: ~s~%" 
internal-time-units-per-second)
   > 
   > (lp) ; enter ACL2 read-eval-print loop
   > 
   > (ld "pkgs.lisp") ; some constant and package definitions
   > 
   > (certify-book "model-eq" ?) ; the main test
   > 
   > (value :q) ; exit ACL2 loop
   > 
   > (format t "*** Internal time: ~s~%" (get-internal-run-time))
   > 
   > (si::gbc-time)
   > 
   > (room)
   > 
   > ++++++++++++++++++++++++++++++ end of test file 
++++++++++++++++++++++++++++++
   > 
   > --  Matt
   >    Date: Sat, 19 Jul 2003 21:18:45 +0300
   >    From: "Vadim V. Zhytnikov" <address@hidden>
   >    User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; ru-RU; rv:1.4)
   >     Gecko/20030630
   >    X-Accept-Language: ru-ru, ru
   >    cc: address@hidden
   >    X-MIME-Autoconverted: from 8bit to quoted-printable by amdext.amd.com id
   >     h6JHJ1bk029276
   >    X-WSS-ID: 1307A21C5363219-01-01
   >    Content-Type: text/plain;
   >     charset=koi8-r;
   >     format=flowed
   >    X-MIME-Autoconverted: from quoted-printable to 8bit by timon.amd.com id 
h6JHMJm22449
   > 
   >    Matt Kaufmann ÐÉÛÅÔ:
   > 
   >    > Hi --
   >    > 
   >    > Sorry I couldn't reply soon (I just returned from vacation).
   >    > 
   >    > I'm also really sorry to say that I can't provide the test example, 
since it's
   >    > derived directly from AMD design data and I think it would take 
considerable
   >    > effort to "sanitize" it, if that's even possible.  But below are some 
details
   >    > from the run, and if someone cares to suggest some allocate settings 
then I'd
   >    > be happy to re-run.  Anyhow, here's some info that may halp.
   >    > 
   >    > Here I'm focusing on one run from a suite of runs.  The timing was as 
follows:
   >    > 
   >    > ACL2 built on GCL:
   >    > real  93m14.066s
   >    > user  92m47.830s
   >    > sys   0m16.260s
   >    > 
   >    > ACL2 built on Allegro CL dynamic runtime:
   >    > real  32m40.528s
   >    > user  32m21.530s
   >    > sys   0m10.140s
   >    > 
   >    > I built ACL2 by starting with modest allocations and causing growth 
to occur
   >    > slowly (details upon request).   Here is the room available when I 
first
   >    > started up ACL2.
   >    > 
   >    >   ACL2>(room)
   >    >   2917/2917 82.0%CONS RATIO LONG-FLOAT COMPLEX STRUCTURE
   >    >    100/100   18.4%    FIXNUM SHORT-FLOAT CHARACTER RANDOM-STATE 
READTABLE NIL
   >    >    400/400   35.2%    SYMBOL STREAM
   >    >      1/2     37.2%    PACKAGE
   >    >      5/38    13.8%    ARRAY HASH-TABLE VECTOR BIT-VECTOR PATHNAME 
CCLOSURE FAT-STRING
   >    >    200/200   46.4%    STRING
   >    >    400/400    1.8%    CFUN BIGNUM
   >    >     40/40    56.7%    SFUN GFUN CFDATA SPICE NIL
   >    > 
   >    >      1/100            contiguous (1 blocks)
   >    >        1000           hole
   >    >        500    0.1%    relocatable
   >    > 
   >    >    4063 pages for cells
   >    >    5564 total pages
   >    >   55769 pages available
   >    >    4203 pages in heap but not gc'd + pages needed for gc marking
   >    >   65536 maximum pages
   >    > 
   >    >   ACL2>
   >    > 
   >    > At the end of the run, (room) gave the following.
   >    > 
   >    >   ACL2>(room)
   >    >   50251/51062 98.9%350CONS RATIO LONG-FLOAT COMPLEX STRUCTURE
   >    >    245/225   62.6% 77 FIXNUM SHORT-FLOAT CHARACTER RANDOM-STATE 
READTABLE NIL
   >    >    790/900   99.3%  2 SYMBOL STREAM
   >    >      1/2     64.1%    PACKAGE
   >    >     29/38     3.2%    ARRAY HASH-TABLE VECTOR BIT-VECTOR PATHNAME 
CCLOSURE FAT-STRING
   >    >    450/450   97.4%3916STRING
   >    >    400/400   74.9%  9 CFUN BIGNUM
   >    >     43/60    97.1%  1 SFUN GFUN CFDATA SPICE NIL
   >    > 
   >    >   6414/6553       669 contiguous (17 blocks)
   >    >        382            hole
   >    >        750   68.2%669 relocatable
   >    > 
   >    >   52209 pages for cells
   >    >   59755 total pages
   >    >     710 pages available
   >    >    5071 pages in heap but not gc'd + pages needed for gc marking
   >    >   65536 maximum pages
   >    > 
   >    >   ACL2>
   >    > 
   >    > I particularly noticed a lot of string GCs, such as:
   >    > 
   >    > [SGC for 93 STRING pages..(11793 writable)..(T=14).GC finished]
   >    > 
   >    > Here are total counts of gc messages.
   >    > 
   >    > [SGC for ... CONS pages]:              350
   >    > [SGC for ... STRING pages]:           3916
   >    > [SGC for ... FIXNUM pages]:             77
   >    > [SGC for ... SYMBOL pages]:              2
   >    > [SGC for ... CFUN pages]:                9
   >    > [SGC for ... SFUN pages]:                1
   >    > [SGC for 0 CONTIGUOUS-BLOCKS pages]:    12
   >    > [SGC for 0 RELOCATABLE-BLOCKS pages]:  553
   >    > 
   >    > I can send you all 4920 lines of SGC messages if you like.  I also 
got this count:
   >    > 
   >    > [GC for ... RELOCATABLE-BLOCKS pages]: 116
   >    > 
   > 
   >    Try to call
   >       (si::gbc-time 0)
   >    before starting ACL2 test. This function activates
   >    internal GC timing counter.  Finally (si::gbc-time) will
   >    give total time spent by GCL in GC (the sum of T=... in GC messages)
   >    in some internal units (1/100 of second as far as I recall).
   >    I'm perfectly sure that from 60% to 90% of total time
   >    is wasted in the GC.  If you increase preallocated space
   >    (especially for storage types which cause more frequent GC)
   >    then total GC time should go down significantly keeping
   >       (net time) = (total time) - (total GC time)
   >    approximately constant.
   > 
   >    -- 
   >     Vadim V. Zhytnikov
   > 
   >      <address@hidden>
   >     <address@hidden>
   > 
   > 
   > 
   > _______________________________________________
   > Gcl-devel mailing list
   > address@hidden
   > http://mail.gnu.org/mailman/listinfo/gcl-devel
   > 
   > 
   > 

   -- 
   Camm Maguire                                         address@hidden
   ==========================================================================
   "The earth is but one country, and mankind its citizens."  --  Baha'u'llah