diff --git a/lisp/emacs-lisp/elp.el b/lisp/emacs-lisp/elp.el index 385ddb3f41..67c80c0bbb 100644 --- a/lisp/emacs-lisp/elp.el +++ b/lisp/emacs-lisp/elp.el @@ -221,34 +221,49 @@ them would thus lead to infinite recursion.") (autoloadp (symbol-function fun)) ;FIXME: Why not just load it? (special-form-p fun))))) +(defvar elp--instrumented-functions nil) + (defconst elp--advice-name 'ELP-instrumentation\ ) + +(defun new-infovec () + ;; The info vector data structure is a 2 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 exits 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 seconds that has + ;; been spent inside this function. This number is added to on + ;; function exit. + (vector 0 0)) + ;;;###autoload (defun elp-instrument-function (funsym) "Instrument FUNSYM for profiling. FUNSYM must be a symbol of a defined function." (interactive "aFunction to instrument: ") - (let* ((infovec (vector 0 0))) - ;; We cannot profile functions used internally during profiling. - (unless (elp-profilable-p funsym) - (error "ELP cannot profile the function: %s" funsym)) - ;; The info vector data structure is a 2 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 exits 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 seconds that has - ;; been spent inside this function. This number is added to on - ;; function exit. - + ;; We cannot profile functions used internally during profiling. + (unless (elp-profilable-p funsym) + (error "ELP cannot profile the function: %s" funsym)) + + ;; calls from functions not instrumented + (put funsym elp-timer-info-property (list t (new-infovec))) + ;; recursive calls (with no other instrumented function in between) + (plist-put (get funsym elp-timer-info-property) funsym (new-infovec)) + (dolist (caller elp--instrumented-functions) ;; Put the info vector on the property list. - (put funsym elp-timer-info-property infovec) + (plist-put (get funsym elp-timer-info-property) caller (new-infovec)) + (plist-put (get caller elp-timer-info-property) funsym (new-infovec))) - ;; Set the symbol's new profiling function definition to run - ;; ELP wrapper. - (advice-add funsym :around (elp--make-wrapper funsym) - `((name . ,elp--advice-name) (depth . -99))))) + (unless (elp--instrumented-p funsym) + (setq elp--instrumented-functions + (cons funsym elp--instrumented-functions))) + + ;; Set the symbol's new profiling function definition to run + ;; ELP wrapper. + (advice-add funsym :around (elp--make-wrapper funsym) + `((name . ,elp--advice-name) (depth . -99)))) (defun elp--instrumented-p (sym) (advice-member-p elp--advice-name sym)) @@ -268,8 +283,13 @@ Argument FUNSYM is the symbol of a defined function." ;; Zap the properties. (put funsym elp-timer-info-property nil) + (setq elp--instrumented-functions + (delete funsym elp--instrumented-functions)) + (advice-remove funsym elp--advice-name) - (advice-remove funsym elp--advice-name)) + ;; Clean up references in other instrumented functions + (dolist (caller elp--instrumented-functions) + (plist-put funsym (get caller elp-timer-info-property) nil))) ;;;###autoload (defun elp-instrument-list (&optional list) @@ -320,16 +340,22 @@ Use optional LIST if provided instead." (defun elp-restore-all () "Restore the original definitions of all functions being profiled." (interactive) - (mapatoms #'elp-restore-function)) + (mapatoms (lambda (funsym) + (put funsym elp-timer-info-property nil) + (advice-remove funsym elp--advice-name))) + (setq elp--instrumented-functions nil)) (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 "Not implemented") + (let ((caller-plist (get funsym elp-timer-info-property))) + (or caller-plist (error "%s is not instrumented for profiling" funsym)) - (aset info 0 0) ;reset call counter - (aset info 1 0.0) ;reset total time + (dolist (caller-and-info caller-plist) + (let ((info (cadr caller-and-info))) + (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 )) @@ -343,9 +369,17 @@ Use optional LIST if provided instead." (defun elp-reset-all () "Reset the profiling information for all functions being profiled." (interactive) - (mapatoms (lambda (sym) - (if (get sym elp-timer-info-property) - (elp-reset-function sym))))) + (dolist (sym elp--instrumented-functions) + (if (get sym elp-timer-info-property) + (let ((info-plist (get sym elp-timer-info-property))) + (let ((info (plist-get info-plist t))) + (aset info 0 0) + (aset info 1 0.0)) + (dolist (caller elp--instrumented-functions) + (let ((info (plist-get info-plist caller))) + (aset info 0 0) ; reset call counter + (aset info 1 0.0)))) ; reset total time + ))) (defun elp-set-master (funsym) "Set the master function for profiling." @@ -373,38 +407,33 @@ Use optional LIST if provided instead." (defsubst elp-elapsed-time (start end) (float-time (time-subtract end start))) +(defvar elp--parent-funsym nil) + (defun elp--make-wrapper (funsym) "Make the piece of advice that instruments FUNSYM." (lambda (func &rest 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)) - result) - (or func + (let ((info-plist (get funsym elp-timer-info-property)) + result) + (or info-plist (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 (apply func args)) - ;; we are recording times - (let (enter-time) - ;; increment the call-counter - (cl-incf (aref info 0)) - (setq enter-time (current-time) - result (apply func args)) - ;; calculate total time in function - (cl-incf (aref info 1) (elp-elapsed-time enter-time nil)) - )) - ;; turn off recording if this is the master function - (if (and elp-master - (eq funsym elp-master)) - (setq elp-record-p nil)) + + + (let* ((old-parent (if elp--parent-funsym + elp--parent-funsym + t)) + (info (plist-get info-plist old-parent)) + (elp--parent-funsym funsym) + enter-time) + ;; increment the call-counter + (cl-incf (aref info 0)) + (setq enter-time (current-time) + result (apply func args)) + ;; calculate total time in function + (cl-incf (aref info 1) (elp-elapsed-time enter-time nil))) result))) @@ -441,7 +470,39 @@ original definition, use \\[elp-restore-function] or \\[elp-restore-all]." (match-string 2 number)) (substring number 0 width)))) -(defun elp-output-result (resultvec) +(defvar elp--indent "`-") + +(defun elp--output-function-p (resultvec &optional cc-limit) + "Whether to print the output function. + +RESULTVEC is a result vector as defined for `elp--output-result'. +CC-LIMIT is an optional lower bound for the call count in +RESULTVEC." + (let ((cc-limit (or cc-limit elp-report-limit)) + (cc (aref resultvec 0))) + (if cc-limit + (>= cc cc-limit) + t))) + +(defun elp-output-function (results-plist) + (dolist (parent-func elp--instrumented-functions) + (let* ((result-vectors (plist-get results-plist parent-func)) + (elp-field-len elp-field-len) + (parent-resultvec (car result-vectors)) + (resultvec-list (cdr result-vectors))) + (if (or (elp--output-function-p parent-resultvec) + (eval `(or ,@(map 'list #'elp--output-function-p + resultvec-list)))) + (progn + (message "%s" (aref parent-resultvec 3)) + (elp--output-result parent-resultvec t) + (dolist (child-func resultvec-list) + (when (elp--output-function-p child-func) + (elp--output-result child-func))) + (insert "\n")) + (message "~%s" (aref parent-resultvec 3)))))) + +(defun elp--output-result (resultvec &optional parentp) ;; 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 @@ -457,11 +518,17 @@ original definition, use \\[elp-restore-function] or \\[elp-restore-all]." avetime (number-to-string at)) ;; possibly prune the results (if (and elp-report-limit + (not parentp) (numberp elp-report-limit) (< cc elp-report-limit)) nil + (when (not parentp) + (insert elp--indent)) (elp-output-insert-symname symname) - (insert-char 32 (+ elp-field-len (- (length symname)) 2)) + (insert-char 32 (+ elp-field-len + (- (length symname)) + (if (not parentp) (- (length elp--indent)) 0) + 2)) ;; print stuff out, formatting it nicely (insert callcnt) (insert-char 32 (+ elp-cc-len (- (length callcnt)) 2)) @@ -478,7 +545,7 @@ original definition, use \\[elp-restore-function] or \\[elp-restore-all]." (define-key map [follow-link] 'mouse-face) (define-key map "\C-m" 'elp-results-jump-to-definition) map) - "Keymap used on the function name column." ) + "Keymap used on the function name column.") (defun elp-results-jump-to-definition (&optional event) "Jump to the definition of the function at point." @@ -524,64 +591,78 @@ displayed." (elp-et-len (length et-header)) (at-header "Average Time") (elp-at-len (length at-header)) - (resvec '()) - ) ; end let* - (mapatoms - (lambda (funsym) - (when (elp--instrumented-p 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))) - (push - (vector cc tt (if (zerop cc) - 0.0 ;avoid arithmetic div-by-zero errors - (/ (float tt) (float cc))) - symname) - resvec)))))) + (res-plist nil)) + (dolist (funsym elp--instrumented-functions) + ;;(plist-put res-plist funsym nil) + (push nil res-plist) + (push funsym res-plist)) + ;; invert the call matrix + (dolist (child-func elp--instrumented-functions) + (dolist (parent-func elp--instrumented-functions) + (let* ((info-plist (get child-func elp-timer-info-property)) + (info (plist-get info-plist parent-func)) + (symname (format "%s" child-func)) + (cc (aref info 0)) + (tt (aref info 1))) + (when info + (setq longest (max longest (length symname))) + (plist-put res-plist parent-func + (cons (vector cc tt (if (zerop cc) + 0.0 ;avoid arithmetic div-by-zero errors + (/ (float tt) (float cc))) + symname) + (plist-get res-plist parent-func))))))) + ;; parent == `t' signals parent function is not profiled + (dolist (funsym elp--instrumented-functions) + (let* ((info-plist (get funsym elp-timer-info-property)) + (info (plist-get info-plist t)) + (symname (format "%s" funsym)) + (cc (aref info 0)) + (tt (aref info 1))) + (plist-put res-plist funsym + (cons (vector cc tt (if (zerop cc) + 0.0 + (/ (float tt) (float cc))) + symname) + (plist-get res-plist funsym))))) ;; If printing to stdout, insert the header so it will print. ;; Otherwise use header-line-format. - (setq elp-field-len (max titlelen longest)) - (if (or elp-use-standard-output noninteractive) - (progn - (insert title) - (if (> longest titlelen) - (progn - (insert-char 32 (- longest titlelen)))) - (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")) - (let ((column 0)) - (setq header-line-format - (mapconcat - (lambda (title) - (prog1 - (concat - (propertize " " - 'display (list 'space :align-to column) - 'face 'fixed-pitch) - title) - (setq column (+ column 2 - (if (= column 0) - elp-field-len - (length title)))))) - (list title cc-header et-header at-header) "")))) - ;; 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))) - (mapc 'elp-output-result resvec)) + (let ((elp-field-len (max titlelen longest))) + (if (or elp-use-standard-output noninteractive) + (progn + (insert title) + (if (> longest titlelen) + (insert-char 32 (- longest titlelen))) + (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")) + (let ((column 0)) + (setq header-line-format + (mapconcat + (lambda (title) + (prog1 + (concat + (propertize " " + 'display (list 'space :align-to column) + 'face 'fixed-pitch) + title) + (setq column (+ column 2 + (if (= column 0) + elp-field-len + (length title)))))) + (list title cc-header et-header at-header) "")))) + ;; 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))) + (elp-output-function res-plist))) ;; copy results to standard-output? (if (or elp-use-standard-output noninteractive) (princ (buffer-substring (point-min) (point-max))) diff --git a/test/lisp/emacs-lisp/elp-tests.el b/test/lisp/emacs-lisp/elp-tests.el new file mode 100644 index 0000000000..c838c72780 --- /dev/null +++ b/test/lisp/emacs-lisp/elp-tests.el @@ -0,0 +1,64 @@ +(require 'elp) + +(defun g (n) + (f (abs n))) + +(defun f (n) + (when (not (= n 0)) + (f (1- n)))) + +(defun get-timer-info (funsym caller) + (let ((info-plist (get funsym elp-timer-info-property))) + (or info-plist (error "%s is not instrumented for profiling" funsym)) + (plist-get info-plist caller))) + +(defun call-count (funsym caller) + (let ((info (get-timer-info funsym caller))) + (or info + (error "%s is not instrumented for profiling" caller)) + (aref info 0))) + +(ert-deftest root-function-is-profiled () + (elp-instrument-function 'g) + (g 3) + ;; f(3) -> f(2) -> f(1) -> f(0) + (should (= (call-count #'g t) 1)) + (should (= (call-count #'g #'g) 0)) + (elp-restore-all)) + +(ert-deftest recursive-calls-not-profiled () + (elp-instrument-function 'f) + (elp-instrument-function 'g) + (g 3) + ;; f(3) -> f(2) -> f(1) -> f(0) + (should (= (call-count #'f #'g) 1)) + (should (= (call-count #'f #'f) 3)) + (should (= (call-count #'f t) 0)) + (elp-restore-all)) + +(ert-deftest print-elp-result () + (setq elp--instrumented-functions `(g f)) + (let ((res-plist + `(g (,(vector 1 2 3 "g") + ,(vector 4 5 6 "f") + ,(vector 0 0 0 "g")) + f (,(vector 3 2 1 "f") + ,(vector 9 9 9 "f")) + )) + (elp-field-len 2) + (elp-cc-len 2) + (elp-et-len 2) + (elp-at-len 2)) + (with-temp-buffer + (message (format "elp-field-len: %s" elp-field-len)) + (elp-output-function res-plist) + (let ((first-line (buffer-substring-no-properties + (point-min) (point)))) + (should (equal first-line + ""))))) + (elp-restore-all)) + +(ert-deftest elp-reset-test () + (elp-instrument-list `(g f)) + (g 3) + (elp-reset-function 'g))