comparison lisp/emacs-lisp/profile.el @ 23512:1cd5555e67a9

(profile-timer-program): Var deleted. (profile-timer-process, profile-temp-result-, profile-time): Likewise. (profile-filter, profile-reset-timer): Functions deleted. (profile-check-zero-init-times, profile-get-time): Likewise. (profile-find-function, profile-quit): Likewise. (profile-distinct, profile-call-stack, profile-last-time): New vars. (profile-time-list, profile-init-list): Doc fix. (profile-functions): Simplify. (profile-print): Use float. Make output include space separators. (profile-add-time): New helper function. (profile-function-prolog): Renamed from profile-start-function. Handle profile-distinct. (profile-function-epilog): Renamed from profile-update-function. Handle profile-distinct. (profile-a-function): If the function to be profiled is an autoload form, load it. If it's lazy-loaded, fetch it. (profile-fix-fun): Simplify profiling wrapper, and unwind-protect it. (profile-restore-fun): Arg FUN is now a function symbol, as was documented, rather than a one-element list. (profile-finish): Call profile-restore-fun properly.

23511:8b4cdcbaf071

;;; profile.el --- generate run time measurements of Emacs Lisp functions

;; Copyright (C) 1992, 1994 Free Software Foundation, Inc.

;; Author: Boaz Ben-Zvi <[e-mail]>
;; Created: 07 Feb 1992
;; Version: 1.0
;; Adapted-By: ESR

;;; Commentary:

;; DESCRIPTION:
;; ------------
;;   This program can be used to monitor running time performance of Emacs Lisp
;; functions. It takes a list of functions and report the real time spent 
;; inside these functions. It runs a process with a separate timer program.
;;   Caveat: the C code in ../lib-src/profile.c requires BSD-compatible
;; time-of-day functions.  If you're running an AT&T version prior to SVr4,
;; you may have difficulty getting it to work.  Your X library may supply
;; the required routines if the standard C library does not.

;; HOW TO USE:
;; -----------
;;   Set the variable  profile-functions-list  to the list of functions
;; (as symbols) You want to profile. Call  M-x  profile-functions to set 
;; this list on and start using your program.  Note that profile-functions 
;; MUST be called AFTER all the functions in profile-functions-list have 
;; been loaded !!   (This call modifies the code of the profiled functions.
;; Hence if you reload these functions, you need to call  profile-functions  
;; again! ).
;;   To display the results do  M-x  profile-results .  For example:
;;-------------------------------------------------------------------
;;  (setq profile-functions-list '(sokoban-set-mode-line sokoban-load-game 
;;	                          sokoban-move-vertical sokoban-move))
;;  (load "sokoban")
;;  M-x profile-functions
;;     ...  I play the sokoban game ..........
;;  M-x profile-results

;;      sokoban-move                     0.539088
;;      sokoban-move-vertical            0.410130
;;      sokoban-load-game                0.453235
;;      sokoban-set-mode-line            1.949203
;;-----------------------------------------------------
;; To clear all the settings to profile use profile-finish. 
;; To set one function at a time (instead of or in addition to setting the 
;; above list and  M-x profile-functions) use M-x profile-a-function.

;;; Code:

