1;;; elp.el --- Emacs Lisp Profiler -*- lexical-binding: t -*- 2 3;; Copyright (C) 1994-2021 Free Software Foundation, Inc. 4 5;; Author: Barry A. Warsaw 6;; Maintainer: emacs-devel@gnu.org 7;; Created: 26-Feb-1994 8;; Keywords: debugging lisp tools 9 10;; This file is part of GNU Emacs. 11 12;; GNU Emacs is free software: you can redistribute it and/or modify 13;; it under the terms of the GNU General Public License as published by 14;; the Free Software Foundation, either version 3 of the License, or 15;; (at your option) any later version. 16 17;; GNU Emacs is distributed in the hope that it will be useful, 18;; but WITHOUT ANY WARRANTY; without even the implied warranty of 19;; MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 20;; GNU General Public License for more details. 21 22;; You should have received a copy of the GNU General Public License 23;; along with GNU Emacs. If not, see <https://www.gnu.org/licenses/>. 24 25;;; Commentary: 26;; 27;; If you want to profile a bunch of functions, set elp-function-list 28;; to the list of symbols, then do a M-x elp-instrument-list. This 29;; hacks those functions so that profiling information is recorded 30;; whenever they are called. To print out the current results, use 31;; M-x elp-results. If you want output to go to standard-output 32;; instead of a separate buffer, set `elp-use-standard-output' to 33;; non-nil. With `elp-reset-after-results' set to non-nil, profiling 34;; information will be reset whenever the results are displayed. You 35;; can also reset all profiling info at any time with M-x 36;; elp-reset-all. 37;; 38;; You can also instrument all functions in a package, provided that 39;; the package follows the GNU coding standard of a common textual 40;; prefix. Use M-x elp-instrument-package for this. 41;; 42;; If you want to sort the results, set `elp-sort-by-function' to some 43;; predicate function. The three most obvious choices are predefined: 44;; `elp-sort-by-call-count', `elp-sort-by-average-time', and 45;; `elp-sort-by-total-time'. Also, you can prune from the output, all 46;; functions that have been called fewer than a given number of times 47;; by setting `elp-report-limit'. 48;; 49;; Elp can instrument byte-compiled functions just as easily as 50;; interpreted functions, but it cannot instrument macros. However, 51;; when you redefine a function (e.g. with eval-defun), you'll need to 52;; re-instrument it with M-x elp-instrument-function. This will also 53;; reset profiling information for that function. Elp can handle 54;; interactive functions (i.e. commands), but of course any time spent 55;; idling for user prompts will show up in the timing results. 56;; 57;; You can also designate a `master' function. Profiling times will 58;; be gathered for instrumented functions only during execution of 59;; this master function. Thus, if you have some defuns like: 60;; 61;; (defun foo () (do-something-time-intensive)) 62;; (defun bar () (foo)) 63;; (defun baz () (bar) (foo)) 64;; 65;; and you want to find out the amount of time spent in bar and foo, 66;; but only during execution of bar, make bar the master. The call of 67;; foo from baz will not add to foo's total timing sums. Use M-x 68;; elp-set-master and M-x elp-unset-master to utilize this feature. 69;; Only one master function can be set at a time. 70 71;; You can restore any function's original function definition with 72;; elp-restore-function. The other instrument, restore, and reset 73;; functions are provided for symmetry. 74 75;; Here is a list of variable you can use to customize elp: 76;; elp-function-list 77;; elp-reset-after-results 78;; elp-sort-by-function 79;; elp-report-limit 80;; 81;; Here is a list of the interactive commands you can use: 82;; elp-instrument-function 83;; elp-restore-function 84;; elp-instrument-list 85;; elp-restore-list 86;; elp-instrument-package 87;; elp-restore-all 88;; elp-reset-function 89;; elp-reset-list 90;; elp-reset-all 91;; elp-set-master 92;; elp-unset-master 93;; elp-results 94 95;; Note that there are plenty of factors that could make the times 96;; reported unreliable, including the accuracy and granularity of your 97;; system clock, and the overhead spent in Lisp calculating and 98;; recording the intervals. I figure the latter is pretty constant, 99;; so while the times may not be entirely accurate, I think they'll 100;; give you a good feel for the relative amount of work spent in the 101;; various Lisp routines you are profiling. Note further that times 102;; are calculated using wall-clock time, so other system load will 103;; affect accuracy too. 104 105;;; Background: 106 107;; This program was inspired by the only two existing Emacs Lisp 108;; profilers that I'm aware of, Boaz Ben-Zvi's profile.el, and Root 109;; Boy Jim's profiler.el. Both were written for Emacs 18 and both were 110;; pretty good first shots at profiling, but I found that they didn't 111;; provide the functionality or interface that I wanted, so I wrote 112;; this. 113 114;; Unlike previous profilers, elp uses Emacs 19's built-in function 115;; current-time to return interval times. This obviates the need for 116;; both an external C program and Emacs processes to communicate with 117;; such a program, and thus simplifies the package as a whole. 118 119;; TBD: 120;; Make this act like a real profiler, so that it records time spent 121;; in all branches of execution. 122 123;;; Code: 124 125(eval-when-compile (require 'cl-lib)) 126 127;; start of user configuration variables 128;; vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv 129 130(defgroup elp nil 131 "Emacs Lisp Profiler." 132 :group 'lisp) 133 134(defcustom elp-function-list nil 135 "List of functions to profile. 136Used by the command `elp-instrument-list'." 137 :type '(repeat function) 138 :group 'elp) 139 140(defcustom elp-reset-after-results t 141 "Non-nil means reset all profiling info after results are displayed. 142Results are displayed with the `elp-results' command." 143 :type 'boolean 144 :group 'elp) 145 146(defcustom elp-sort-by-function 'elp-sort-by-total-time 147 "Non-nil specifies ELP results sorting function. 148These functions are currently available: 149 150 `elp-sort-by-call-count' -- sort by the highest call count 151 `elp-sort-by-total-time' -- sort by the highest total time 152 `elp-sort-by-average-time' -- sort by the highest average times 153 154You can write your own sort function. It should adhere to the 155interface specified by the PREDICATE argument for `sort'. 156Each \"element of LIST\" is really a 4 element vector where element 0 is 157the call count, element 1 is the total time spent in the function, 158element 2 is the average time spent in the function, and element 3 is 159the symbol's name string." 160 :type 'function 161 :group 'elp) 162 163(defcustom elp-report-limit 1 164 "Prevent some functions from being displayed in the results buffer. 165If a number, no function that has been called fewer than that number 166of times will be displayed in the output buffer. If nil, all 167functions will be displayed." 168 :type '(choice integer 169 (const :tag "Show All" nil)) 170 :group 'elp) 171 172(defcustom elp-use-standard-output nil 173 "If non-nil, output to `standard-output' instead of a buffer." 174 :type 'boolean 175 :group 'elp) 176 177(defcustom elp-recycle-buffers-p t 178 "If nil, don't recycle the `elp-results-buffer'. 179In other words, a new unique buffer is create every time you run 180\\[elp-results]." 181 :type 'boolean 182 :group 'elp) 183 184 185;; ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 186;; end of user configuration variables 187 188 189(defvar elp-results-buffer "*ELP Profiling Results*" 190 "Buffer name for outputting profiling results.") 191 192(defconst elp-timer-info-property 'elp-info 193 "ELP information property name.") 194 195(defvar elp-record-p t 196 "Controls whether functions should record times or not. 197This variable is set by the master function.") 198 199(defvar elp-master nil 200 "Master function symbol.") 201 202(defvar elp-not-profilable 203 ;; First, the functions used inside each instrumented function: 204 '(called-interactively-p 205 ;; (delq 206 ;; nil (mapcar 207 ;; (lambda (x) (and (symbolp x) (fboundp x) x)) 208 ;; (aref (aref (aref (symbol-function 'elp--make-wrapper) 2) 1) 2))) 209 error apply current-time float-time time-subtract 210 ;; Andreas Politz reports problems profiling these (Bug#4233): 211 + byte-code-function-p functionp byte-code subrp fboundp) 212 "List of functions that cannot be profiled. 213Those functions are used internally by the profiling code and profiling 214them would thus lead to infinite recursion.") 215 216(defun elp-profilable-p (fun) 217 (and (symbolp fun) 218 (fboundp fun) 219 (not (or (memq fun elp-not-profilable) 220 (keymapp fun) 221 (autoloadp (symbol-function fun)) ;FIXME: Why not just load it? 222 (special-form-p fun))))) 223 224(defconst elp--advice-name 'ELP-instrumentation\ ) 225 226;;;###autoload 227(defun elp-instrument-function (funsym) 228 "Instrument FUNSYM for profiling. 229FUNSYM must be a symbol of a defined function." 230 (interactive "aFunction to instrument: ") 231 (let* ((infovec (vector 0 0))) 232 ;; We cannot profile functions used internally during profiling. 233 (unless (elp-profilable-p funsym) 234 (error "ELP cannot profile the function: %s" funsym)) 235 ;; The info vector data structure is a 2 element vector. The 0th 236 ;; element is the call-count, i.e. the total number of times this 237 ;; function has been entered. This value is bumped up on entry to 238 ;; the function so that non-local exits are still recorded. TBD: 239 ;; I haven't tested non-local exits at all, so no guarantees. 240 ;; 241 ;; The 1st element is the total amount of time in seconds that has 242 ;; been spent inside this function. This number is added to on 243 ;; function exit. 244 245 ;; Put the info vector on the property list. 246 (put funsym elp-timer-info-property infovec) 247 248 ;; Set the symbol's new profiling function definition to run 249 ;; ELP wrapper. 250 (advice-add funsym :around (elp--make-wrapper funsym) 251 `((name . ,elp--advice-name) (depth . -99))))) 252 253(defun elp--instrumented-p (sym) 254 (advice-member-p elp--advice-name sym)) 255 256(defun elp-restore-function (funsym) 257 "Restore an instrumented function to its original definition. 258Argument FUNSYM is the symbol of a defined function." 259 (interactive 260 (list 261 (intern 262 (completing-read "Function to restore: " obarray 263 #'elp--instrumented-p t)))) 264 ;; If the function was the master, reset the master. 265 (if (eq funsym elp-master) 266 (setq elp-master nil 267 elp-record-p t)) 268 269 ;; Zap the properties. 270 (put funsym elp-timer-info-property nil) 271 272 (advice-remove funsym elp--advice-name)) 273 274;;;###autoload 275(defun elp-instrument-list (&optional list) 276 "Instrument, for profiling, all functions in `elp-function-list'. 277Use optional LIST if provided instead. 278If called interactively, prompt for LIST in the minibuffer; 279type \"nil\" to use `elp-function-list'." 280 (interactive "xList of functions to instrument: ") 281 (unless (listp list) 282 (signal 'wrong-type-argument (list 'listp list))) 283 (mapcar #'elp-instrument-function (or list elp-function-list))) 284 285;;;###autoload 286(defun elp-instrument-package (prefix) 287 "Instrument for profiling, all functions which start with PREFIX. 288For example, to instrument all ELP functions, do the following: 289 290 \\[elp-instrument-package] RET elp- RET" 291 (interactive 292 (list (completing-read "Prefix of package to instrument: " 293 obarray 'elp-profilable-p))) 294 (if (zerop (length prefix)) 295 (error "Instrumenting all Emacs functions would render Emacs unusable")) 296 (elp-instrument-list 297 (mapcar 298 'intern 299 (all-completions prefix obarray 'elp-profilable-p)))) 300 301(defun elp-restore-package (prefix) 302 "Remove instrumentation from functions with names starting with PREFIX." 303 (interactive "SPrefix: ") 304 (elp-restore-list 305 (mapcar #'intern 306 (all-completions (symbol-name prefix) 307 obarray 'elp-profilable-p)))) 308 309(defun elp-restore-list (&optional list) 310 "Restore the original definitions for all functions in `elp-function-list'. 311Use optional LIST if provided instead." 312 (interactive) 313 (mapcar #'elp-restore-function (or list elp-function-list))) 314 315(defun elp-restore-all () 316 "Restore the original definitions of all functions being profiled." 317 (interactive) 318 (mapatoms #'elp-restore-function)) 319 320(defun elp-reset-function (funsym) 321 "Reset the profiling information for FUNSYM." 322 (interactive "aFunction to reset: ") 323 (let ((info (get funsym elp-timer-info-property))) 324 (or info 325 (error "%s is not instrumented for profiling" funsym)) 326 (aset info 0 0) ;reset call counter 327 (aset info 1 0.0) ;reset total time 328 ;; don't muck with aref 2 as that is the old symbol definition 329 )) 330 331(defun elp-reset-list (&optional list) 332 "Reset the profiling information for all functions in `elp-function-list'. 333Use optional LIST if provided instead." 334 (interactive) 335 (let ((list (or list elp-function-list))) 336 (mapcar 'elp-reset-function list))) 337 338(defun elp-reset-all () 339 "Reset the profiling information for all functions being profiled." 340 (interactive) 341 (mapatoms (lambda (sym) 342 (if (get sym elp-timer-info-property) 343 (elp-reset-function sym))))) 344 345(defun elp-set-master (funsym) 346 "Set the master function for profiling." 347 (interactive 348 (list 349 (intern 350 (let ((default (if elp-master (symbol-name elp-master)))) 351 (completing-read (format-prompt "Master function" default) 352 obarray #'elp--instrumented-p t nil nil default))))) 353 ;; When there's a master function, recording is turned off by default. 354 (setq elp-master funsym 355 elp-record-p nil) 356 ;; Make sure master function is instrumented. 357 (or (elp--instrumented-p funsym) 358 (elp-instrument-function funsym))) 359 360(defun elp-unset-master () 361 "Unset the master function." 362 (interactive) 363 ;; When there's no master function, recording is turned on by default. 364 (setq elp-master nil 365 elp-record-p t)) 366 367 368(defsubst elp-elapsed-time (start end) 369 (float-time (time-subtract end start))) 370 371(defun elp--make-wrapper (funsym) 372 "Make the piece of advice that instruments FUNSYM." 373 (lambda (func &rest args) 374 "This function has been instrumented for profiling by the ELP. 375ELP is the Emacs Lisp Profiler. To restore the function to its 376original definition, use \\[elp-restore-function] or \\[elp-restore-all]." 377 ;; turn on recording if this is the master function 378 (if (and elp-master 379 (eq funsym elp-master)) 380 (setq elp-record-p t)) 381 ;; get info vector and original function symbol 382 (let* ((info (get funsym elp-timer-info-property)) 383 result) 384 (or func 385 (error "%s is not instrumented for profiling" funsym)) 386 (if (not elp-record-p) 387 ;; when not recording, just call the original function symbol 388 ;; and return the results. 389 (setq result (apply func args)) 390 ;; we are recording times 391 (let (enter-time) 392 ;; increment the call-counter 393 (cl-incf (aref info 0)) 394 (setq enter-time (current-time) 395 result (apply func args)) 396 ;; calculate total time in function 397 (cl-incf (aref info 1) (elp-elapsed-time enter-time nil)) 398 )) 399 ;; turn off recording if this is the master function 400 (if (and elp-master 401 (eq funsym elp-master)) 402 (setq elp-record-p nil)) 403 result))) 404 405 406;; shut the byte-compiler up 407(defvar elp-field-len nil) 408(defvar elp-cc-len nil) 409(defvar elp-at-len nil) 410(defvar elp-et-len nil) 411 412(defun elp-sort-by-call-count (vec1 vec2) 413 "Predicate to sort by highest call count. See `sort'." 414 (>= (aref vec1 0) (aref vec2 0))) 415 416(defun elp-sort-by-total-time (vec1 vec2) 417 "Predicate to sort by highest total time spent in function. See `sort'." 418 (>= (aref vec1 1) (aref vec2 1))) 419 420(defun elp-sort-by-average-time (vec1 vec2) 421 "Predicate to sort by highest average time spent in function. See `sort'." 422 (>= (aref vec1 2) (aref vec2 2))) 423 424(defsubst elp-pack-number (number width) 425 ;; pack the NUMBER string into WIDTH characters, watching out for 426 ;; very small or large numbers 427 (if (<= (length number) width) 428 number 429 ;; check for very large or small numbers 430 (if (string-match "^\\(.*\\)\\(e[+-].*\\)$" number) 431 (concat (substring 432 (match-string 1 number) 433 0 434 (- width (match-end 2) (- (match-beginning 2)) 3)) 435 "..." 436 (match-string 2 number)) 437 (substring number 0 width)))) 438 439(defun elp-output-result (resultvec) 440 ;; output the RESULTVEC into the results buffer. RESULTVEC is a 4 or 441 ;; more element vector where aref 0 is the call count, aref 1 is the 442 ;; total time spent in the function, aref 2 is the average time 443 ;; spent in the function, and aref 3 is the symbol's string 444 ;; name. All other elements in the vector are ignored. 445 (let* ((cc (aref resultvec 0)) 446 (tt (aref resultvec 1)) 447 (at (aref resultvec 2)) 448 (symname (aref resultvec 3)) 449 callcnt totaltime avetime) 450 (setq callcnt (number-to-string cc) 451 totaltime (number-to-string tt) 452 avetime (number-to-string at)) 453 ;; possibly prune the results 454 (if (and elp-report-limit 455 (numberp elp-report-limit) 456 (< cc elp-report-limit)) 457 nil 458 (elp-output-insert-symname symname) 459 (insert-char 32 (+ elp-field-len (- (length symname)) 2)) 460 ;; print stuff out, formatting it nicely 461 (insert callcnt) 462 (insert-char 32 (+ elp-cc-len (- (length callcnt)) 2)) 463 (let ((ttstr (elp-pack-number totaltime elp-et-len)) 464 (atstr (elp-pack-number avetime elp-at-len))) 465 (insert ttstr) 466 (insert-char 32 (+ elp-et-len (- (length ttstr)) 2)) 467 (insert atstr)) 468 (insert "\n")))) 469 470(defvar elp-results-symname-map 471 (let ((map (make-sparse-keymap))) 472 (define-key map [mouse-2] 'elp-results-jump-to-definition) 473 (define-key map [follow-link] 'mouse-face) 474 (define-key map "\C-m" 'elp-results-jump-to-definition) 475 map) 476 "Keymap used on the function name column." ) 477 478(defun elp-results-jump-to-definition (&optional event) 479 "Jump to the definition of the function at point." 480 (interactive (list last-nonmenu-event)) 481 (if event (posn-set-point (event-end event))) 482 (find-function (get-text-property (point) 'elp-symname))) 483 484(defun elp-output-insert-symname (symname) 485 "Insert SYMNAME with text properties." 486 (insert (propertize symname 487 'elp-symname (intern symname) 488 'keymap elp-results-symname-map 489 'mouse-face 'highlight 490 'face 'link 491 'help-echo "mouse-2 or RET jumps to definition"))) 492 493(define-derived-mode elp-results-mode special-mode "ELP" 494 "Mode for ELP results." 495 :interactive nil) 496 497;;;###autoload 498(defun elp-results () 499 "Display current profiling results. 500If `elp-reset-after-results' is non-nil, then current profiling 501information for all instrumented functions is reset after results are 502displayed." 503 (interactive) 504 (pop-to-buffer 505 (if elp-recycle-buffers-p 506 (get-buffer-create elp-results-buffer) 507 (generate-new-buffer elp-results-buffer))) 508 (elp-results-mode) 509 (let ((inhibit-read-only t)) 510 (erase-buffer) 511 ;; get the length of the longest function name being profiled 512 (let* ((longest 0) 513 (title "Function Name") 514 (titlelen (length title)) 515 (elp-field-len titlelen) 516 (cc-header "Call Count") 517 (elp-cc-len (length cc-header)) 518 (et-header "Elapsed Time") 519 (elp-et-len (length et-header)) 520 (at-header "Average Time") 521 (elp-at-len (length at-header)) 522 (resvec '()) 523 ) ; end let* 524 (mapatoms 525 (lambda (funsym) 526 (when (elp--instrumented-p funsym) 527 (let* ((info (get funsym elp-timer-info-property)) 528 (symname (format "%s" funsym)) 529 (cc (aref info 0)) 530 (tt (aref info 1))) 531 (if (not info) 532 (insert "No profiling information found for: " 533 symname) 534 (setq longest (max longest (length symname))) 535 (push 536 (vector cc tt (if (zerop cc) 537 0.0 ;avoid arithmetic div-by-zero errors 538 (/ (float tt) (float cc))) 539 symname) 540 resvec)))))) 541 ;; If printing to stdout, insert the header so it will print. 542 ;; Otherwise use header-line-format. 543 (setq elp-field-len (max titlelen longest)) 544 (if (or elp-use-standard-output noninteractive) 545 (progn 546 (insert title) 547 (if (> longest titlelen) 548 (progn 549 (insert-char 32 (- longest titlelen)))) 550 (insert " " cc-header " " et-header " " at-header "\n") 551 (insert-char ?= elp-field-len) 552 (insert " ") 553 (insert-char ?= elp-cc-len) 554 (insert " ") 555 (insert-char ?= elp-et-len) 556 (insert " ") 557 (insert-char ?= elp-at-len) 558 (insert "\n")) 559 (let ((column 0)) 560 (setq header-line-format 561 (mapconcat 562 (lambda (title) 563 (prog1 564 (concat 565 (propertize " " 566 'display (list 'space :align-to column) 567 'face 'fixed-pitch) 568 title) 569 (setq column (+ column 2 570 (if (= column 0) 571 elp-field-len 572 (length title)))))) 573 (list title cc-header et-header at-header) "")))) 574 ;; if sorting is enabled, then sort the results list. in either 575 ;; case, call elp-output-result to output the result in the 576 ;; buffer 577 (if elp-sort-by-function 578 (setq resvec (sort resvec elp-sort-by-function))) 579 (mapc 'elp-output-result resvec)) 580 ;; copy results to standard-output? 581 (if (or elp-use-standard-output noninteractive) 582 (princ (buffer-substring (point-min) (point-max))) 583 (goto-char (point-min))) 584 ;; reset profiling info if desired 585 (and elp-reset-after-results 586 (elp-reset-all)))) 587 588(defun elp-unload-function () 589 "Unload the Emacs Lisp Profiler." 590 (elp-restore-all) 591 ;; continue standard unloading 592 nil) 593 594(cl-defmethod loadhist-unload-element :extra "elp" :before ((x (head defun))) 595 "Un-instrument before unloading a function." 596 (elp-restore-function (cdr x))) 597 598(provide 'elp) 599 600;;; elp.el ends here 601