Re: [Chicken-users] entry/exit to Scheme really slow on Solaris

[Bruce Hoult]

On Fri, 2003-08-08 at 15:54, Bruce Hoult wrote:
> I'm wanting to call into some relatively trivial (but important) Scheme
> code many thousands of times per second.  The performance is OK on Linux
> or HP/UX, but unexpectedly slow on Solaris (which is the one that matter
> to me right now)
>
> [...]
> 
> The amount of time this takes on various machines is:
> 
> Athlon 1800+, RedHat 8 Linux  :  2 sec
> HPPA 9000/785, HP/UX 10.20    : 29 sec
> Sunfire v120, Solaris 9       : 94 sec
> 
> Based on the relative speeds of these machines running other code
> (everything from Perl to my own C code) I'd expect the Sun to be a bit
> over twice as fast as the HP and six or seven times slower than the
> Athlon.  i.e. something around 12 - 15 seconds would be in line with my
> expectations -- and would make my real application perform well.
> 
> Also, the Sun shows 25% - 30% User time, 70% - 70% kernel.  The others
> show nearly zero kernel time.

Well, I solved it.

Each time Chicken does a GC (major or minor), it calls getrusage before
and after so it can calculate the amount of CPU time used in the GC. 
Unfortunately, this takes around 60 uS per call on this SPARC SunFire
v120, which turns out to be about 90% of the total runtime of my
program.

With the following patch the runtime of my test program drops from 94
seconds to 9 seconds!

This turns out to be a significant improvement not only for very short
calls into Scheme, but also for normal programs.  For example, it
dramatically lowers all the times for nsample, especially with small
nursery sizes:

Before:
checking for the best nursery size ...
 8K -> 6123 ms
 10K -> 5043 ms
 12K -> 4346 ms
 16K -> 3440 ms
 24K -> 2550 ms
 32K -> 2110 ms
 48K -> 1660 ms
 64K -> 1450 ms
 128K -> 1130 ms
 256K -> 986 ms
 512K -> 1480 ms
 1024K -> 2710 ms

After:
checking for the best nursery size ...
 8K -> 1096 ms
 10K -> 1026 ms
 12K -> 963 ms
 16K -> 900 ms
 24K -> 846 ms
 32K -> 820 ms
 48K -> 786 ms
 64K -> 776 ms
 128K -> 756 ms
 256K -> 746 ms
 512K -> 1126 ms
 1024K -> 2543 ms

It also brings the kernel time usage into line with other programs and
platforms.


The patch:

===================================================================
RCS file: /cvsroot/chicken/chicken/runtime.c,v
retrieving revision 1.43
diff -c -r1.43 runtime.c
*** runtime.c   7 Aug 2003 21:51:55 -0000       1.43
--- runtime.c   11 Aug 2003 03:04:10 -0000
***************
*** 297,302 ****
--- 297,303 ----
             gc_mode,
             gc_count_1,
             gc_count_2,
+            timer_is_running = 0,
             timer_start_gc_count_1,
             timer_start_gc_count_2,
             interrupt_reason,
***************
*** 1849,1858 ****
    LF_LIST *lfn;
    C_SCHEME_BLOCK *bp;
    WEAK_TABLE_ENTRY *wep;
!   long tgc = cpu_milliseconds();

    /* assert(C_timer_interrupt_counter >= 0); */

    if(interrupt_reason && C_interrupts_enabled)
      handle_interrupt(trampoline, proc);

--- 1850,1862 ----
    LF_LIST *lfn;
    C_SCHEME_BLOCK *bp;
    WEAK_TABLE_ENTRY *wep;
!   long tgc = 0;

    /* assert(C_timer_interrupt_counter >= 0); */

+   if (timer_is_running)
+     tgc = cpu_milliseconds();
+
    if(interrupt_reason && C_interrupts_enabled)
      handle_interrupt(trampoline, proc);

***************
*** 2078,2085 ****
      }
    }

!   tgc = cpu_milliseconds() - tgc;
!   timer_start_gc_ms += tgc;

    /* Display GC report:
       Note: stubbornly writes to stdout - there is no provision for
other output-ports */
--- 2082,2091 ----
      }
    }

!   if (timer_is_running){
!     tgc = cpu_milliseconds() - tgc;
!     timer_start_gc_ms += tgc;
!   }

    /* Display GC report:
       Note: stubbornly writes to stdout - there is no provision for
other output-ports */


-- 
Bruce Hoult <address@hidden>