* src/profiler.c: Rename sample_profiler_* to profiler_cpu_* and
[emacs.git] / lisp / profiler.el
blobfb38b00c2d8ff11f6243a34bedb564a9e3455e7d
1 ;;; profiler.el --- UI and helper functions for Emacs's native profiler -*- lexical-binding: t -*-
3 ;; Copyright (C) 2012 Free Software Foundation, Inc.
5 ;; Author: Tomohiro Matsuyama <tomo@cx4a.org>
6 ;; Keywords: lisp
8 ;; This program is free software; you can redistribute it and/or modify
9 ;; it under the terms of the GNU General Public License as published by
10 ;; the Free Software Foundation, either version 3 of the License, or
11 ;; (at your option) any later version.
13 ;; This program is distributed in the hope that it will be useful,
14 ;; but WITHOUT ANY WARRANTY; without even the implied warranty of
15 ;; MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
16 ;; GNU General Public License for more details.
18 ;; You should have received a copy of the GNU General Public License
19 ;; along with this program. If not, see <http://www.gnu.org/licenses/>.
21 ;;; Commentary:
25 ;;; Code:
27 (eval-when-compile
28 (require 'cl-lib))
30 (defgroup profiler nil
31 "Emacs profiler."
32 :group 'lisp
33 :prefix "profiler-")
35 (defcustom profiler-sample-interval 1
36 "Default sample interval in millisecond."
37 :type 'integer
38 :group 'profiler)
40 ;;; Utilities
42 (defun profiler-ensure-string (object)
43 (cond ((stringp object)
44 object)
45 ((symbolp object)
46 (symbol-name object))
47 ((numberp object)
48 (number-to-string object))
50 (format "%s" object))))
52 (defun profiler-format (fmt &rest args)
53 (cl-loop for (width align subfmt) in fmt
54 for arg in args
55 for str = (cond
56 ((consp subfmt)
57 (apply 'profiler-format subfmt arg))
58 ((stringp subfmt)
59 (format subfmt arg))
60 ((and (symbolp subfmt)
61 (fboundp subfmt))
62 (funcall subfmt arg))
64 (profiler-ensure-string arg)))
65 for len = (length str)
66 if (< width len)
67 collect (substring str 0 width) into frags
68 else
69 collect
70 (let ((padding (make-string (- width len) ?\s)))
71 (cl-ecase align
72 (left (concat str padding))
73 (right (concat padding str))))
74 into frags
75 finally return (apply #'concat frags)))
77 (defun profiler-format-percent (number divisor)
78 (concat (number-to-string (/ (* number 100) divisor)) "%"))
80 (defun profiler-format-nbytes (nbytes)
81 "Format NBYTES in humarn readable string."
82 (if (and (integerp nbytes) (> nbytes 0))
83 (cl-loop with i = (% (1+ (floor (log10 nbytes))) 3)
84 for c in (append (number-to-string nbytes) nil)
85 if (= i 0)
86 collect ?, into s
87 and do (setq i 3)
88 collect c into s
89 do (cl-decf i)
90 finally return
91 (apply 'string (if (eq (car s) ?,) (cdr s) s)))
92 (profiler-ensure-string nbytes)))
95 ;;; Entries
97 (defun profiler-entry-format (entry)
98 "Format ENTRY in human readable string. ENTRY would be a
99 function name of a function itself."
100 (cond ((memq (car-safe entry) '(closure lambda))
101 (format "#<lambda 0x%x>" (sxhash entry)))
102 ((byte-code-function-p entry)
103 (format "#<compiled 0x%x>" (sxhash entry)))
104 ((or (subrp entry) (symbolp entry) (stringp entry))
105 (format "%s" entry))
107 (format "#<unknown 0x%x>" (sxhash entry)))))
109 ;;; Log data structure
111 ;; The C code returns the log in the form of a hash-table where the keys are
112 ;; vectors (of size profiler-max-stack-depth, holding truncated
113 ;; backtraces, where the first element is the top of the stack) and
114 ;; the values are integers (which count how many times this backtrace
115 ;; has been seen, multiplied by a "weight factor" which is either the
116 ;; sample-interval or the memory being allocated).
117 ;; We extend it by adding a few other entries to the hash-table, most notably:
118 ;; - Key `type' has a value indicating the kind of log (`memory' or `cpu').
119 ;; - Key `timestamp' has a value giving the time when the log was obtained.
120 ;; - Key `diff-p' indicates if this log represents a diff between two logs.
122 (defun profiler-log-timestamp (log) (gethash 'timestamp log))
123 (defun profiler-log-type (log) (gethash 'type log))
124 (defun profiler-log-diff-p (log) (gethash 'diff-p log))
126 (defun profiler-log-diff (log1 log2)
127 "Compare LOG1 with LOG2 and return a diff log. Both logs must
128 be same type."
129 (unless (eq (profiler-log-type log1)
130 (profiler-log-type log2))
131 (error "Can't compare different type of logs"))
132 (let ((newlog (make-hash-table :test 'equal)))
133 ;; Make a copy of `log1' into `newlog'.
134 (maphash (lambda (backtrace count) (puthash backtrace count newlog))
135 log1)
136 (puthash 'diff-p t newlog)
137 (maphash (lambda (backtrace count)
138 (when (vectorp backtrace)
139 (puthash backtrace (- (gethash backtrace log1 0) count)
140 newlog)))
141 log2)
142 newlog))
144 (defun profiler-log-fixup-entry (entry)
145 (if (symbolp entry)
146 entry
147 (profiler-entry-format entry)))
149 (defun profiler-log-fixup-backtrace (backtrace)
150 (mapcar 'profiler-log-fixup-entry backtrace))
152 (defun profiler-log-fixup (log)
153 "Fixup LOG so that the log could be serialized into file."
154 (let ((newlog (make-hash-table :test 'equal)))
155 (maphash (lambda (backtrace count)
156 (puthash (if (not (vectorp backtrace))
157 backtrace
158 (profiler-log-fixup-backtrace backtrace))
159 count newlog))
160 log)
161 newlog))
163 (defun profiler-log-write-file (log filename &optional confirm)
164 "Write LOG into FILENAME."
165 (with-temp-buffer
166 (let (print-level print-length)
167 (print (profiler-log-fixup log) (current-buffer)))
168 (write-file filename confirm)))
170 (defun profiler-log-read-file (filename)
171 "Read log from FILENAME."
172 (with-temp-buffer
173 (insert-file-contents filename)
174 (goto-char (point-min))
175 (read (current-buffer))))
178 ;;; Calltree data structure
180 (cl-defstruct (profiler-calltree (:constructor profiler-make-calltree))
181 entry
182 (count 0) (count-percent "")
183 parent children)
185 (defun profiler-calltree-leaf-p (tree)
186 (null (profiler-calltree-children tree)))
188 (defun profiler-calltree-count< (a b)
189 (cond ((eq (profiler-calltree-entry a) t) t)
190 ((eq (profiler-calltree-entry b) t) nil)
191 (t (< (profiler-calltree-count a)
192 (profiler-calltree-count b)))))
194 (defun profiler-calltree-count> (a b)
195 (not (profiler-calltree-count< a b)))
197 (defun profiler-calltree-depth (tree)
198 (let ((parent (profiler-calltree-parent tree)))
199 (if (null parent)
201 (1+ (profiler-calltree-depth parent)))))
203 (defun profiler-calltree-find (tree entry)
204 "Return a child tree of ENTRY under TREE."
205 ;; OPTIMIZED
206 (let (result (children (profiler-calltree-children tree)))
207 ;; FIXME: Use `assoc'.
208 (while (and children (null result))
209 (let ((child (car children)))
210 (when (equal (profiler-calltree-entry child) entry)
211 (setq result child))
212 (setq children (cdr children))))
213 result))
215 (defun profiler-calltree-walk (calltree function)
216 (funcall function calltree)
217 (dolist (child (profiler-calltree-children calltree))
218 (profiler-calltree-walk child function)))
220 (defun profiler-calltree-build-1 (tree log &optional reverse)
221 (maphash
222 (lambda (backtrace count)
223 (when (vectorp backtrace)
224 (let ((node tree)
225 (max (length backtrace)))
226 (dotimes (i max)
227 (let ((entry (aref backtrace (if reverse i (- max i 1)))))
228 (when entry
229 (let ((child (profiler-calltree-find node entry)))
230 (unless child
231 (setq child (profiler-make-calltree
232 :entry entry :parent node))
233 (push child (profiler-calltree-children node)))
234 (cl-incf (profiler-calltree-count child) count)
235 (setq node child))))))))
236 log))
238 (defun profiler-calltree-compute-percentages (tree)
239 (let ((total-count 0))
240 ;; FIXME: the memory profiler's total wraps around all too easily!
241 (dolist (child (profiler-calltree-children tree))
242 (cl-incf total-count (profiler-calltree-count child)))
243 (unless (zerop total-count)
244 (profiler-calltree-walk
245 tree (lambda (node)
246 (setf (profiler-calltree-count-percent node)
247 (profiler-format-percent (profiler-calltree-count node)
248 total-count)))))))
250 (cl-defun profiler-calltree-build (log &key reverse)
251 (let ((tree (profiler-make-calltree)))
252 (profiler-calltree-build-1 tree log reverse)
253 (profiler-calltree-compute-percentages tree)
254 tree))
256 (defun profiler-calltree-sort (tree predicate)
257 (let ((children (profiler-calltree-children tree)))
258 (setf (profiler-calltree-children tree) (sort children predicate))
259 (dolist (child (profiler-calltree-children tree))
260 (profiler-calltree-sort child predicate))))
263 ;;; Report rendering
265 (defcustom profiler-report-closed-mark "+"
266 "An indicator of closed calltrees."
267 :type 'string
268 :group 'profiler)
270 (defcustom profiler-report-open-mark "-"
271 "An indicator of open calltrees."
272 :type 'string
273 :group 'profiler)
275 (defcustom profiler-report-leaf-mark " "
276 "An indicator of calltree leaves."
277 :type 'string
278 :group 'profiler)
280 (defvar profiler-report-sample-line-format
281 '((60 left)
282 (14 right ((9 right)
283 (5 right)))))
285 (defvar profiler-report-memory-line-format
286 '((55 left)
287 (19 right ((14 right profiler-format-nbytes)
288 (5 right)))))
290 (defvar-local profiler-report-log nil
291 "The current profiler log.")
293 (defvar-local profiler-report-reversed nil
294 "True if calltree is rendered in bottom-up. Do not touch this
295 variable directly.")
297 (defvar-local profiler-report-order nil
298 "The value can be `ascending' or `descending'. Do not touch
299 this variable directly.")
301 (defun profiler-report-make-entry-part (entry)
302 (let ((string (cond
303 ((eq entry t)
304 "Others")
305 ((and (symbolp entry)
306 (fboundp entry))
307 (propertize (symbol-name entry)
308 'face 'link
309 'mouse-face 'highlight
310 'help-echo "mouse-2 or RET jumps to definition"))
312 (profiler-entry-format entry)))))
313 (propertize string 'profiler-entry entry)))
315 (defun profiler-report-make-name-part (tree)
316 (let* ((entry (profiler-calltree-entry tree))
317 (depth (profiler-calltree-depth tree))
318 (indent (make-string (* (1- depth) 2) ?\s))
319 (mark (if (profiler-calltree-leaf-p tree)
320 profiler-report-leaf-mark
321 profiler-report-closed-mark))
322 (entry (profiler-report-make-entry-part entry)))
323 (format "%s%s %s" indent mark entry)))
325 (defun profiler-report-header-line-format (fmt &rest args)
326 (let* ((header (apply 'profiler-format fmt args))
327 (escaped (replace-regexp-in-string "%" "%%" header)))
328 (concat " " escaped)))
330 (defun profiler-report-line-format (tree)
331 (let ((diff-p (profiler-log-diff-p profiler-report-log))
332 (name-part (profiler-report-make-name-part tree))
333 (count (profiler-calltree-count tree))
334 (count-percent (profiler-calltree-count-percent tree)))
335 (profiler-format (cl-ecase (profiler-log-type profiler-report-log)
336 (cpu profiler-report-sample-line-format)
337 (memory profiler-report-memory-line-format))
338 name-part
339 (if diff-p
340 (list (if (> count 0)
341 (format "+%s" count)
342 count)
344 (list count count-percent)))))
346 (defun profiler-report-insert-calltree (tree)
347 (let ((line (profiler-report-line-format tree)))
348 (insert (propertize (concat line "\n") 'calltree tree))))
350 (defun profiler-report-insert-calltree-children (tree)
351 (mapc 'profiler-report-insert-calltree
352 (profiler-calltree-children tree)))
355 ;;; Report mode
357 (defvar profiler-report-mode-map
358 (let ((map (make-sparse-keymap)))
359 ;; FIXME: Add menu.
360 (define-key map "n" 'profiler-report-next-entry)
361 (define-key map "p" 'profiler-report-previous-entry)
362 ;; I find it annoying more than helpful to not be able to navigate
363 ;; normally with the cursor keys. --Stef
364 ;; (define-key map [down] 'profiler-report-next-entry)
365 ;; (define-key map [up] 'profiler-report-previous-entry)
366 (define-key map "\r" 'profiler-report-toggle-entry)
367 (define-key map "\t" 'profiler-report-toggle-entry)
368 (define-key map "i" 'profiler-report-toggle-entry)
369 (define-key map "f" 'profiler-report-find-entry)
370 (define-key map "j" 'profiler-report-find-entry)
371 (define-key map [mouse-2] 'profiler-report-find-entry)
372 (define-key map "d" 'profiler-report-describe-entry)
373 (define-key map "C" 'profiler-report-render-calltree)
374 (define-key map "B" 'profiler-report-render-reversed-calltree)
375 (define-key map "A" 'profiler-report-ascending-sort)
376 (define-key map "D" 'profiler-report-descending-sort)
377 (define-key map "=" 'profiler-report-compare-log)
378 (define-key map (kbd "C-x C-w") 'profiler-report-write-log)
379 (define-key map "q" 'quit-window)
380 map))
382 (defun profiler-report-make-buffer-name (log)
383 (format "*%s-Profiler-Report %s*"
384 (cl-ecase (profiler-log-type log) (cpu 'CPU) (memory 'Memory))
385 (format-time-string "%Y-%m-%d %T" (profiler-log-timestamp log))))
387 (defun profiler-report-setup-buffer (log)
388 "Make a buffer for LOG and return it."
389 (let* ((buf-name (profiler-report-make-buffer-name log))
390 (buffer (get-buffer-create buf-name)))
391 (with-current-buffer buffer
392 (profiler-report-mode)
393 (setq profiler-report-log log
394 profiler-report-reversed nil
395 profiler-report-order 'descending))
396 buffer))
398 (define-derived-mode profiler-report-mode special-mode "Profiler-Report"
399 "Profiler Report Mode."
400 (setq buffer-read-only t
401 buffer-undo-list t
402 truncate-lines t))
405 ;;; Report commands
407 (defun profiler-report-calltree-at-point ()
408 (get-text-property (point) 'calltree))
410 (defun profiler-report-move-to-entry ()
411 (let ((point (next-single-property-change (line-beginning-position)
412 'profiler-entry)))
413 (if point
414 (goto-char point)
415 (back-to-indentation))))
417 (defun profiler-report-next-entry ()
418 "Move cursor to next entry."
419 (interactive)
420 (forward-line)
421 (profiler-report-move-to-entry))
423 (defun profiler-report-previous-entry ()
424 "Move cursor to previous entry."
425 (interactive)
426 (forward-line -1)
427 (profiler-report-move-to-entry))
429 (defun profiler-report-expand-entry ()
430 "Expand entry at point."
431 (interactive)
432 (save-excursion
433 (beginning-of-line)
434 (when (search-forward (concat profiler-report-closed-mark " ")
435 (line-end-position) t)
436 (let ((tree (profiler-report-calltree-at-point)))
437 (when tree
438 (let ((inhibit-read-only t))
439 (replace-match (concat profiler-report-open-mark " "))
440 (forward-line)
441 (profiler-report-insert-calltree-children tree)
442 t))))))
444 (defun profiler-report-collapse-entry ()
445 "Collpase entry at point."
446 (interactive)
447 (save-excursion
448 (beginning-of-line)
449 (when (search-forward (concat profiler-report-open-mark " ")
450 (line-end-position) t)
451 (let* ((tree (profiler-report-calltree-at-point))
452 (depth (profiler-calltree-depth tree))
453 (start (line-beginning-position 2))
455 (when tree
456 (let ((inhibit-read-only t))
457 (replace-match (concat profiler-report-closed-mark " "))
458 (while (and (eq (forward-line) 0)
459 (let ((child (get-text-property (point) 'calltree)))
460 (and child
461 (numberp (setq d (profiler-calltree-depth child)))))
462 (> d depth)))
463 (delete-region start (line-beginning-position)))))
464 t)))
466 (defun profiler-report-toggle-entry ()
467 "Expand entry at point if the tree is collapsed,
468 otherwise collapse."
469 (interactive)
470 (or (profiler-report-expand-entry)
471 (profiler-report-collapse-entry)))
473 (defun profiler-report-find-entry (&optional event)
474 "Find entry at point."
475 (interactive (list last-nonmenu-event))
476 (if event (posn-set-point (event-end event)))
477 (let ((tree (profiler-report-calltree-at-point)))
478 (when tree
479 (let ((entry (profiler-calltree-entry tree)))
480 (find-function entry)))))
482 (defun profiler-report-describe-entry ()
483 "Describe entry at point."
484 (interactive)
485 (let ((tree (profiler-report-calltree-at-point)))
486 (when tree
487 (let ((entry (profiler-calltree-entry tree)))
488 (require 'help-fns)
489 (describe-function entry)))))
491 (cl-defun profiler-report-render-calltree-1
492 (log &key reverse (order 'descending))
493 (let ((calltree (profiler-calltree-build profiler-report-log
494 :reverse reverse)))
495 (setq header-line-format
496 (cl-ecase (profiler-log-type log)
497 (cpu
498 (profiler-report-header-line-format
499 profiler-report-sample-line-format
500 "Function" (list "Time (ms)" "%")))
501 (memory
502 (profiler-report-header-line-format
503 profiler-report-memory-line-format
504 "Function" (list "Bytes" "%")))))
505 (let ((predicate (cl-ecase order
506 (ascending #'profiler-calltree-count<)
507 (descending #'profiler-calltree-count>))))
508 (profiler-calltree-sort calltree predicate))
509 (let ((inhibit-read-only t))
510 (erase-buffer)
511 (profiler-report-insert-calltree-children calltree)
512 (goto-char (point-min))
513 (profiler-report-move-to-entry))))
515 (defun profiler-report-rerender-calltree ()
516 (profiler-report-render-calltree-1 profiler-report-log
517 :reverse profiler-report-reversed
518 :order profiler-report-order))
520 (defun profiler-report-render-calltree ()
521 "Render calltree view."
522 (interactive)
523 (setq profiler-report-reversed nil)
524 (profiler-report-rerender-calltree))
526 (defun profiler-report-render-reversed-calltree ()
527 "Render reversed calltree view."
528 (interactive)
529 (setq profiler-report-reversed t)
530 (profiler-report-rerender-calltree))
532 (defun profiler-report-ascending-sort ()
533 "Sort calltree view in ascending order."
534 (interactive)
535 (setq profiler-report-order 'ascending)
536 (profiler-report-rerender-calltree))
538 (defun profiler-report-descending-sort ()
539 "Sort calltree view in descending order."
540 (interactive)
541 (setq profiler-report-order 'descending)
542 (profiler-report-rerender-calltree))
544 (defun profiler-report-log (log)
545 (let ((buffer (profiler-report-setup-buffer log)))
546 (with-current-buffer buffer
547 (profiler-report-render-calltree))
548 (pop-to-buffer buffer)))
550 (defun profiler-report-compare-log (buffer)
551 "Compare the current profiler log with another."
552 (interactive (list (read-buffer "Compare to: ")))
553 (let* ((log1 (with-current-buffer buffer profiler-report-log))
554 (log2 profiler-report-log)
555 (diff-log (profiler-log-diff log1 log2)))
556 (profiler-report-log diff-log)))
558 (defun profiler-report-write-log (filename &optional confirm)
559 "Write the current profiler log into FILENAME."
560 (interactive
561 (list (read-file-name "Write log: " default-directory)
562 (not current-prefix-arg)))
563 (profiler-log-write-file profiler-report-log
564 filename
565 confirm))
568 ;;; Profiler commands
570 ;;;###autoload
571 (defun profiler-start (mode)
572 "Start/restart profilers.
573 MODE can be one of `cpu', `mem', or `cpu+mem'.
574 If MODE is `cpu' or `cpu+mem', time-based profiler will be started.
575 Also, if MODE is `mem' or `cpu+mem', then memory profiler will be started."
576 (interactive
577 (list (intern (completing-read "Mode (default cpu): "
578 '("cpu" "mem" "cpu+mem")
579 nil t nil nil "cpu"))))
580 (cl-ecase mode
581 (cpu
582 (profiler-cpu-start profiler-sample-interval)
583 (message "CPU profiler started"))
584 (mem
585 (profiler-memory-start)
586 (message "Memory profiler started"))
587 (cpu+mem
588 (profiler-cpu-start profiler-sample-interval)
589 (profiler-memory-start)
590 (message "CPU and memory profiler started"))))
592 (defun profiler-stop ()
593 "Stop started profilers. Profiler logs will be kept."
594 (interactive)
595 (cond
596 ((and (profiler-cpu-running-p)
597 (profiler-memory-running-p))
598 (profiler-cpu-stop)
599 (profiler-memory-stop)
600 (message "CPU and memory profiler stopped"))
601 ((profiler-cpu-running-p)
602 (profiler-cpu-stop)
603 (message "CPU profiler stopped"))
604 ((profiler-memory-running-p)
605 (profiler-memory-stop)
606 (message "Memory profiler stopped"))
608 (error "No profilers started"))))
610 (defun profiler-reset ()
611 "Reset profiler log."
612 (interactive)
613 (ignore (profiler-cpu-log))
614 (ignore (profiler-memory-log))
617 (defun profiler--report-cpu ()
618 (let ((log (profiler-cpu-log)))
619 (when log
620 (puthash 'type 'cpu log)
621 (puthash 'timestamp (current-time) log)
622 (profiler-report-log log))))
624 (defun profiler--report-memory ()
625 (let ((log (profiler-memory-log)))
626 (when log
627 (puthash 'type 'memory log)
628 (puthash 'timestamp (current-time) log)
629 (profiler-report-log log))))
631 (defun profiler-report ()
632 "Report profiling results."
633 (interactive)
634 (profiler--report-cpu)
635 (profiler--report-memory))
637 ;;;###autoload
638 (defun profiler-find-log (filename)
639 "Read a profiler log from FILENAME and report it."
640 (interactive
641 (list (read-file-name "Find log: " default-directory)))
642 (profiler-report-log (profiler-log-read-file filename)))
645 ;;; Profiling helpers
647 (cl-defmacro with-sample-profiling ((&key interval) &rest body)
648 `(unwind-protect
649 (progn
650 (ignore (profiler-cpu-log))
651 (profiler-cpu-start ,interval)
652 ,@body)
653 (profiler-cpu-stop)
654 (profiler--report-cpu)))
656 (defmacro with-memory-profiling (&rest body)
657 `(unwind-protect
658 (progn
659 (ignore (profiler-memory-log))
660 (profiler-memory-start)
661 ,@body)
662 (profiler-memory-stop)
663 (profiler--report-memory)))
665 (provide 'profiler)
666 ;;; profiler.el ends here