From 9658c723db58b4a902dbd6dec22a3380d9620911 Mon Sep 17 00:00:00 2001 From: Matthew Flatt Date: Wed, 15 Aug 2018 07:41:29 -0600 Subject: [PATCH] more consistent expander/linklet performance-logging output --- racket/src/cs/linklet/performance.ss | 26 ++++---- racket/src/expander/README.txt | 18 +++++- racket/src/expander/common/performance.rkt | 2 +- racket/src/racket/src/linklet.c | 69 +++++++++++++--------- racket/src/racket/src/startup.inc | 2 +- 5 files changed, 73 insertions(+), 44 deletions(-) diff --git a/racket/src/cs/linklet/performance.ss b/racket/src/cs/linklet/performance.ss index faabd65a79..18afe64dbb 100644 --- a/racket/src/cs/linklet/performance.ss +++ b/racket/src/cs/linklet/performance.ss @@ -61,21 +61,23 @@ (compile (compile-linklet compile-nested)))] [region-subs (make-eq-hashtable)] [region-gc-subs (make-eq-hashtable)]) + (define (lprintf fmt . args) + (log-message root-logger 'error (apply #%format fmt args) #f)) (define (pad v w combine) - (let ([s (chez:format "~a" v)]) + (let ([s (#%format "~a" v)]) (combine (make-string (max 0 (- w (string-length s))) #\space) s))) (define (pad-left v w) (pad v w string-append)) (define (pad-right v w) (pad v w (lambda (p s) (string-append s p)))) (define (report level label n n-extra units extra) - (chez:printf ";; ~a~a~a ~a~a ~a~a\n" - (make-string (* level 2) #\space) - (pad-right label name-len) - (make-string (* (- 3 level) 2) #\space) - (pad-left (round (inexact->exact n)) len) - n-extra - units - extra)) + (lprintf ";; ~a~a~a ~a~a ~a~a" + (make-string (* level 2) #\space) + (pad-right label name-len) + (make-string (* (- 3 level) 2) #\space) + (pad-left (round (inexact->exact n)) len) + n-extra + units + extra)) (define (ht->sorted-list ht) (list-sort (lambda (a b) (< (cdr a) (cdr b))) (hash-table-map ht cons))) @@ -93,12 +95,12 @@ (+ v (loop (cdr keys))))]))) (define (report-time level label n gc-ht) (report level label n - (chez:format " [~a]" (pad-left (hashtable-ref gc-ht label 0) gc-len)) + (#%format " [~a]" (pad-left (hashtable-ref gc-ht label 0) gc-len)) 'ms (let ([c (hashtable-ref region-counts label 0)]) (if (zero? c) "" - (chez:format " ; ~a times" c))))) + (#%format " ; ~a times" c))))) (for-each (lambda (l) (let* ([cat (car l)] [subs (cadr l)] @@ -119,6 +121,6 @@ (loop sub-ht sub-gc-ht (add1 level)))))) (ht->sorted-list ht))) (report 0 'total total (#%format " [~a]" gc-total) 'ms "") - (chez:printf ";;\n") + (lprintf ";;") (for-each (lambda (p) (report 0 (car p) (/ (cdr p) 1024 1024) "" 'MB "")) (ht->sorted-list region-memories))))) diff --git a/racket/src/expander/README.txt b/racket/src/expander/README.txt index 18749d9454..2b0d05d681 100644 --- a/racket/src/expander/README.txt +++ b/racket/src/expander/README.txt @@ -144,8 +144,6 @@ Roadmap to the implementation: common/ - utilities module-path.rkt - [resolved] module path [indexes] - performance.rkt - performance instrumentation; enable statistic - gathering and reporting by changing this module compile/ - from expanded to S-expression linklet main.rkt - compiler functions called from "eval/main.rkt" @@ -195,6 +193,22 @@ needs `syntax?` must import "syntax/syntax.rkt" or ---------------------------------------- +Performance measurements: + +Set the `PLT_EXPANDER_TIMES` environment variable for a summary of +performance information (written via `log-error`, which normally goes +to stderr) on exit. In the output, a category that is nested under +another category contributes to the latter's recorded time and memory +use, but not to its counts. Beware that taking measurements can slow +down the expander slightly. + +Set the `PLT_LINKLET_TIMES` environment variable to get similar +information from the underlying runtime system. Except for compile +times, linklet-level times generally will be disjoint from the times +reported by the expander. + +---------------------------------------- + Implementation guidelines: * Do not rely on more than `racket/base` for code that will be diff --git a/racket/src/expander/common/performance.rkt b/racket/src/expander/common/performance.rkt index 98ff88e0b4..39ed2c80cd 100644 --- a/racket/src/expander/common/performance.rkt +++ b/racket/src/expander/common/performance.rkt @@ -36,7 +36,7 @@ (define log-performance? (and (environment-variables-ref (current-environment-variables) - #"PLT_EXPAND_TIMES") + #"PLT_EXPANDER_TIMES") #t)) (define-syntax-rule (performance-region [tag0-expr tag-expr ...] body ...) diff --git a/racket/src/racket/src/linklet.c b/racket/src/racket/src/linklet.c index 01f2f0e94f..984d121940 100644 --- a/racket/src/racket/src/linklet.c +++ b/racket/src/racket/src/linklet.c @@ -1856,11 +1856,11 @@ static void sort_perf(Performance_Entry *pref_entries, int lo, int hi) } static void show_perf(Performance_Entry *perf_entries, int perf_count, - int len, int name_len, + int len, int name_len, int gc_len, int depth) { intptr_t total = 0, gc_total = 0; - int i, j, k, m, n, gc_len; + int i, j, k, m, n; char name_tab[16], tab[10], gc_tab[10], pre_indent[8], post_indent[8]; Performance_Cat cats[MAX_PERF_CATS]; int num_cats = 0; @@ -1888,7 +1888,7 @@ static void show_perf(Performance_Entry *perf_entries, int perf_count, if (perf_count <= k) perf_count = k+1; perf_entries[k].accum += perf_entries[i].accum; perf_entries[k].gc_accum += perf_entries[i].gc_accum; - perf_entries[k].count += perf_entries[i].count; + perf_entries[k].count = -1; n = cats[m].perf_count++; cats[m].perf_entries[n] = perf_entries[i]; @@ -1911,7 +1911,8 @@ static void show_perf(Performance_Entry *perf_entries, int perf_count, n = numlen(total); if (n > len) len = n; - gc_len = numlen(gc_total); + n = numlen(gc_total); + if (n > gc_len) gc_len = n; if (name_len >= sizeof(name_tab)) name_len = sizeof(name_tab) - 1; @@ -1928,45 +1929,57 @@ static void show_perf(Performance_Entry *perf_entries, int perf_count, post_indent[i] = ' '; } post_indent[i] = 0; - + + if (!depth) + scheme_log(NULL, SCHEME_LOG_ERROR, 0, ";;"); + +#define BASE_TIMES_TEMPLATE ";; %s%s%s%s %s%ld [%s%ld] ms" +#define FULL_TIMES_TEMPLATE BASE_TIMES_TEMPLATE " ; %ld times" + for (i = 0; i < perf_count; i++) { if (perf_entries[i].count) - fprintf(stderr, ";; %s%s%s%s %s%"PRIdPTR " [%s%"PRIdPTR"] ms ; %"PRIdPTR" times\n", - pre_indent, - perf_entries[i].name, - tab_string(perf_entries[i].name, name_tab, name_len), - post_indent, - tab_number(perf_entries[i].accum, tab, len), - perf_entries[i].accum, - tab_number(perf_entries[i].gc_accum, gc_tab, gc_len), - perf_entries[i].gc_accum, - perf_entries[i].count); + scheme_log(NULL, SCHEME_LOG_ERROR, 0, + ((perf_entries[i].count < 0) + ? BASE_TIMES_TEMPLATE + : FULL_TIMES_TEMPLATE), + pre_indent, + perf_entries[i].name, + tab_string(perf_entries[i].name, name_tab, name_len), + post_indent, + tab_number(perf_entries[i].accum, tab, len), + perf_entries[i].accum, + tab_number(perf_entries[i].gc_accum, gc_tab, gc_len), + perf_entries[i].gc_accum, + perf_entries[i].count); for (m = 0; m < num_cats; m++) { if (!strcmp(perf_entries[i].name, cats[m].name)) - show_perf(cats[m].perf_entries, cats[m].perf_count, len, name_len, depth+1); + show_perf(cats[m].perf_entries, cats[m].perf_count, len, name_len, gc_len, depth+1); } } if (!depth) { - fprintf(stderr, ";; %stotal%s %s%"PRIdPTR " [%s%"PRIdPTR"] ms\n", - tab_number(total, tab, len), - tab_string("total", name_tab, name_len), - post_indent, - total, - tab_number(gc_total, gc_tab, gc_len), - gc_total); + scheme_log(NULL, SCHEME_LOG_ERROR, 0, + ";; %stotal%s %s%ld [%s%ld] ms", + tab_number(total, tab, len), + tab_string("total", name_tab, name_len), + post_indent, + total, + tab_number(gc_total, gc_tab, gc_len), + gc_total); #ifdef MZ_PRECISE_GC - fprintf(stderr, ";; [JIT code: %"PRIdPTR" procs %"PRIdPTR" bytes JIT code+admin: %"PRIdPTR" bytes]\n", - scheme_code_count, - scheme_code_total, - scheme_code_page_total); + scheme_log(NULL, SCHEME_LOG_ERROR, 0, ";;"); + scheme_log(NULL, SCHEME_LOG_ERROR, 0, + ";; [JIT code: %d procs %d bytes code+admin: %d bytes]", + scheme_code_count, + scheme_code_total, + scheme_code_page_total); #endif } } static void show_all_perf() { - return show_perf(perf_entries, perf_count, 0, 0, 0); + return show_perf(perf_entries, perf_count, 0, 0, 0, 0); } void scheme_performance_record_start(GC_CAN_IGNORE Scheme_Performance_State *perf_state) diff --git a/racket/src/racket/src/startup.inc b/racket/src/racket/src/startup.inc index 1885c24334..6a53684897 100644 --- a/racket/src/racket/src/startup.inc +++ b/racket/src/racket/src/startup.inc @@ -12775,7 +12775,7 @@ static const char *startup_source = "(define-values(set-current-previously-unbound!)(lambda(proc_0)(begin(set! current-previously-unbound proc_0))))" "(define-values" "(log-performance?)" -" (if (environment-variables-ref (current-environment-variables) #\"PLT_EXPAND_TIMES\") #t #f))" +" (if (environment-variables-ref (current-environment-variables) #\"PLT_EXPANDER_TIMES\") #t #f))" "(define-values(region-stack) #f)" "(define-values(accums)(make-hasheq))" "(define-values"