more consistent expander/linklet performance-logging output
This commit is contained in:
Matthew Flatt
parent
f46721fe85
commit
9658c723db
|
|
@ -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)))))
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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 ...)
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
|
|
@ -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"
|
||||
|
|
|
|||
Loading…
Reference in New Issue
Block a user