Mercurial > hg > xemacs-beta
diff lisp/prim/profile.el @ 199:169c0442b401 r20-3b26
Import from CVS: tag r20-3b26
author | cvs |
---|---|
date | Mon, 13 Aug 2007 10:00:33 +0200 |
parents | 8eaf7971accc |
children | eb5470882647 |
line wrap: on
line diff
--- a/lisp/prim/profile.el Mon Aug 13 10:00:04 2007 +0200 +++ b/lisp/prim/profile.el Mon Aug 13 10:00:33 2007 +0200 @@ -1,6 +1,6 @@ ;;; profile.el --- basic profiling commands for XEmacs -;; Copyright (C) 1996 Ben Wing. +;; Copyright (C) 1996 Ben Wing, (C) 1997 Free Software Foundation. ;; Maintainer: XEmacs Development Team ;; Keywords: internal @@ -26,8 +26,36 @@ ;;; Commentary: -;; `profile' macro and `profile-key-sequence' added in June 1997 by -;; hniksic. +;; In addition to Lisp-based `elp', XEmacs contains a set of +;; primitives able to profile evaluation of Lisp functions, created by +;; the illustrious Ben Wing. The functions in this file can be used +;; to gain easy access to the internal profiling functions. + +;; The profiler works by catching "ticks" (actually SIGPROF signals), +;; and looking at the current Lisp function, at the time of each tick. +;; The output of this process is an alist with keys being the +;; functions, and values being the number of ticks per function. From +;; this, `pretty-print-profiling-info' easily extracts the total +;; number of ticks, and the percentage CPU time of each function. + +;; Unless stated otherwise, profiling info is being accumulated (the +;; current info is returned by `get-profiling-info'). Use +;; `clear-profiling-info' to break the accumulation chain. + +;; Caveats (ELP users should read this): +;; 1) The time reported is function time, rather than +;; function+descendants time; +;; 2) The Time/ms is CPU time (user+kernel), not the real time; +;; 3) Only the actuall funcalls are profiled. If a subr Ffoo calls +;; Fbar using Fbar (), only Ffoo will appear in the profile. + +;; A typical profiling session consists of using `clear-profiling-info' +;; followed by `profile' or `profile-key-sequence', followed by +;; `pretty-print-profiling-info'. + +;; For instance, to see where Gnus spends time when generating Summary +;; buffer, go to the group buffer, and press `M-x clear-profiling-info' +;; followed by `M-x profile-key-sequence RET SPC'. ;;; Code: @@ -36,28 +64,51 @@ (defun pretty-print-profiling-info (&optional info stream) "Print profiling info INFO to STREAM in a pretty format. If INFO is omitted, the current profiling info is retrieved using -`get-profiling-info'. -If STREAM is omitted, either current buffer or standard output are used, - depending on whether the function was called interactively or not." + `get-profiling-info'. +If STREAM is omitted, either a *Profiling Results* buffer or standard + output are used, depending on whether the function was called + interactively or not." (interactive) - (if info - (setq info (copy-alist info)) - (setq info (get-profiling-info))) - (let ((standard-output (or stream (if (interactive-p) - (current-buffer) - standard-output)))) + (setq info (if info + (copy-alist info) + (get-profiling-info))) + (when (and (not stream) + (interactive-p)) + (pop-to-buffer (get-buffer-create "*Profiling Results*")) + (erase-buffer)) + (let* ((standard-output (or stream (if (interactive-p) + (current-buffer) + standard-output))) + (maxfunlen (max (length "Function Name") + (apply 'max (mapcar (lambda (sym) + (length (symbol-name + (car sym)))) + info)))) + (formatstr (format "%%-%ds" maxfunlen))) (setq info (nreverse (sort info #'cdr-less-than-cdr))) - (princ "Function Count %\n") - (princ "---------------------------------------------------------------------\n") + (princ (format (concat formatstr " Ticks %%/Total\n") + "Function Name")) + (princ (make-string maxfunlen ?=)) + (princ " ===== =======\n") (let ((sum 0.0)) (dolist (info2 info) (incf sum (cdr info2))) (while info (let ((f (caar info))) - (princ (format "%-50s%10d %6.3f\n" f (cdar info) - (* 100 (/ (cdar info) sum))))) - (pop info))))) + (princ (format (concat formatstr " %-5d %-6.3f\n") + f (cdar info) (* 100 (/ (cdar info) sum))))) + (pop info)) + (princ (make-string maxfunlen ?-)) + (princ "--------------------\n") + (princ (format (concat formatstr " %-5d %-6.2f\n") + "Total" sum 100.0)) + (princ (format "\n\nOne tick = %g ms\n" + (/ default-profiling-interval 1000.0))))) + (when (and (not stream) + (interactive-p)) + (goto-char (point-min)))) +;; Is it really necessary for this to be a macro? ;;;###autoload (defmacro profile (&rest forms) "Turn on profiling, execute FORMS and restore profiling state.