(defgroup profile nil
  "Generate run time measurements of Emacs Lisp functions."
  :prefix "profile-"
  :group 'lisp)

;;;
;;;  User modifiable VARIABLES
;;;

(defcustom profile-functions-list nil 
  "*List of functions to profile."
  :type '(repeat function)
  :group 'profile)

(defcustom profile-timer-program
  (concat exec-directory "profile")
  "*Name of the profile timer program."
  :type 'file
  :group 'profile)

;;;
;;; V A R I A B L E S
;;;

(defvar profile-timer-process nil "Process running the timer.")
(defvar profile-time-list nil 
    "List of cumulative calls and time for each profiled function.")
(defvar profile-init-list nil
    "List of entry time for each function. 
Both how many times invoked and real time of start.")
(defvar profile-max-fun-name 0 "Max length of name of any function profiled.")
(defvar profile-temp-result- nil "Should NOT be used anywhere else.")
(defvar profile-time (cons 0 0) "Used to return result from a filter.")
(defcustom profile-buffer "*profile*" 
  "Name of profile buffer."
  :type 'string
  :group 'profile)

(defconst profile-million 1000000)

;;;
;;; F U N C T I O N S

(defun profile-functions (&optional flist)
  "Profile all the functions listed in `profile-functions-list'.
With argument FLIST, use the list FLIST instead."
  (interactive "P")
  (if (null flist) (setq flist profile-functions-list))
  (mapcar 'profile-a-function flist))

(defun profile-filter (process input)
  "Filter for the timer process.  Sets `profile-time' to the returned time."
  (if (zerop (string-match "\\." input)) 
      (error "Bad output from %s" profile-timer-program)
    (setcar profile-time 
	    (string-to-int (substring input 0 (match-beginning 0))))
    (setcdr profile-time 
	    (string-to-int (substring input (match-end 0))))))


(defun profile-print (entry)
  "Print one ENTRY (from `profile-time-list')."
  (let* ((calls (car (cdr entry)))
	 (timec (cdr (cdr entry)))
	 (time (+ (car timec) (/ (cdr timec) (float profile-million))))
	 (avgtime 0.0))
    (insert (format (concat "%-"
			    (int-to-string profile-max-fun-name)
			    "s%8d%11d.%06d")
		    (car entry) calls (car timec) (cdr timec))
	    (if (zerop calls)
		"\n"
	      (format "%12d.%06d\n"
		      (truncate (setq avgtime (/ time calls)))
		      (truncate (* (- avgtime (ftruncate avgtime))
				   profile-million))))
	    )))

(defun profile-results ()
  "Display profiling results in the buffer `*profile*'.
\(The buffer name comes from `profile-buffer'.)"
  (interactive)

  (insert "Function" (make-string (- profile-max-fun-name 6) ? ))
  (insert " Calls  Total time (sec)  Avg time per call\n")
  (insert (make-string profile-max-fun-name ?=) "  ")
  (insert "======  ================  =================\n")
  (mapcar 'profile-print profile-time-list))
    
(defun profile-reset-timer ()
  (process-send-string profile-timer-process "z\n"))

(defun profile-check-zero-init-times (entry)
  "If ENTRY has non zero time, give an error."
  (let ((time (cdr (cdr entry))))
    (if (and (zerop (car time)) (zerop (cdr time))) nil ; OK
      (error "Process timer died while making performance profile."))))

(defun profile-get-time ()
  "Get time from timer process into `profile-time'."
  ;; first time or if process dies
  (if (and (processp profile-timer-process)
	   (eq 'run (process-status profile-timer-process))) nil
    (setq profile-timer-process;; [re]start the timer process
	  (start-process "timer" 
			 (get-buffer-create profile-buffer) 
			 profile-timer-program))
    (set-process-filter profile-timer-process 'profile-filter)
    (process-kill-without-query profile-timer-process)
    (profile-reset-timer)
    ;; check if timer died during time measurement
    (mapcar 'profile-check-zero-init-times profile-init-list)) 
  ;; make timer process return current time
  (process-send-string profile-timer-process "p\n")
  (accept-process-output))

(defun profile-find-function (fun flist)
  "Linear search for FUN in FLIST."
  (if (null flist) nil
    (if (eq fun (car (car flist))) (cdr (car flist))
      (profile-find-function fun (cdr flist)))))

(defun profile-start-function (fun)
  "On entry, keep current time for function FUN."
  ;; assumes that profile-time contains the current time
  (let ((init-time (profile-find-function fun profile-init-list)))
    (if (null init-time) (error "Function %s missing from list" fun))
    (if (not (zerop (car init-time)));; is it a recursive call ?
	(setcar init-time (1+ (car init-time)))
      (setcar init-time 1)		; mark first entry
      (setq init-time (cdr init-time))
      (setcar init-time (car profile-time))
      (setcdr init-time (cdr profile-time)))
    ))

(defun profile-update-function (fun)
  "When the call to the function FUN is finished, add its run time."
  ;; assumes that profile-time contains the current time
  (let ((init-time (profile-find-function fun profile-init-list))
	(accum (profile-find-function fun profile-time-list))
	calls time sec usec)
    (if (or (null init-time)
	    (null accum)) (error "Function %s missing from list" fun))
    (setq calls (car accum))
    (setq time (cdr accum))
    (setcar init-time (1- (car init-time))) ; pop one level in recursion
    (if (not (zerop (car init-time))) 
	nil				; in some recursion level,
					; do not update cumulated time
      (setcar accum (1+ calls))
      (setq init-time (cdr init-time))
      (setq sec (- (car profile-time) (car init-time))
	    usec (- (cdr profile-time) (cdr init-time)))
      (setcar init-time 0)		;  reset time to check for error
      (setcdr init-time 0)		;  in case timer process dies
      (if (>= usec 0) nil
	(setq usec (+ usec profile-million))
	(setq sec (1- sec)))
      (setcar time (+ sec (car time)))
      (setcdr time (+ usec (cdr time)))
      (if (< (cdr time) profile-million) nil
	(setcar time (1+ (car time)))
	(setcdr time (- (cdr time) profile-million)))
      )))

(defun profile-convert-byte-code (function)
  (let ((defn (symbol-function function)))
    (if (byte-code-function-p defn)
	;; It is a compiled code object.

	  (fset function (cons 'lambda (cons (car contents) body)))))))

(defun profile-a-function (fun)
  "Profile the function FUN."
  (interactive "aFunction to profile: ")
  (profile-convert-byte-code fun)
  (let ((def (symbol-function fun)) (funlen (length (symbol-name fun))))
    (if (eq (car def) 'lambda) nil
      (error "To profile: %s must be a user-defined function" fun))
    (setq profile-time-list		; add a new entry
	  (cons (cons fun (cons 0 (cons 0 0))) profile-time-list))
    (setq profile-init-list		; add a new entry
	  (cons (cons fun (cons 0 (cons 0 0))) profile-init-list))
    (if (< profile-max-fun-name funlen) (setq profile-max-fun-name funlen))
    (fset fun (profile-fix-fun fun def))))

(defun profile-fix-fun (fun def)
  "Take function FUN and return it fixed for profiling.
DEF is (symbol-function FUN)."
  (if (< (length def) 3)
      def		; nothing to see
    (let ((prefix (list (car def) (car (cdr def))))
	  (suffix (cdr (cdr def))))
      ;; Skip the doc string, if there is a string
      ;; which serves only as a doc string,
      ;; and put it in PREFIX.
      (if (and (stringp (car suffix)) (cdr suffix))
	  (setq prefix (nconc prefix (list (car suffix)))
		suffix (cdr suffix)))
      ;; Check for an interactive spec.
      ;; If found, put it into PREFIX and skip it.
      (if (and (listp (car suffix)) 
	       (eq (car (car suffix)) 'interactive))
	  (setq prefix (nconc prefix (list (car suffix)))
		suffix (cdr suffix)))
      (if (equal (car suffix) '(profile-get-time))
	  def				; already profiled
	;; Prepare new function definition.
	(nconc prefix
	       (list '(profile-get-time) ; read time
		     (list 'profile-start-function 
			   (list 'quote fun))
		     (list 'setq 'profile-temp-result- 
			   (cons 'progn suffix))
		     '(profile-get-time) ; read time
		     (list 'profile-update-function 
			   (list 'quote fun))
		     'profile-temp-result-))))))

(defun profile-restore-fun (fun)
  "Restore profiled function FUN to its original state."
  (let ((def (symbol-function (car fun))) body index)
    ;; move index beyond header
    (setq index (cdr def))
    (if (stringp (car (cdr index))) (setq index (cdr index)))
    (if (and (listp (car (cdr index)))
	     (eq (car (car (cdr index))) 'interactive))
	(setq index (cdr index)))
    (setq body (car (nthcdr 3 index)))
    (if (and (listp body)		; the right element ?
	     (eq (car (cdr body)) 'profile-temp-result-))
	(setcdr index (cdr (car (cdr (cdr body))))))))

(defun profile-finish ()
  "Stop profiling functions.  Clear all the settings."
  (interactive)
  (mapcar 'profile-restore-fun profile-time-list)
  (setq profile-max-fun-name 0)
  (setq profile-time-list nil)
  (setq profile-init-list nil))

(defun profile-quit ()
  "Kill the timer process."
  (interactive)
  (process-send-string profile-timer-process "q\n"))

(provide 'profile)

;;; profile.el ends here

23512:1cd5555e67a9

;;; profile.el --- generate run time measurements of Emacs Lisp functions

;; Copyright (C) 1992, 1994, 1998 Free Software Foundation, Inc.

;; Author: Boaz Ben-Zvi <[e-mail]>
;; Created: 07 Feb 1992
;; Version: 1.0
;; Adapted-By: ESR

;;; Commentary:

;; DESCRIPTION:
;; ------------
;;   This program can be used to monitor running time performance of Emacs Lisp
;; functions.  It takes a list of functions and report the real time spent
;; inside these functions.  (Actually, for each function it reports the amount
;; of time spent while at least one instance of that function is on the call
;; stack.  So if profiled function FOO calls profiled function BAR, the time
;; spent inside BAR is credited to both functions.)

;; HOW TO USE:
;; -----------
;;   Set the variable  profile-functions-list  to the list of functions
;; (as symbols) You want to profile. Call  M-x  profile-functions to set
;; this list on and start using your program.  Note that profile-functions
;; MUST be called AFTER all the functions in profile-functions-list have
;; been loaded !!   (This call modifies the code of the profiled functions.
;; Hence if you reload these functions, you need to call  profile-functions
;; again! ).
;;   To display the results do  M-x  profile-results .  For example:
;;-------------------------------------------------------------------
;;  (setq profile-functions-list '(sokoban-set-mode-line sokoban-load-game
;;	                          sokoban-move-vertical sokoban-move))
;;  (load "sokoban")
;;  M-x profile-functions
;;     ...  I play the sokoban game ..........
;;  M-x profile-results

;;      sokoban-move                     0.539088
;;      sokoban-move-vertical            0.410130
;;      sokoban-load-game                0.453235
;;      sokoban-set-mode-line            1.949203
;;-----------------------------------------------------
;; To clear all the settings to profile use profile-finish.
;; To set one function at a time (instead of or in addition to setting the
;; above list and  M-x profile-functions) use M-x profile-a-function.

;;; Code:

;;;
;;;  User modifiable VARIABLES
;;;

(defvar profile-functions-list nil "*List of functions to profile.")
(defvar profile-buffer "*profile*"
  "Name of profile buffer.")
(defvar profile-distinct nil
  "If non-nil, each time slice gets credited to at most one function.
\(Namely, the most recent one in the call stack.)  If nil, then the
time reported for a function includes the entire time from beginning
to end, even if it called some other function that was also profiled.")

;;;
;;; V A R I A B L E S
;;;

(defvar profile-time-list nil
  "List of cumulative calls and time for each profiled function.
Each element looks like (FUN NCALLS SEC . USEC).")
(defvar profile-init-list nil
  "List of entry time for each function.
Both how many times invoked and real time of start.
Each element looks like (FUN DEPTH HISEC LOSEC USEC), where DEPTH is
the current recursion depth, and HISEC, LOSEC, and USEC represent the
starting time of the call (or of the outermost recursion).")
(defvar profile-max-fun-name 0
  "Max length of name of any function profiled.")
(defvar profile-call-stack nil
  "A list of the profiled functions currently executing.
Used only when profile-distinct is non-nil.")
(defvar profile-last-time nil
  "The start time of the current time slice.
Used only when profile-distinct is non-nil.")

(defconst profile-million 1000000)

;;;
;;; F U N C T I O N S

(defun profile-functions (&optional flist)
  "Profile all the functions listed in `profile-functions-list'.
With argument FLIST, use the list FLIST instead."
  (interactive "P")
  (mapcar 'profile-a-function (or flist profile-functions-list)))

(defun profile-print (entry)
  "Print one ENTRY (from `profile-time-list')."
  (let* ((calls (car (cdr entry)))
	 (timec (cdr (cdr entry)))
	 (avgtime (and (not (zerop calls))
		       (/ (+ (car timec)
			     (/ (cdr timec) (float profile-million)))
			  calls))))
    (insert (format (concat "%-"
			    (int-to-string profile-max-fun-name)
			    "s %7d %10d.%06d")
		    (car entry) calls (car timec) (cdr timec))
	    (if (null avgtime)
		"\n"
	      (format " %18.6f\n" avgtime)))))

(defun profile-results ()
  "Display profiling results in the buffer `*profile*'.
\(The buffer name comes from `profile-buffer'.)"
  (interactive)

  (insert "Function" (make-string (- profile-max-fun-name 6) ? ))
  (insert " Calls  Total time (sec)  Avg time per call\n")
  (insert (make-string profile-max-fun-name ?=) "  ")
  (insert "======  ================  =================\n")
  (mapcar 'profile-print profile-time-list))

(defun profile-add-time (dest now prev)
  "Add to DEST the difference between timestamps NOW and PREV.
DEST is a pair (SEC . USEC) which is modified in place.
NOW and PREV are triples as returned by `current-time'."
  (let ((sec (+ (car dest)
		(* 65536 (- (car now) (car prev)))
		(- (cadr now) (cadr prev))))
	(usec (+ (cdr dest)
		 (- (car (cddr now)) (car (cddr prev))))))
    (if (< usec 0)
	(setq sec (1- sec)
	      usec (+ usec profile-million))
      (if (>= usec profile-million)
	  (setq sec (1+ sec)
		usec (- usec profile-million))))
    (setcar dest sec)
    (setcdr dest usec)))

(defun profile-function-prolog (fun)
  "Mark the beginning of a call to function FUN."
  (if profile-distinct
      (let ((profile-time (current-time)))
	(if profile-call-stack
	    (profile-add-time (cdr (cdr (assq (car profile-call-stack)
					      profile-time-list)))
			      profile-time profile-last-time))
	(setq profile-call-stack (cons fun profile-call-stack)
	      profile-last-time profile-time))
    (let ((profile-time (current-time))
	  (init-time (cdr (assq fun profile-init-list))))
      (if (null init-time) (error "Function %s missing from list" fun))
      (if (not (zerop (car init-time)));; is it a recursive call ?
	  (setcar init-time (1+ (car init-time)))
	(setcar init-time 1)		; mark first entry
	(setcdr init-time profile-time)))))

(defun profile-function-epilog (fun)
  "Mark the end of a call to function FUN."
  (if profile-distinct
      (let ((profile-time (current-time))
	    (accum (cdr (assq fun profile-time-list))))
	(setcar accum (1+ (car accum)))
	(profile-add-time (cdr accum) profile-time profile-last-time)
	(setq profile-call-stack (cdr profile-call-stack)
	      profile-last-time profile-time))
    (let ((profile-time (current-time))
	  (init-time (cdr (assq fun profile-init-list)))
	  (accum (cdr (assq fun profile-time-list))))
      (if (or (null init-time)
	      (null accum))
	  (error "Function %s missing from list" fun))
      (setcar init-time (1- (car init-time))) ; pop one level in recursion
      ;; Update only if we've finished the outermost recursive call
      (when (zerop (car init-time))
	(setcar accum (1+ (car accum)))
	(profile-add-time (cdr accum) profile-time (cdr init-time))))))

(defun profile-convert-byte-code (function)
  (let ((defn (symbol-function function)))
    (if (byte-code-function-p defn)
	;; It is a compiled code object.

	  (fset function (cons 'lambda (cons (car contents) body)))))))

(defun profile-a-function (fun)
  "Profile the function FUN."
  (interactive "aFunction to profile: ")
  (let ((def (symbol-function fun)))
    (when (eq (car-safe def) 'autoload)
      (load (car (cdr def)))
      (setq def (symbol-function fun)))
    (fetch-bytecode def))
  (profile-convert-byte-code fun)
  (let ((def (symbol-function fun)) (funlen (length (symbol-name fun))))
    (or (eq (car def) 'lambda)
	(error "To profile: %s must be a user-defined function" fun))
    (setq profile-time-list		; add a new entry
	  (cons (cons fun (cons 0 (cons 0 0))) profile-time-list))
    (setq profile-init-list		; add a new entry
	  (cons (cons fun (cons 0 nil)) profile-init-list))
    (if (< profile-max-fun-name funlen) (setq profile-max-fun-name funlen))
    (fset fun (profile-fix-fun fun def))))

(defun profile-fix-fun (fun def)
  "Take function FUN and return it fixed for profiling.
DEF is (symbol-function FUN)."
  (if (< (length def) 3)
      def		; nothing to change
    (let ((prefix (list (car def) (car (cdr def))))
	  (suffix (cdr (cdr def))))
      ;; Skip the doc string, if there is a string
      ;; which serves only as a doc string,
      ;; and put it in PREFIX.
      (if (and (stringp (car suffix)) (cdr suffix))
	  (setq prefix (nconc prefix (list (car suffix)))
		suffix (cdr suffix)))
      ;; Check for an interactive spec.
      ;; If found, put it into PREFIX and skip it.
      (if (and (listp (car suffix))
	       (eq (car (car suffix)) 'interactive))
	  (setq prefix (nconc prefix (list (car suffix)))
		suffix (cdr suffix)))
      (if (eq (car-safe (car suffix)) 'profile-function-prolog)
	  def				; already profiled
	;; Prepare new function definition.
	;; If you change this structure, also change profile-restore-fun.
	(nconc prefix
	       (list (list 'profile-function-prolog
			   (list 'quote fun))
		     (list 'unwind-protect
			   (cons 'progn suffix)
			   (list 'profile-function-epilog
				 (list 'quote fun)))))))))

(defun profile-restore-fun (fun)
  "Restore profiled function FUN to its original state."
  (let ((def (symbol-function fun)) body index)
    ;; move index beyond header
    (setq index (cdr-safe def))
    (if (stringp (car (cdr index)))
	(setq index (cdr index)))
    (if (eq (car-safe (car (cdr index))) 'interactive)
	(setq index (cdr index)))
    (if (eq (car-safe (car (cdr index))) 'profile-function-prolog)
	(setcdr index (cdr (car (cdr (car (cdr (cdr index))))))))))

(defun profile-finish ()
  "Stop profiling functions.  Clear all the settings."
  (interactive)
  (while profile-time-list
    (profile-restore-fun (car (car profile-time-list)))
    (setq profile-time-list (cdr profile-time-list)))
  (setq profile-max-fun-name 0)
  (setq profile-init-list nil))

(provide 'profile)

;;; profile.el ends here