Re: [Gcl-devel] Re: possible lisp reader enhancement/modification ?JUNK MAIL? 4

[Matt Kaufmann]

Hi, Camm --

OK, we'll try the patch.

>> From what I can gather, you have maybe a slight inefficiency in your
>> reloc page gbc, but in general gbc doesn't seem to be the issue.
>> Please verify this for me.  

Sure; how would you like me to verify that?  (Perhaps that's what you're
addressing in the next paragraph.)

>> There are at least two profiling modes available to gcl, a native one
>> using (si::prof ...) and one built on top of the external gprof, the
>> latter of which is more familiar to me.  Do you have any experience
>> with these?  I'll try to get a few profiles on 'maxima test', and we
>> can go from there.

No, I haven't used either of these (well, maybe gprof a long time ago, but I
don't recall how).  Let me know what you'd like me to do.  By the way, I
searched for "profile" in the GCL info documentation, but didn't find it.  I
also tried (describe 'SYSTEM:PROFILE) and (documentation 'SYSTEM:PROFILE
'function) but got nothing.  Any suggestions?  (I did an apropos on 'prof and
it appears that the function is si::profile rather than si::prof.)

-- Matt
   cc: address@hidden, address@hidden, address@hidden
   From: "Camm Maguire" <address@hidden>
   Date: 30 Jul 2003 11:10:36 -0400
   User-Agent: Gnus/5.09 (Gnus v5.9.0) Emacs/21.2
   X-WSS-ID: 133900757687335-01-01
   Content-Type: text/plain;
    charset=us-ascii

   Greetings!

   OK, as for the gbc counter problem, please try this patch:

   =============================================================================
   Index: gbc.c
   ===================================================================
   RCS file: /cvsroot/gcl/gcl/o/gbc.c,v
   retrieving revision 1.13
   diff -u -r1.13 gbc.c
   --- gbc.c    15 Feb 2003 00:38:28 -0000      1.13
   +++ gbc.c    30 Jul 2003 14:32:32 -0000
   @@ -96,6 +96,7 @@
    bool saving_system;
    static int gc_time = -1;
    static int gc_start = 0;
   +static int gc_recursive = 0;
    int runtime(void);
    int sgc_enabled=0;
    int  first_protectable_page =0;
   @@ -1091,7 +1092,7 @@
        fflush(stdout);
      }
    #endif
   -  if (gc_time >=0) {gc_start=runtime();}
   +  if (gc_time >=0 && !gc_recursive++) {gc_start=runtime();}

      maxpage = page(heap_end);

   @@ -1326,14 +1327,16 @@
      if (in_sgc && sgc_enabled==0)
        sgc_start();

   -  if(gc_time>=0) {gc_time=gc_time+(gc_start=(runtime()-gc_start));}
   +  if(gc_time>=0 && !--gc_recursive) 
{gc_time=gc_time+(gc_start=(runtime()-gc_start));}

      if (sSAnotify_gbcA->s.s_dbind != Cnil) {

   -    fprintf(stdout, "(T=%d).GC finished]\n",
   -        gc_start
   -        );
   +    if (gc_recursive)
   +      fprintf(stdout, "(T=...).GC finished]\n");
   +    else
   +      fprintf(stdout, "(T=%d).GC finished]\n",gc_start);
        fflush(stdout);
   +
      }
   =============================================================================

   >From what I can gather, you have maybe a slight inefficiency in your
   reloc page gbc, but in general gbc doesn't seem to be the issue.
   Please verify this for me.  

   There are at least two profiling modes available to gcl, a native one
   using (si::prof ...) and one built on top of the external gprof, the
   latter of which is more familiar to me.  Do you have any experience
   with these?  I'll try to get a few profiles on 'maxima test', and we
   can go from there.

   Take care,



   "Matt Kaufmann" <address@hidden> writes:

   > Hi, Camm --
   > 
   > OK, I re-ran and kept an eye on the screen this time.  There were two full 
gcs
   > with high "T=" numbers, and each actually took only a few seconds (I looked
   > away from the screen so I don't have an exact timing, but I think well 
under a
   > minute each, maybe much less.)
   > 
   > What I noticed is that the high "T=" numbers occur exactly when the full gc
   > includes a "GC for RELOCATABLE-BLOCKS pages".  That has been the case for 
all
   > three runs that I have a record of.  For example, in this latest run here 
are
   > the two high "T=" full gcs, followed by an example of a low "T=" full gcl.
   > 
   > ....
   > 
   > [SGC for 0 CFUN pages..(9590 writable)..[SGC off] (doing full gc)[GC for 
750 RELOCATABLE-BLOCKS pages..(T=230).GC finished]
   > [SGC on](T=383688).GC finished]
   > 
   > ....
   > 
   > [SGC for 0 RELOCATABLE-BLOCKS pages..(10942 writable)..(T=19).GC finished]
   > [SGC for 0 CFUN pages..(11014 writable)..[SGC off] (doing full gc)[GC for 
750 RELOCATABLE-BLOCKS pages..(T=225).GC finished]
   > [SGC on](T=396526).GC finished]
   > [SGC for 0 RELOCATABLE-BLOCKS pages..(9294 writable)..(T=14).GC finished]
   > 
   > ....
   > 
   > [SGC for 0 CFUN pages..(11177 writable)..[SGC off] (doing full gc)[SGC 
on](T=340).GC finished]
   > 
   > ....
   > 
   > So, I can imagine that the counters used for full gcs are somehow getting
   > messed up by the "GC for 750 RELOCATABLE-BLOCKS pages".
   > 
   > I hope this helps.  I realize that it doesn't really explain the bigger 
issue,
   > of where the time is really being spent in the run.
   > 
   > Thanks --
   > -- Matt
   >    cc: address@hidden, address@hidden, address@hidden
   >    From: "Camm Maguire" <address@hidden>
   >    Date: 28 Jul 2003 20:49:19 -0400
   >    User-Agent: Gnus/5.09 (Gnus v5.9.0) Emacs/21.2
   >    X-WSS-ID: 133B1B2B7333583-01-01
   >    Content-Type: text/plain;
   >     charset=us-ascii
   > 
   >    Greetings!  Matt, could you fill in any missing log lines excluded by
   >    the grep from these locations:
   > 
   > 
   >    > [SGC for 0 RELOCATABLE-BLOCKS pages..(10703 writable)..(T=19).GC 
finished]
   >    > ACL2 !>>[SGC for 0 CFUN pages..(10762 writable)..[SGC off] (doing 
full gc)[GC for 750 RELOCATABLE-BLOCKS pages..(T=226).GC finished]
   >    > [SGC on](T=247161).GC finished]
   >    > [SGC for 74 FIXNUM pages..(8845 writable)..(T=11).GC finished]
   > 
   > 
   > 
   >    > [SGC for 3000 CONS pages..(21898 writable)..(T=64).GC finished]
   >    > [SGC for 0 CFUN pages..(21908 writable)..[SGC off] (doing full gc)[GC 
for 1125 RELOCATABLE-BLOCKS pages..(T=91).GC finished]
   >    > [SGC on](T=438992).GC finished]
   >    > [SGC for 232 FIXNUM pages..(9121 writable)..(T=14).GC finished]
   > 
   >    These two instances account for nearly all your reported GBC time,
   >    though it is possible these reported values are in error.  Would be
   >    nice if someone actually watched the run at this point and determined
   >    what the pause was roughly with a wall clock.  
   > 
   >    Take care,
   > 
   > 
   >    -- 
   >    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