better benchmark timing

benchmarks/gabriel/chibi-prelude.scm

@@ -5,26 +5,42 @@
   (quotient (+ (* 1000000 (timeval-seconds tv)) (timeval-microseconds tv))
             1000))
 
+(define (timeval-diff start end)
+  (- (timeval->milliseconds end)
+     (timeval->milliseconds start)))
+
 (define (time* thunk)
   (call-with-output-string
     (lambda (out)
+      (gc)
       (let* ((start (car (get-time-of-day)))
+             (start-rusage (get-resource-usage))
              (gc-start (gc-usecs))
+             (gc-start-count (gc-count))
+             ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
              (result (parameterize ((current-output-port out)) (thunk)))
+             ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
              (end (car (get-time-of-day)))
+             (end-rusage (get-resource-usage))
              (gc-end (gc-usecs))
              (gc-msecs (quotient (- gc-end gc-start) 1000))
-             (msecs (- (timeval->milliseconds end)
-                       (timeval->milliseconds start))))
+             (real-msecs (timeval-diff start end))
+             (user-msecs
+              (timeval-diff (resource-usage-time start-rusage)
+                            (resource-usage-time end-rusage)))
+             (system-msecs
+              (timeval-diff (resource-usage-system-time start-rusage)
+                            (resource-usage-system-time end-rusage))))
         (display "user: ")
-        (display msecs)
-        (display " system: 0")
+        (display user-msecs)
+        (display " system: ")
+        (display system-msecs)
         (display " real: ")
-        (display msecs)
+        (display real-msecs)
         (display " gc: ")
         (display gc-msecs)
         (display " (")
-        (display (gc-count))
+        (display (- (gc-count) gc-start-count))
         (display " times)\n")
         (display "result: ")
         (write result)

benchmarks/gabriel/run.sh

@@ -1,16 +1,32 @@
 #!/bin/sh
 
-BENCHDIR=$(dirname $0)
-if [ "${BENCHDIR%%/*}" == "." ]; then
-    BENCHDIR=$(pwd)${BENCHDIR#.}
-fi
-CHIBIHOME=${BENCHDIR%%/benchmarks/gabriel}
-CHIBI="${CHIBI:-${CHIBIHOME}/chibi-scheme} -I$CHIBIHOME"
+# set -ex
 
-cd $BENCHDIR
+BENCHDIR=$(dirname $0)
+if [ "${BENCHDIR%%/*}" = "." ]; then
+    BENCHDIR="$(pwd)${BENCHDIR#.}"
+fi
+OUTPUT="$BENCHDIR/out.txt"
+DB="$BENCHDIR/times.tsv"
+CHIBIHOME="${BENCHDIR%%/benchmarks/gabriel}"
+CHIBI="${CHIBI:-${CHIBIHOME}/chibi-scheme} -I$CHIBIHOME"
+HEAP="2M"
+
+cd "$BENCHDIR"
 for t in *.sch; do
-    echo "${t%%.sch}"
+    echo "program: ${t%%.sch}"
     LD_LIBRARY_PATH="$CHIBIHOME" DYLD_LIBRARY_PATH="$CHIBIHOME" \
-        $CHIBI -I"$CHIBIHOME/lib" -q -lchibi-prelude.scm $t
-done
+        $CHIBI -I"$CHIBIHOME/lib" -h"$HEAP" -q -lchibi-prelude.scm "$t"
+done | tee "$OUTPUT"
 cd -
+
+if [ ! -f "$DB" ]; then
+    echo $'program\tuser_ms\tsystem_ms\treal_ms\tgc_ms\tgc_count\ttimestamp\tcommit\tfeatures\tinit_heap\tcpu' > "$DB"
+fi
+
+#DATE=$(date -Iseconds)
+DATE=$(date +%s)
+COMMIT=$(git -C "$CHIBIHOME" rev-parse HEAD)
+FEATURES=$(LD_LIBRARY_PATH="$CHIBIHOME" DYLD_LIBRARY_PATH="$CHIBIHOME" $CHIBI -q -p'(cddr *features*)' | tr ' ' , | tr -d '()')
+CPU=$(lscpu | perl -ne 'if (s/^Model name:\s*//){s/\b(Intel|Core|Atom|AMD|CPU)(\s*\(\w+\))?\s*//gi;s/\s*@\s*[.\d]+[KMGT]Hz\b\s*//gi;print}')
+perl -ane 'if (/^program:\s*(\w+)/) {$p=$1} elsif (/^user:\s*(\d+)\s*system:\s*(\d+)\s*real:\s*(\d+)(?:\s*gc:\s*(\d+)\s*(?:\((\d+)\s*times\))?)?/) {print"$p\t$1\t$2\t$3\t$4\t$5\t'"$DATE"'\t'"$COMMIT"'\t'"$FEATURES"'\t'"$HEAP"'\t'"$CPU"'\n"}' "$OUTPUT" >> "$DB"

gc.c

@@ -483,11 +483,11 @@ sexp sexp_gc (sexp ctx, size_t *sum_freed) {
   sexp_reset_weak_references(ctx);
   finalized = sexp_finalize(ctx);
   res = sexp_sweep(ctx, sum_freed);
+  ++sexp_context_gc_count(ctx);
 #if SEXP_USE_TIME_GC
   getrusage(RUSAGE_SELF, &end);
   gc_usecs = (end.ru_utime.tv_sec - start.ru_utime.tv_sec) * 1000000 +
     end.ru_utime.tv_usec - start.ru_utime.tv_usec;
-  ++sexp_context_gc_count(ctx);
   sexp_context_gc_usecs(ctx) += gc_usecs;
   sexp_debug_printf("%p (freed: %lu max_freed: %lu finalized: %lu time: %luus)",
                     ctx, (sum_freed ? *sum_freed : 0), sexp_unbox_fixnum(res),

include/chibi/features.h

@@ -446,7 +446,7 @@
 #endif
 
 #ifndef SEXP_USE_TIME_GC
-#define SEXP_USE_TIME_GC SEXP_USE_DEBUG_GC > 0
+#define SEXP_USE_TIME_GC (SEXP_USE_DEBUG_GC > 0 || defined(__linux) || SEXP_BSD)
 #endif
 
 #ifndef SEXP_USE_SAFE_GC_MARK