Mercurial > hg > xemacs-beta
diff lisp/utils/elp.el @ 0:376386a54a3c r19-14
Import from CVS: tag r19-14
author | cvs |
---|---|
date | Mon, 13 Aug 2007 08:45:50 +0200 |
parents | |
children | b82b59fe008d |
line wrap: on
line diff
--- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/lisp/utils/elp.el Mon Aug 13 08:45:50 2007 +0200 @@ -0,0 +1,601 @@ +;;; elp.el --- Emacs Lisp Profiler + +;; Copyright (C) 1994 Free Software Foundation, Inc. + +;; Author: 1994-1995 Barry A. Warsaw +;; Maintainer: tools-help@merlin.cnri.reston.va.us +;; Created: 26-Feb-1994 +;; Version: 2.32 +;; Last Modified: 1995/07/12 18:53:17 +;; Keywords: debugging lisp tools + +;; This file is part of GNU Emacs. + +;; GNU Emacs is free software; you can redistribute it and/or modify +;; it under the terms of the GNU General Public License as published by +;; the Free Software Foundation; either version 2, or (at your option) +;; any later version. + +;; GNU Emacs is distributed in the hope that it will be useful, +;; but WITHOUT ANY WARRANTY; without even the implied warranty of +;; MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +;; GNU General Public License for more details. + +;; You should have received a copy of the GNU General Public License +;; along with GNU Emacs; see the file COPYING. If not, write to +;; the Free Software Foundation, 675 Mass Ave, Cambridge, MA 02139, USA. + +;;; Synched up with: FSF 19.30. +;;; In typical "What the hell?" fashion, the version distributed +;;; with FSF 19.30 claims to be version 2.33 while ours is version 2.32, +;;; but ours is actually more recent. Is this another example of +;;; FSFmacs version corruption? + +;;; Commentary: +;; +;; If you want to profile a bunch of functions, set elp-function-list +;; to the list of symbols, then do a M-x elp-instrument-list. This +;; hacks those functions so that profiling information is recorded +;; whenever they are called. To print out the current results, use +;; M-x elp-results. If you want output to go to standard-output +;; instead of a separate buffer, setq elp-use-standard-output to +;; non-nil. With elp-reset-after-results set to non-nil, profiling +;; information will be reset whenever the results are displayed. You +;; can also reset all profiling info at any time with M-x +;; elp-reset-all. +;; +;; You can also instrument all functions in a package, provided that +;; the package follows the GNU coding standard of a common textural +;; prefix. Use M-x elp-instrument-package for this. +;; +;; If you want to sort the results, set elp-sort-by-function to some +;; predicate function. The three most obvious choices are predefined: +;; elp-sort-by-call-count, elp-sort-by-average-time, and +;; elp-sort-by-total-time. Also, you can prune from the output, all +;; functions that have been called fewer than a given number of times +;; by setting elp-report-limit. +;; +;; Elp can instrument byte-compiled functions just as easily as +;; interpreted functions, but it cannot instrument macros. However, +;; when you redefine a function (e.g. with eval-defun), you'll need to +;; re-instrument it with M-x elp-instrument-function. This will also +;; reset profiling information for that function. Elp can handle +;; interactive functions (i.e. commands), but of course any time spent +;; idling for user prompts will show up in the timing results. +;; +;; You can also designate a `master' function. Profiling times will +;; be gathered for instrumented functions only during execution of +;; this master function. Thus, if you have some defuns like: +;; +;; (defun foo () (do-something-time-intensive)) +;; (defun bar () (foo)) +;; (defun baz () (bar) (foo)) +;; +;; and you want to find out the amount of time spent in bar and foo, +;; but only during execution of bar, make bar the master. The call of +;; foo from baz will not add to foo's total timing sums. Use M-x +;; elp-set-master and M-x elp-unset-master to utilize this feature. +;; Only one master function can be set at a time. + +;; You can restore any function's original function definition with +;; elp-restore-function. The other instrument, restore, and reset +;; functions are provided for symmetry. + +;; Note that there are plenty of factors that could make the times +;; reported unreliable, including the accuracy and granularity of your +;; system clock, and the overhead spent in lisp calculating and +;; recording the intervals. The latter I figure is pretty constant +;; so, while the times may not be entirely accurate, I think they'll +;; give you a good feel for the relative amount of work spent in the +;; various lisp routines you are profiling. Note further that times +;; are calculated using wall-clock time, so other system load will +;; affect accuracy too. + +;; Here is a list of variable you can use to customize elp: +;; elp-function-list +;; elp-reset-after-results +;; elp-sort-by-function +;; elp-report-limit +;; +;; Here is a list of the interactive commands you can use: +;; elp-instrument-function +;; elp-restore-function +;; elp-instrument-list +;; elp-restore-list +;; elp-instrument-package +;; elp-restore-all +;; elp-reset-function +;; elp-reset-list +;; elp-reset-all +;; elp-set-master +;; elp-unset-master +;; elp-results +;; elp-submit-bug-report + +;; Note that there are plenty of factors that could make the times +;; reported unreliable, including the accuracy and granularity of your +;; system clock, and the overhead spent in lisp calculating and +;; recording the intervals. I figure the latter is pretty constant, +;; so while the times may not be entirely accurate, I think they'll +;; give you a good feel for the relative amount of work spent in the +;; various lisp routines you are profiling. Note further that times +;; are calculated using wall-clock time, so other system load will +;; affect accuracy too. You cannot profile anything longer than ~18 +;; hours since I throw away the most significant 16 bits of seconds +;; returned by current-time: 2^16 == 65536 seconds == ~1092 minutes == +;; ~18 hours. I doubt you will ever want to profile stuff on the +;; order of 18 hours anyway. + +;;; Background: +;; +;; This program was inspired by the only two existing Emacs Lisp +;; profilers that I'm aware of, Boaz Ben-Zvi's profile.el, and Root +;; Boy Jim's profiler.el. Both were written for Emacs 18 and both were +;; pretty good first shots at profiling, but I found that they didn't +;; provide the functionality or interface that I wanted, so I wrote +;; this. I've tested elp in XEmacs 19 and Emacs 19. There's no point +;; in even trying to make this work with Emacs 18. + +;; Unlike previous profilers, elp uses Emacs 19's built-in function +;; current-time to return interval times. This obviates the need for +;; both an external C program and Emacs processes to communicate with +;; such a program, and thus simplifies the package as a whole. + +;; TBD: +;; Make this act like a real profiler, so that it records time spent +;; in all branches of execution. + +;; LCD Archive Entry: +;; elp|Barry A. Warsaw|tools-help@merlin.cnri.reston.va.us| +;; Emacs Lisp Profiler| +;; 1995/07/12 18:53:17|2.32|~/misc/elp.el.Z| + +;;; Code: + + +;; start of user configuration variables +;; vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv + +(defvar elp-function-list nil + "*List of functions to profile. +Used by the command `elp-instrument-list'.") + +(defvar elp-reset-after-results t + "*Non-nil means reset all profiling info after results are displayed. +Results are displayed with the `elp-results' command.") + +(defvar elp-sort-by-function 'elp-sort-by-total-time + "*Non-nil specifies elp results sorting function. +These functions are currently available: + + elp-sort-by-call-count -- sort by the highest call count + elp-sort-by-total-time -- sort by the highest total time + elp-sort-by-average-time -- sort by the highest average times + +You can write you're own sort function. It should adhere to the +interface specified by the PRED argument for the `sort' defun. Each +\"element of LIST\" is really a 4 element vector where element 0 is +the call count, element 1 is the total time spent in the function, +element 2 is the average time spent in the function, and element 3 is +the symbol's name string.") + +(defvar elp-report-limit 1 + "*Prevents some functions from being displayed in the results buffer. +If a number, no function that has been called fewer than that number +of times will be displayed in the output buffer. If nil, all +functions will be displayed.") + +(defvar elp-use-standard-output nil + "*Non-nil says to output to `standard-output' instead of a buffer.") + +(defvar elp-recycle-buffers-p t + "*Nil says to not recycle the `elp-results-buffer'. +In other words, a new unique buffer is create every time you run +\\[elp-results].") + + +;; ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ +;; end of user configuration variables + + +(defconst elp-version "2.32" + "ELP version number.") + +(defconst elp-help-address "tools-help@merlin.cnri.reston.va.us" + "Address accepting submissions of bug reports and questions.") + +(defvar elp-results-buffer "*ELP Profiling Results*" + "Buffer name for outputting profiling results.") + +(defconst elp-timer-info-property 'elp-info + "ELP information property name.") + +(defvar elp-all-instrumented-list nil + "List of all functions currently being instrumented.") + +(defvar elp-record-p t + "Controls whether functions should record times or not. +This variable is set by the master function.") + +(defvar elp-master nil + "Master function symbol.") + + +;;;###autoload +(defun elp-instrument-function (funsym) + "Instrument FUNSYM for profiling. +FUNSYM must be a symbol of a defined function." + (interactive "aFunction to instrument: ") + ;; raise an error if the function is already instrumented + (and (get funsym elp-timer-info-property) + (error "Symbol `%s' is already instrumented for profiling." funsym)) + (let* ((funguts (symbol-function funsym)) + (infovec (vector 0 0 funguts)) + (newguts '(lambda (&rest args)))) + ;; we cannot profile macros + (and (eq (car-safe funguts) 'macro) + (error "ELP cannot profile macro %s" funsym)) + ;; put rest of newguts together + (if (commandp funsym) + (setq newguts (append newguts '((interactive))))) + (setq newguts (append newguts (list + (list 'elp-wrapper + (list 'quote funsym) + (list 'and + '(interactive-p) + (not (not (commandp funsym)))) + 'args)))) + ;; to record profiling times, we set the symbol's function + ;; definition so that it runs the elp-wrapper function with the + ;; function symbol as an argument. We place the old function + ;; definition on the info vector. + ;; + ;; The info vector data structure is a 3 element vector. The 0th + ;; element is the call-count, i.e. the total number of times this + ;; function has been entered. This value is bumped up on entry to + ;; the function so that non-local exists are still recorded. TBD: + ;; I haven't tested non-local exits at all, so no guarantees. + ;; + ;; The 1st element is the total amount of time in usecs that have + ;; been spent inside this function. This number is added to on + ;; function exit. + ;; + ;; The 2nd element is the old function definition list. This gets + ;; funcall'd in between start/end time retrievals. I believe that + ;; this lets us profile even byte-compiled functions. + + ;; put the info vector on the property list + (put funsym elp-timer-info-property infovec) + + ;; set the symbol's new profiling function definition to run + ;; elp-wrapper + (fset funsym newguts) + + ;; add this function to the instrumentation list + (or (memq funsym elp-all-instrumented-list) + (setq elp-all-instrumented-list + (cons funsym elp-all-instrumented-list))) + )) + +;;;###autoload +(defun elp-restore-function (funsym) + "Restore an instrumented function to its original definition. +Argument FUNSYM is the symbol of a defined function." + (interactive "aFunction to restore: ") + (let ((info (get funsym elp-timer-info-property))) + ;; delete the function from the all instrumented list + (setq elp-all-instrumented-list + (delq funsym elp-all-instrumented-list)) + + ;; if the function was the master, reset the master + (if (eq funsym elp-master) + (setq elp-master nil + elp-record-p t)) + + ;; zap the properties + (put funsym elp-timer-info-property nil) + + ;; restore the original function definition, but if the function + ;; wasn't instrumented do nothing. we do this after the above + ;; because its possible the function got un-instrumented due to + ;; circumstances beyond our control. Also, check to make sure + ;; that the current function symbol points to elp-wrapper. If + ;; not, then the user probably did an eval-defun while the + ;; function was instrumented and we don't want to destroy the new + ;; definition. + (and info + (assq 'elp-wrapper (symbol-function funsym)) + (fset funsym (aref info 2))))) + +;;;###autoload +(defun elp-instrument-list (&optional list) + "Instrument for profiling, all functions in `elp-function-list'. +Use optional LIST if provided instead." + (interactive "PList of functions to instrument: ") + (let ((list (or list elp-function-list))) + (mapcar + (function + (lambda (funsym) + (condition-case nil + (elp-instrument-function funsym) + (error nil)))) + list))) + +;;;###autoload +(defun elp-instrument-package (prefix) + "Instrument for profiling, all functions which start with PREFIX. +For example, to instrument all ELP functions, do the following: + + \\[elp-instrument-package] RET elp- RET" + (interactive "sPrefix of package to instrument: ") + (elp-instrument-list + (mapcar 'intern (all-completions prefix obarray + (function + (lambda (sym) + (and (fboundp sym) + (not (eq (car-safe + (symbol-function sym)) + 'macro))))))))) + +(defun elp-restore-list (&optional list) + "Restore the original definitions for all functions in `elp-function-list'. +Use optional LIST if provided instead." + (interactive "PList of functions to restore: ") + (let ((list (or list elp-function-list))) + (mapcar 'elp-restore-function list))) + +(defun elp-restore-all () + "Restores the original definitions of all functions being profiled." + (interactive) + (elp-restore-list elp-all-instrumented-list)) + + +(defun elp-reset-function (funsym) + "Reset the profiling information for FUNSYM." + (interactive "aFunction to reset: ") + (let ((info (get funsym elp-timer-info-property))) + (or info + (error "%s is not instrumented for profiling." funsym)) + (aset info 0 0) ;reset call counter + (aset info 1 0.0) ;reset total time + ;; don't muck with aref 2 as that is the old symbol definition + )) + +(defun elp-reset-list (&optional list) + "Reset the profiling information for all functions in `elp-function-list'. +Use optional LIST if provided instead." + (interactive "PList of functions to reset: ") + (let ((list (or list elp-function-list))) + (mapcar 'elp-reset-function list))) + +(defun elp-reset-all () + "Reset the profiling information for all functions being profiled." + (interactive) + (elp-reset-list elp-all-instrumented-list)) + +(defun elp-set-master (funsym) + "Set the master function for profiling." + (interactive "aMaster function: ") + ;; when there's a master function, recording is turned off by + ;; default + (setq elp-master funsym + elp-record-p nil) + ;; make sure master function is instrumented + (or (memq funsym elp-all-instrumented-list) + (elp-instrument-function funsym))) + +(defun elp-unset-master () + "Unsets the master function." + (interactive) + ;; when there's no master function, recording is turned on by default. + (setq elp-master nil + elp-record-p t)) + + +(defsubst elp-get-time () + ;; get current time in seconds and microseconds. I throw away the + ;; most significant 16 bits of seconds since I doubt we'll ever want + ;; to profile lisp on the order of 18 hours. See notes at top of file. + (let ((now (current-time))) + (+ (float (nth 1 now)) (/ (float (nth 2 now)) 1000000.0)))) + +(defun elp-wrapper (funsym interactive-p args) + "This function has been instrumented for profiling by the ELP. +ELP is the Emacs Lisp Profiler. To restore the function to its +original definition, use \\[elp-restore-function] or \\[elp-restore-all]." + ;; turn on recording if this is the master function + (if (and elp-master + (eq funsym elp-master)) + (setq elp-record-p t)) + ;; get info vector and original function symbol + (let* ((info (get funsym elp-timer-info-property)) + (func (aref info 2)) + result) + (or func + (error "%s is not instrumented for profiling." funsym)) + (if (not elp-record-p) + ;; when not recording, just call the original function symbol + ;; and return the results. + (setq result + (if interactive-p + (call-interactively func) + (apply func args))) + ;; we are recording times + (let ((enter-time (elp-get-time))) + ;; increment the call-counter + (aset info 0 (1+ (aref info 0))) + ;; now call the old symbol function, checking to see if it + ;; should be called interactively. make sure we return the + ;; correct value + (setq result + (if interactive-p + (call-interactively func) + (apply func args))) + ;; calculate total time in function + (aset info 1 (+ (aref info 1) (- (elp-get-time) enter-time))) + )) + ;; turn off recording if this is the master function + (if (and elp-master + (eq funsym elp-master)) + (setq elp-record-p nil)) + result)) + + +;; shut the byte-compiler up +(defvar elp-field-len nil) +(defvar elp-cc-len nil) +(defvar elp-at-len nil) +(defvar elp-et-len nil) + +(defun elp-sort-by-call-count (vec1 vec2) + ;; sort by highest call count. See `sort'. + (>= (aref vec1 0) (aref vec2 0))) + +(defun elp-sort-by-total-time (vec1 vec2) + ;; sort by highest total time spent in function. See `sort'. + (>= (aref vec1 1) (aref vec2 1))) + +(defun elp-sort-by-average-time (vec1 vec2) + ;; sort by highest average time spent in function. See `sort'. + (>= (aref vec1 2) (aref vec2 2))) + +(defsubst elp-pack-number (number width) + ;; pack the NUMBER string into WIDTH characters, watching out for + ;; very small or large numbers + (if (<= (length number) width) + number + ;; check for very large or small numbers + (if (string-match "^\\(.*\\)\\(e[+-].*\\)$" number) + (concat (substring + (substring number (match-beginning 1) (match-end 1)) + 0 + (- width (match-end 2) (- (match-beginning 2)) 3)) + "..." + (substring number (match-beginning 2) (match-end 2))) + (concat (substring number 0 width))))) + +(defun elp-output-result (resultvec) + ;; output the RESULTVEC into the results buffer. RESULTVEC is a 4 or + ;; more element vector where aref 0 is the call count, aref 1 is the + ;; total time spent in the function, aref 2 is the average time + ;; spent in the function, and aref 3 is the symbol's string + ;; name. All other elements in the vector are ignored. + (let* ((cc (aref resultvec 0)) + (tt (aref resultvec 1)) + (at (aref resultvec 2)) + (symname (aref resultvec 3)) + callcnt totaltime avetime) + (setq callcnt (number-to-string cc) + totaltime (number-to-string tt) + avetime (number-to-string at)) + ;; possibly prune the results + (if (and elp-report-limit + (numberp elp-report-limit) + (< cc elp-report-limit)) + nil + (insert symname) + (insert-char 32 (+ elp-field-len (- (length symname)) 2)) + ;; print stuff out, formatting it nicely + (insert callcnt) + (insert-char 32 (+ elp-cc-len (- (length callcnt)) 2)) + (let ((ttstr (elp-pack-number totaltime elp-et-len)) + (atstr (elp-pack-number avetime elp-at-len))) + (insert ttstr) + (insert-char 32 (+ elp-et-len (- (length ttstr)) 2)) + (insert atstr)) + (insert "\n")))) + +;;;###autoload +(defun elp-results () + "Display current profiling results. +If `elp-reset-after-results' is non-nil, then current profiling +information for all instrumented functions are reset after results are +displayed." + (interactive) + (let ((curbuf (current-buffer)) + (resultsbuf (if elp-recycle-buffers-p + (get-buffer-create elp-results-buffer) + (generate-new-buffer elp-results-buffer)))) + (set-buffer resultsbuf) + (erase-buffer) + (beginning-of-buffer) + ;; get the length of the longest function name being profiled + (let* ((longest 0) + (title "Function Name") + (titlelen (length title)) + (elp-field-len titlelen) + (cc-header "Call Count") + (elp-cc-len (length cc-header)) + (et-header "Elapsed Time") + (elp-et-len (length et-header)) + (at-header "Average Time") + (elp-at-len (length at-header)) + (resvec + (mapcar + (function + (lambda (funsym) + (let* ((info (get funsym elp-timer-info-property)) + (symname (format "%s" funsym)) + (cc (aref info 0)) + (tt (aref info 1))) + (if (not info) + (insert "No profiling information found for: " + symname) + (setq longest (max longest (length symname))) + (vector cc tt (if (zerop cc) + 0.0 ;avoid arithmetic div-by-zero errors + (/ (float tt) (float cc))) + symname))))) + elp-all-instrumented-list)) + ) ; end let* + (insert title) + (if (> longest titlelen) + (progn + (insert-char 32 (- longest titlelen)) + (setq elp-field-len longest))) + (insert " " cc-header " " et-header " " at-header "\n") + (insert-char ?= elp-field-len) + (insert " ") + (insert-char ?= elp-cc-len) + (insert " ") + (insert-char ?= elp-et-len) + (insert " ") + (insert-char ?= elp-at-len) + (insert "\n") + ;; if sorting is enabled, then sort the results list. in either + ;; case, call elp-output-result to output the result in the + ;; buffer + (if elp-sort-by-function + (setq resvec (sort resvec elp-sort-by-function))) + (mapcar 'elp-output-result resvec)) + ;; now pop up results buffer + (set-buffer curbuf) + (pop-to-buffer resultsbuf) + ;; copy results to standard-output? + (if (or elp-use-standard-output noninteractive) + (princ (buffer-substring (point-min) (point-max)))) + ;; reset profiling info if desired + (and elp-reset-after-results + (elp-reset-all)))) + + +(eval-when-compile + (require 'reporter)) + +;;;###autoload +(defun elp-submit-bug-report () + "Submit via mail, a bug report on elp." + (interactive) + (and + (y-or-n-p "Do you want to submit a report on elp? ") + (require 'reporter) + (reporter-submit-bug-report + elp-help-address (concat "elp " elp-version) + '(elp-report-limit + elp-reset-after-results + elp-sort-by-function)))) + + +(provide 'elp) + +;; elp.el ends here