;;; {Profile} ;;; Copyright (C) 2009 Red Hat, Inc. ;;; This file is part of CGEN. ;;; See file COPYING.CGEN for details. ;;; ;;; This code is just an experimental prototype (e. g., it is not ;;; thread safe), but since it's at the same time useful, it's ;;; included anyway. ;;; ;;; This is copied from the tracing support in debug.scm. ;;; If merged into the main distribution it will need an efficiency ;;; and layout cleanup pass. ; FIXME: Prefix "proc-" added to not collide with cgen stuff. ; Put this stuff in the debug module since we need the trace facilities. (define-module (ice-9 profile) :use-module (ice-9 debug)) (define profiled-procedures '()) (define-public (profile-enable . args) (if (null? args) (nameify profiled-procedures) (begin (for-each (lambda (proc) (if (not (procedure? proc)) (error "profile: Wrong type argument:" proc)) ; `trace' is a magic property understood by guile (set-procedure-property! proc 'trace #t) (if (not (memq proc profiled-procedures)) (set! profiled-procedures (cons proc profiled-procedures)))) args) (set! apply-frame-handler profile-entry) (set! exit-frame-handler profile-exit) (debug-enable 'trace) (nameify args)))) (define-public (profile-disable . args) (if (and (null? args) (not (null? profiled-procedures))) (apply profile-disable profiled-procedures) (begin (for-each (lambda (proc) (set-procedure-property! proc 'trace #f) (set! profiled-procedures (delq! proc profiled-procedures))) args) (if (null? profiled-procedures) (debug-disable 'trace)) (nameify args)))) (define (nameify ls) (map (lambda (proc) (let ((name (procedure-name proc))) (or name proc))) ls)) ; Subroutine of profile-entry to find the calling procedure. ; Result is name of calling procedure or #f. (define (find-caller frame) (let ((prev (frame-previous frame))) (if prev ; ??? Not sure this is right. The goal is to find the real "caller". (if (and (frame-procedure? prev) ;(or (frame-real? prev) (not (frame-evaluating-args? prev))) (not (frame-evaluating-args? prev)) ) (let ((name (procedure-name (frame-procedure prev)))) (if name name 'lambda)) (find-caller prev)) 'top-level)) ) ; Return the current time. ; The result is a black box understood only by elapsed-time. (define (current-time) (gettimeofday)) ; Return the elapsed time in milliseconds since START. (define (elapsed-time start) (let ((now (gettimeofday))) (+ (* (- (car now) (car start)) 1000) (quotient (- (cdr now) (cdr start)) 1000))) ) ; Handle invocation of profiled procedures. (define (profile-entry key cont tail) (if (eq? (stack-id cont) 'repl-stack) (let* ((stack (make-stack cont)) (frame (stack-ref stack 0)) (proc (frame-procedure frame))) (if proc ; procedure-property returns #f if property not present (let ((counts (procedure-property proc 'profile-count))) (set-procedure-property! proc 'entry-time (current-time)) (if counts (let* ((caller (find-caller frame)) (count-elm (assq caller counts))) (if count-elm (set-cdr! count-elm (1+ (cdr count-elm))) (set-procedure-property! proc 'profile-count (acons caller 1 counts))))))))) ; SCM_TRACE_P is reset each time by the interpreter ;(display "entry\n" (current-error-port)) (debug-enable 'trace) ;; It's not necessary to call the continuation since ;; execution will continue if the handler returns ;(cont #f) ) ; Handle exiting of profiled procedures. (define (profile-exit key cont retval) ;(display "exit\n" (current-error-port)) (display (list key cont retval)) (newline) (display (stack-id cont)) (newline) (if (eq? (stack-id cont) 'repl-stack) (let* ((stack (make-stack cont)) (frame (stack-ref stack 0)) (proc (frame-procedure frame))) (display stack) (newline) (display frame) (newline) (if proc (set-procedure-property! proc 'total-time (+ (procedure-property proc 'total-time) (elapsed-time (procedure-property proc 'entry-time))))))) ; ??? Need to research if we have to do this or not. ; SCM_TRACE_P is reset each time by the interpreter (debug-enable 'trace) ) ; Called before something is to be profiled. ; All desired procedures to be profiled must have been previously selected. ; Property `profile-count' is an association list of caller name and call ; count. ; ??? Will eventually want to use a hash table or some such. (define-public (profile-init) (for-each (lambda (proc) (set-procedure-property! proc 'profile-count '()) (set-procedure-property! proc 'total-time 0)) profiled-procedures) ) ; Called after execution to print profile counts. ; If ARGS contains 'all, stats on all profiled procs are printed, not just ; those that were actually called. (define-public (profile-stats . args) (let ((stats (map (lambda (proc) (cons (procedure-name proc) (procedure-property proc 'profile-count))) profiled-procedures)) (all? (memq 'all args)) (sort (if (defined? 'sort) (local-ref '(sort)) (lambda args args)))) (display "Profiling results:\n\n") ; Print the procs in sorted order. (let ((stats (sort stats (lambda (a b) (string (cdr a) (cdr b)))))) (display (string-append (car proc-stats) "\n")) (for-each (lambda (call) (display (string-append " " (number->string (cdr call)) " " (car call) "\n"))) calls) (display " ") (display (apply + (map cdr calls))) (display " -- total\n\n")))) stats))) )