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

[Camm Maguire]

Greetings!  Sorry its been awhile getting back to this.  I'd like to
resolve if possible.

"Matt Kaufmann" <address@hidden> writes:

> 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.
> 

Matt, I assume this is linux.  Please let me know if otherwise.  There
is a 100 millisecond granulatiry to the gbc-time statistic currently,
which is not present (microsecond granularity) with
(get-internal-real-time).  I can suggest a patch to try out if you'd
like.  We should fix this in any case.  If I'm right, the fact that
your gbc time exceeded the total likely indicates many small gbc
calls.  Please let me know if this is consistent with what you are
seeing. 

At worst, the granularity could account for a factor of 2, which means
that still at least over 60% of your run is spent in gbc.  I'd like to
see some of the individual SGC messages -- my guess is that the cons
GBC is the killer.

Take care,


> 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
> 
> 
> 
> _______________________________________________
> 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