mirror of
https://git.savannah.gnu.org/git/emacs.git
synced 2024-11-24 07:20:37 +00:00
37ae4d5c39
current buffer is writable. (profile-print, profile-results): Changed to display number of calls and average time per call. (profile-update-function): Update the number of calls. (profile-a-function): Init the number of calls.
316 lines
12 KiB
EmacsLisp
316 lines
12 KiB
EmacsLisp
;;; profile.el --- generate run time measurements of Emacs Lisp functions
|
|
|
|
;; Copyright (C) 1992, 1994 Free Software Foundation, Inc.
|
|
|
|
;; Author: Boaz Ben-Zvi <boaz@lcs.mit.edu>
|
|
;; Created: 07 Feb 1992
|
|
;; Version: 1.0
|
|
;; Adapted-By: ESR
|
|
;; Keywords: 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, Inc., 59 Temple Place - Suite 330,
|
|
;; Boston, MA 02111-1307, USA.
|
|
|
|
;;; 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
|
|
;;
|
|
;; Function Time (Seconds.Useconds)
|
|
;; ======== =======================
|
|
;; 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-timer-program
|
|
(concat exec-directory "profile")
|
|
"*Name of the profile timer program.")
|
|
|
|
;;;
|
|
;;; 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. \n\
|
|
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.")
|
|
(defvar profile-buffer "*profile*" "Name of profile buffer.")
|
|
|
|
;;;
|
|
;;; F U N C T I O N S
|
|
;;;
|
|
|
|
(defun profile-functions (&optional flist)
|
|
"Profile all the functions listed in `profile-functions-list'.\n\
|
|
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)
|
|
(switch-to-buffer profile-buffer)
|
|
(erase-buffer)
|
|
(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)))
|
|
))
|
|
|
|
(defconst profile-million 1000000)
|
|
|
|
(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.
|
|
(let* ((contents (append defn nil))
|
|
(body
|
|
(list (list 'byte-code (nth 1 contents)
|
|
(nth 2 contents) (nth 3 contents)))))
|
|
(if (nthcdr 5 contents)
|
|
(setq body (cons (list 'interactive (nth 5 contents)) body)))
|
|
(if (nth 4 contents)
|
|
;; Use `documentation' here, to get the actual string,
|
|
;; in case the compiled function has a reference
|
|
;; to the .elc file.
|
|
(setq body (cons (documentation function) body)))
|
|
(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.\n\
|
|
DEF is (symbol-function FUN)."
|
|
(let (prefix first second third (count 2) inter suffix)
|
|
(if (< (length def) 3) nil ; nothing to see
|
|
(setq first (car def) second (car (cdr def))
|
|
third (car (nthcdr 2 def)))
|
|
(setq prefix (list first second))
|
|
(if (and (stringp third) (< (length def) 3)) nil ; nothing to see
|
|
(if (not (stringp third)) (setq inter third)
|
|
(setq count 3 ; suffix to start after doc string
|
|
prefix (nconc prefix (list third))
|
|
inter (car (nthcdr 3 def))) ; fourth sexp
|
|
)
|
|
(if (not (and (listp inter)
|
|
(eq (car inter) 'interactive))) nil
|
|
(setq prefix (nconc prefix (list inter)))
|
|
(setq count (1+ count))) ; skip this sexp for suffix
|
|
(setq suffix (nthcdr count def))
|
|
(if (equal (car suffix) '(profile-get-time)) nil;; already set
|
|
;; prepare new function
|
|
(nconc prefix
|
|
(list '(profile-get-time)) ; read time
|
|
(list (list 'profile-start-function
|
|
(list 'quote fun)))
|
|
(list (list 'setq 'profile-temp-result-
|
|
(nconc (list 'progn) suffix)))
|
|
(list '(profile-get-time)) ; read time
|
|
(list (list 'profile-update-function
|
|
(list 'quote fun)))
|
|
(list '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"))
|
|
|
|
;;; profile.el ends here
|