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>
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/>.
30 (defgroup profiler nil
35 (defcustom profiler-sample-interval
1
36 "Default sample interval in millisecond."
42 (defun profiler-ensure-string (object)
43 (cond ((stringp 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
57 (apply 'profiler-format subfmt arg
))
60 ((and (symbolp subfmt
)
64 (profiler-ensure-string arg
)))
65 for len
= (length str
)
67 collect
(substring str
0 width
) into frags
70 (let ((padding (make-string (- width len
) ?\s
)))
72 (left (concat str padding
))
73 (right (concat padding str
))))
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
)
91 (apply 'string
(if (eq (car s
) ?
,) (cdr s
) s
)))
92 (profiler-ensure-string nbytes
)))
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
))
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
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
))
136 (puthash 'diff-p t newlog
)
137 (maphash (lambda (backtrace count
)
138 (when (vectorp backtrace
)
139 (puthash backtrace
(- (gethash backtrace log1
0) count
)
144 (defun profiler-log-fixup-entry (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
))
158 (profiler-log-fixup-backtrace backtrace
))
163 (defun profiler-log-write-file (log filename
&optional confirm
)
164 "Write LOG into FILENAME."
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."
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
))
182 (count 0) (count-percent "")
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
)))
201 (1+ (profiler-calltree-depth parent
)))))
203 (defun profiler-calltree-find (tree entry
)
204 "Return a child tree of ENTRY under TREE."
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
)
212 (setq children
(cdr children
))))
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
)
222 (lambda (backtrace count
)
223 (when (vectorp backtrace
)
225 (max (length backtrace
)))
227 (let ((entry (aref backtrace
(if reverse i
(- max i
1)))))
229 (let ((child (profiler-calltree-find node entry
)))
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
))))))))
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
246 (setf (profiler-calltree-count-percent node
)
247 (profiler-format-percent (profiler-calltree-count node
)
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
)
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
))))
265 (defcustom profiler-report-closed-mark
"+"
266 "An indicator of closed calltrees."
270 (defcustom profiler-report-open-mark
"-"
271 "An indicator of open calltrees."
275 (defcustom profiler-report-leaf-mark
" "
276 "An indicator of calltree leaves."
280 (defvar profiler-report-sample-line-format
285 (defvar profiler-report-memory-line-format
287 (19 right
((14 right profiler-format-nbytes
)
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
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)
305 ((and (symbolp entry
)
307 (propertize (symbol-name entry
)
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
))
340 (list (if (> count
0)
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
)))
357 (defvar profiler-report-mode-map
358 (let ((map (make-sparse-keymap)))
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
)
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
))
398 (define-derived-mode profiler-report-mode special-mode
"Profiler-Report"
399 "Profiler Report Mode."
400 (setq buffer-read-only t
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)
415 (back-to-indentation))))
417 (defun profiler-report-next-entry ()
418 "Move cursor to next entry."
421 (profiler-report-move-to-entry))
423 (defun profiler-report-previous-entry ()
424 "Move cursor to previous entry."
427 (profiler-report-move-to-entry))
429 (defun profiler-report-expand-entry ()
430 "Expand entry at point."
434 (when (search-forward (concat profiler-report-closed-mark
" ")
435 (line-end-position) t
)
436 (let ((tree (profiler-report-calltree-at-point)))
438 (let ((inhibit-read-only t
))
439 (replace-match (concat profiler-report-open-mark
" "))
441 (profiler-report-insert-calltree-children tree
)
444 (defun profiler-report-collapse-entry ()
445 "Collpase entry at point."
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))
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
)))
461 (numberp (setq d
(profiler-calltree-depth child
)))))
463 (delete-region start
(line-beginning-position)))))
466 (defun profiler-report-toggle-entry ()
467 "Expand entry at point if the tree is collapsed,
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)))
479 (let ((entry (profiler-calltree-entry tree
)))
480 (find-function entry
)))))
482 (defun profiler-report-describe-entry ()
483 "Describe entry at point."
485 (let ((tree (profiler-report-calltree-at-point)))
487 (let ((entry (profiler-calltree-entry tree
)))
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
495 (setq header-line-format
496 (cl-ecase (profiler-log-type log
)
498 (profiler-report-header-line-format
499 profiler-report-sample-line-format
500 "Function" (list "Time (ms)" "%")))
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
))
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."
523 (setq profiler-report-reversed nil
)
524 (profiler-report-rerender-calltree))
526 (defun profiler-report-render-reversed-calltree ()
527 "Render reversed calltree view."
529 (setq profiler-report-reversed t
)
530 (profiler-report-rerender-calltree))
532 (defun profiler-report-ascending-sort ()
533 "Sort calltree view in ascending order."
535 (setq profiler-report-order
'ascending
)
536 (profiler-report-rerender-calltree))
538 (defun profiler-report-descending-sort ()
539 "Sort calltree view in descending order."
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."
561 (list (read-file-name "Write log: " default-directory
)
562 (not current-prefix-arg
)))
563 (profiler-log-write-file profiler-report-log
568 ;;; Profiler commands
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."
577 (list (intern (completing-read "Mode (default cpu): "
578 '("cpu" "mem" "cpu+mem")
579 nil t nil nil
"cpu"))))
582 (profiler-cpu-start profiler-sample-interval
)
583 (message "CPU profiler started"))
585 (profiler-memory-start)
586 (message "Memory profiler started"))
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."
596 ((and (profiler-cpu-running-p)
597 (profiler-memory-running-p))
599 (profiler-memory-stop)
600 (message "CPU and memory profiler stopped"))
601 ((profiler-cpu-running-p)
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."
613 (ignore (profiler-cpu-log))
614 (ignore (profiler-memory-log))
617 (defun profiler--report-cpu ()
618 (let ((log (profiler-cpu-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)))
627 (puthash 'type
'memory log
)
628 (puthash 'timestamp
(current-time) log
)
629 (profiler-report-log log
))))
631 (defun profiler-report ()
632 "Report profiling results."
634 (profiler--report-cpu)
635 (profiler--report-memory))
638 (defun profiler-find-log (filename)
639 "Read a profiler log from FILENAME and report it."
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
)
650 (ignore (profiler-cpu-log))
651 (profiler-cpu-start ,interval
)
654 (profiler--report-cpu)))
656 (defmacro with-memory-profiling
(&rest body
)
659 (ignore (profiler-memory-log))
660 (profiler-memory-start)
662 (profiler-memory-stop)
663 (profiler--report-memory)))
666 ;;; profiler.el ends here