* Making elp.el behave like a real profiler
@ 2022-08-15 19:22 Winston Carlile via Emacs development discussions.
2022-08-16 15:27 ` Stefan Monnier
2022-08-17 9:18 ` Michael Albinus
0 siblings, 2 replies; 5+ messages in thread
From: Winston Carlile via Emacs development discussions. @ 2022-08-15 19:22 UTC (permalink / raw)
To: emacs-devel
[-- Attachment #1.1: Type: text/plain, Size: 2614 bytes --]
tl;dr:
I'm working on adding one level of context to function calls
in ELP reports, looking for implementation and usability
feedback.
----
As a heavy TRAMP user I have been frustrated the past few
years with slowness, and painstakingly looked for ways to
remedy this. Along the way I started to explore Emacs' core
file API and with it the magic filename system, specifically
tramp-sh.el. I quickly came to realize its complexity and
the inadequacy of the Emacs Lisp Profiler in a highly
recursive and interconnected codebase.
This comment from elp.el in particular resonated with me:
;; TBD:
;; Make this act like a real profiler, so that it records time spent
;; in all branches of execution.
I decided to take one step in this direction and change ELP
to have one additional level of context for each result.
For example,
(defun g (n)
(f n))
(defun f (n)
(when (not (= n 0))
(f (1- n))))
(g 3)
currently results in this report:
Function Name Call Count
g 1
f 4
My changes produce a report like this:
Function Name Call Count
g 1 ;; calls from functions not instrumented
`-f 1
f 0 ;; calls from functions not instrumented
`-f 3
I implemented this by changing the elp-timer-info-property
from a vector to a plist of vectors indexed by function
symbol, a.k.a. the "caller". The advice wrapper sets a
dynamically scoped variable to be the current function's
symbol (the caller), which is used in callee functions to
lookup which timer info vector to update. At reporting
time, the plists are inverted from callee->caller to
caller->callee.
Before I go any further with this I thought I'd reach out to
the community for some early-middle feedback in case there's
something important I'm missing. Some topics I'm open to
discuss:
1) Is there a better way to programmatically access the call
stack than a dynamic binding hack?
2) How can I make the report more intuitive? Specifically
I'm worried about confusing people with the 0 call count
for f in the above example.
3) Maybe a hashmap would be better than a plist when the
number of instrumented functions is large.
Next on my plate:
- Check for unexpected behavior with async functions (mainly
the aio library)
- Implement sorting by call count, total time & avg time
(each section is sorted normally, and the entire report is
sorted by the max value of each section)
- Keybinding to toggle un-inverting the report
- Keybinding to jump to section
- Clean up documentation
Looking forward to any feedback folks want to share.
[-- Attachment #1.2: Type: text/html, Size: 3061 bytes --]
[-- Attachment #2: tramp-profiling.txt --]
[-- Type: text/plain, Size: 4464 bytes --]
find-file-noselect 0 0.0 0.0
`-file-directory-p 1 0.058936746 0.058936746
`-file-attributes 2 0.182768972 0.091384486
`-file-remote-p 3 0.0013816289 0.0004605429
`-file-local-name 6 0.0001210549 2.017...e-05
`-file-name-case-insensitive-p 2 0.0047963450 0.0023981725
`-file-truename 1 0.347325745 0.347325745
`-file-writable-p 1 0.277082318 0.277082318
`-file-name-absolute-p 6 1.104...e-05 1.840...e-06
find-file 1 0.886424674 0.886424674
`-find-file-noselect 1 0.874459605 0.874459605
file-symlink-p 0 0.0 0.0
`-file-attributes 1 0.237407433 0.237407433
`-file-remote-p 1 1.5728e-05 1.5728e-05
`-file-local-name 3 0.000105425 3.514...e-05
`-file-name-absolute-p 4 1.3182e-05 3.2955e-06
file-writable-p 0 0.0 0.0
`-file-remote-p 5 0.000163197 3.26394e-05
`-file-local-name 11 0.0006359219 5.781...e-05
`-file-name-directory 2 0.001158981 0.0005794905
`-file-exists-p 1 0.099896448 0.099896448
`-file-name-absolute-p 5 1.0354e-05 2.070...e-06
file-exists-p 1 6.7167e-05 6.7167e-05
`-file-remote-p 6 0.000147928 2.465...e-05
`-file-local-name 13 0.000526877 4.052...e-05
`-file-name-absolute-p 5 1.0073e-05 2.0146e-06
file-name-directory 5 4.2829e-05 8.5658e-06
`-file-name-directory 2 6.8447e-05 3.42235e-05
`-file-name-absolute-p 2 7.426e-06 3.713e-06
file-truename 0 0.0 0.0
`-file-remote-p 6 0.001457568 0.000242928
`-file-local-name 12 0.0030903100 0.0002575258
`-file-symlink-p 1 0.238940889 0.238940889
`-file-name-absolute-p 5 9.9e-06 1.98e-06
`-find-file-name-handler 1 5.8146e-05 5.8146e-05
file-name-case-insensitive-p 0 0.0 0.0
`-file-remote-p 6 0.001893119 0.0003155198
`-file-local-name 12 0.000228375 1.903...e-05
`-file-name-absolute-p 14 2.032...e-05 1.451...e-06
file-local-name 0 0.0 0.0
`-file-remote-p 124 0.0061714880 4.977...e-05
file-name-nondirectory 6 5.7052e-05 9.508...e-06
file-remote-p 0 0.0 0.0
`-file-remote-p 6 7.2312e-05 1.205...e-05
`-file-local-name 18 0.0004293619 2.385...e-05
`-file-name-absolute-p 24 4.540...e-05 1.891...e-06
`-find-file-name-handler 178 0.0027772200 1.560...e-05
file-attributes 0 0.0 0.0
`-file-remote-p 17 0.000519756 3.057...e-05
`-file-local-name 40 0.0021130370 5.282...e-05
`-file-name-absolute-p 24 5.230...e-05 2.179...e-06
file-directory-p 0 0.0 0.0
`-file-remote-p 4 7.4628e-05 1.8657e-05
`-file-local-name 9 0.000273939 3.043...e-05
`-file-name-absolute-p 5 3.606...e-06 7.213...e-07
[-- Attachment #3: contextual_elp.patch --]
[-- Type: text/x-patch, Size: 19145 bytes --]
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\ )
\f
+
+(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))
\f
(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)))
\f
@@ -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))
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: Making elp.el behave like a real profiler
2022-08-15 19:22 Making elp.el behave like a real profiler Winston Carlile via Emacs development discussions.
@ 2022-08-16 15:27 ` Stefan Monnier
2022-08-16 15:48 ` Stefan Kangas
2022-08-17 9:18 ` Michael Albinus
1 sibling, 1 reply; 5+ messages in thread
From: Stefan Monnier @ 2022-08-16 15:27 UTC (permalink / raw)
To: Winston Carlile via Emacs development discussions.; +Cc: Winston Carlile
Winston Carlile via "Emacs development discussions." [2022-08-15 12:22:54] wrote:
> I'm working on adding one level of context to function calls
> in ELP reports, looking for implementation and usability feedback.
Before we go any further: are you aware of the sampling based profiler
available via `M-x profiler-start`?
> 1) Is there a better way to programmatically access the call
> stack than a dynamic binding hack?
There's `backtrace-frame(s)`, but I'm not sure it qualifies as "better".
> 2) How can I make the report more intuitive? Specifically
> I'm worried about confusing people with the 0 call count
> for f in the above example.
How 'bout:
Function Name Call Count
g 1 ;; called once:
`-? 1 ;; calls from functions not instrumented
f 4 ;; called 4 times:
`-g 1 ;; once from g
`-f 3 ;; and 3 times from itself
Admittedly, this shows the "reverse" from what you currently show.
You'd have the property that for every function, the first line shows
the total of the subsequent lines.
For the other direction:
Function Name Call Count
g 1 ;; called once
`-f 1 ;; called f once
f 4 ;; called 4 times:
`-f 3 ;; called itself 3 times
In that version, for a given function, the first line's count is not
directly related to the other lines's count (it can be smaller or
larger).
> 3) Maybe a hashmap would be better than a plist when the
> number of instrumented functions is large.
A plist is about as bad as it gets. An alist would be at least a bit
more natural (plists only really make sense when they're written by
humans).
I'm not sure I understand the code correctly, but my quick reading of it
suggest you have O(N^2) calls to `new-infovec`, which seems like
a bad idea [ oh, and naming it without an `elp-` prefix is also a bad
idea) ] since the call graph is probably not that dense, so you'd be
better off allocating them more lazily.
If you keep the O(N^2) infovecs, then I'd recommend hashtables, indeed,
since every alist/plist will have N elements in it, here N will easily
grow to be too big for alist/plist (alist/plist work OK for smallish
number of elements only).
Stefan
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Making elp.el behave like a real profiler
2022-08-16 15:27 ` Stefan Monnier
@ 2022-08-16 15:48 ` Stefan Kangas
0 siblings, 0 replies; 5+ messages in thread
From: Stefan Kangas @ 2022-08-16 15:48 UTC (permalink / raw)
To: Stefan Monnier,
Winston Carlile via Emacs development discussions.
Cc: Winston Carlile
Stefan Monnier <monnier@iro.umontreal.ca> writes:
> Before we go any further: are you aware of the sampling based profiler
> available via `M-x profiler-start`?
Whatever else happens, perhaps the
;; TBD:
;; Make this act like a real profiler, so that it records time spent
;; in all branches of execution. See also `M-x profiler-start'.
comment should be deleted or updated to just refer to profiler.el?
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Making elp.el behave like a real profiler
2022-08-15 19:22 Making elp.el behave like a real profiler Winston Carlile via Emacs development discussions.
2022-08-16 15:27 ` Stefan Monnier
@ 2022-08-17 9:18 ` Michael Albinus
2022-08-17 18:33 ` chad
1 sibling, 1 reply; 5+ messages in thread
From: Michael Albinus @ 2022-08-17 9:18 UTC (permalink / raw)
To: Winston Carlile via Emacs development discussions.; +Cc: Winston Carlile
[-- Attachment #1: Type: text/plain, Size: 2086 bytes --]
Winston Carlile via "Emacs development discussions."
<emacs-devel@gnu.org> writes:
Hi Winston,
> As a heavy TRAMP user I have been frustrated the past few
> years with slowness, and painstakingly looked for ways to
> remedy this. Along the way I started to explore Emacs' core
> file API and with it the magic filename system, specifically
> tramp-sh.el. I quickly came to realize its complexity and
> the inadequacy of the Emacs Lisp Profiler in a highly
> recursive and interconnected codebase.
It is highly appreciated to work on this. However, don't expect that it
will help much in Tramp optimization.
In my experience, most time in Tramp is spent on wire. That is, sending
commands to the remote shell, and reading the command's output. Compared
with this, time spent in Elisp is not so important (although any
optimization will be appreciated as well).
In Tramp it is hard to compare the spent time. Mainly, due to different
network latency in different environments. And this can change even in
your local LAN over the day, so that you cannot be sure whether an
applied optimization helps, or not. I know what I'm speaking about,
because I'm working in this area the last weeks.
What I use for Tramp optimization is to count the number of commands
send to the remote host. The less commands are sent, the better.
As a poor man's approach I trace the Tramp functions tramp-send-command
(all commands sent to the remote shell go through this) and
tramp-file-name-handler (all invocations of Tramp functionality pass
this function). The latter is to know, what Emacs primitive function has
caused a remote command.
So I test something like this
(let ((remote-file-name-inhibit-cache t)) ;; Do not use file caches.
(trace-function-background 'tramp-send-command)
(trace-function-background 'tramp-file-name-handler)
(ignore-errors (kill-buffer trace-buffer))
;; The test.
(with-temp-buffer
(insert-file-contents "/ssh::.emacs" nil 100 nil)))
The *trace-output* for this example is appended.
See also the discussion in bug#56342.
Best regards, Michael.
[-- Attachment #2: Type: text/plain, Size: 20459 bytes --]
======================================================================
1 -> (tramp-file-name-handler expand-file-name "/ssh::.emacs" nil)
1 <- tramp-file-name-handler: #("/ssh:gandalf:/home/albinus/.emacs" 5 12 (tramp-default t))
======================================================================
1 -> (tramp-file-name-handler insert-file-contents #("/ssh:gandalf:/home/albinus/.emacs" 5 12 (tramp-default t)) nil 100 nil nil)
| 2 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/home/albinus/.emacs" 5 12 (tramp-default t)) nil)
| 2 <- tramp-file-name-handler: #("/ssh:gandalf:/home/albinus/.emacs" 5 12 (tramp-default t))
| 2 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t)) nil)
| 2 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t))
| 2 -> (tramp-file-name-handler file-writable-p #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t)))
| | 3 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t)) nil)
| | 3 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t))
| | 3 -> (tramp-file-name-handler file-exists-p #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t)))
| | | 4 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/" nil) "test -e /tmp/ 2>/dev/null; echo tramp_exit_status $?")
| | | 4 <- tramp-send-command: 21
| | 3 <- tramp-file-name-handler: t
| | 3 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/" nil) "test -w /tmp/ 2>/dev/null; echo tramp_exit_status $?")
| | 3 <- tramp-send-command: 21
| 2 <- tramp-file-name-handler: t
| 2 -> (tramp-file-name-handler expand-file-name "tramp." #("/ssh:gandalf:/tmp" 5 12 (tramp-default t)))
| 2 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp."
| 2 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp." "/tmp/")
| 2 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp."
| 2 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| 2 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| 2 -> (tramp-file-name-handler write-region "" nil #1="/ssh:gandalf:/tmp/tramp.aKjmrp" nil silent #1# excl)
| | 3 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler file-truename "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | 4 -> (tramp-file-name-handler file-remote-p "/ssh:gandalf:/tmp/tramp.aKjmrp" localname nil)
| | | | 5 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | | 5 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | 4 <- tramp-file-name-handler: "/tmp/tramp.aKjmrp"
| | | 4 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | 4 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | 4 -> (tramp-file-name-handler file-remote-p "/ssh:gandalf:/tmp/tramp.aKjmrp" localname nil)
| | | | 5 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | | 5 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | 4 <- tramp-file-name-handler: "/tmp/tramp.aKjmrp"
| | | 4 -> (tramp-file-name-handler file-remote-p "/ssh:gandalf:/tmp/tramp.aKjmrp" nil nil)
| | | | 5 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | | 5 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | 4 <- tramp-file-name-handler: "/ssh:gandalf:"
| | | 4 -> (tramp-send-command (tramp-file-name "ssh" nil nil "gandalf" nil "/tmp/tramp.aKjmrp" nil) "\\readlink --canonicalize-missing /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | 4 <- tramp-send-command: 39
| | | 4 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | 4 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | 4 -> (tramp-file-name-handler file-symlink-p "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | | 5 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | | 5 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | | 5 -> (tramp-file-name-handler file-attributes "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | | | 6 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | | | 6 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | | | 6 -> (tramp-send-command (tramp-file-name "ssh" nil nil "gandalf" nil "/tmp/tramp.aKjmrp" nil) "tramp_stat_file_attributes /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | | | 6 <- tramp-send-command: 25
| | | | 5 <- tramp-file-name-handler: nil
| | | 4 <- tramp-file-name-handler: nil
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler file-exists-p "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | 4 -> (tramp-send-command (tramp-file-name "ssh" nil nil "gandalf" nil "/tmp/tramp.aKjmrp" nil) "test -e /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | 4 <- tramp-send-command: 21
| | 3 <- tramp-file-name-handler: nil
| | 3 -> (tramp-file-name-handler file-locked-p "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | 4 -> (tramp-file-name-handler make-lock-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | 4 <- tramp-file-name-handler: nil
| | 3 <- tramp-file-name-handler: nil
| | 3 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler file-attributes "/ssh:gandalf:/tmp/tramp.aKjmrp" integer)
| | | 4 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | 4 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | 4 -> (tramp-send-command (tramp-file-name "ssh" nil nil "gandalf" nil "/tmp/tramp.aKjmrp" nil) "tramp_stat_file_attributes /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | 4 <- tramp-send-command: 25
| | 3 <- tramp-file-name-handler: nil
| | 3 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler file-attributes "/ssh:gandalf:/tmp/tramp.aKjmrp" integer)
| | | 4 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | 4 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | 4 -> (tramp-send-command (tramp-file-name "ssh" nil nil "gandalf" nil "/tmp/tramp.aKjmrp" nil) "tramp_stat_file_attributes /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | 4 <- tramp-send-command: 25
| | 3 <- tramp-file-name-handler: nil
| | 3 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler file-acl "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | 3 <- tramp-file-name-handler: nil
| | 3 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler file-selinux-context "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | 3 <- tramp-file-name-handler: (nil nil nil nil)
| | 3 -> (tramp-file-name-handler file-name-nondirectory "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | 3 <- tramp-file-name-handler: "tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler file-remote-p "/ssh:gandalf:/tmp/tramp.aKjmrp" nil nil)
| | | 4 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | 4 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:"
| | 3 -> (tramp-file-name-handler lock-file "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | 4 -> (tramp-file-name-handler file-locked-p "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | | 5 -> (tramp-file-name-handler make-lock-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | | 5 <- tramp-file-name-handler: nil
| | | 4 <- tramp-file-name-handler: nil
| | | 4 -> (tramp-file-name-handler make-lock-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | 4 <- tramp-file-name-handler: nil
| | | 4 -> (tramp-file-name-handler make-lock-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | 4 <- tramp-file-name-handler: nil
| | 3 <- tramp-file-name-handler: nil
| | 3 -> (tramp-send-command (tramp-file-name "ssh" nil nil "gandalf" nil "/tmp/tramp.aKjmrp" nil) "cat </dev/null >/tmp/tramp.aKjmrp")
| | 3 <- tramp-send-command: 1
| | 3 -> (tramp-file-name-handler file-name-directory "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/"
| | 3 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/" nil)
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/"
| | 3 -> (tramp-file-name-handler directory-file-name "/ssh:gandalf:/tmp/")
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp"
| | 3 -> (tramp-file-name-handler file-modes "/ssh:gandalf:/tmp" nil)
| | | 4 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp" nil)
| | | 4 <- tramp-file-name-handler: "/ssh:gandalf:/tmp"
| | | 4 -> (tramp-file-name-handler file-attributes "/ssh:gandalf:/tmp")
| | | | 5 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp" nil)
| | | | 5 <- tramp-file-name-handler: "/ssh:gandalf:/tmp"
| | | | 5 -> (tramp-send-command (tramp-file-name "ssh" nil nil "gandalf" nil "/tmp" nil) "tramp_stat_file_attributes /tmp 2>/dev/null; echo tramp_exit_status $?")
| | | | 5 <- tramp-send-command: 122
| | | 4 <- tramp-file-name-handler: (t 43 0 0 (25339 54877 0 0) (25340 45027 0 0) (25340 45027 0 0) 10240 "drwxrwxrwt" t 1 (-1 . 1))
| | 3 <- tramp-file-name-handler: 1023
| | 3 -> (tramp-file-name-handler tramp-set-file-uid-gid "/ssh:gandalf:/tmp/tramp.aKjmrp" 1000 1000)
| | | 4 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | 4 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | | 4 -> (tramp-file-name-handler file-exists-p "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | | 5 -> (tramp-send-command (tramp-file-name "ssh" nil nil "gandalf" nil "/tmp/tramp.aKjmrp" nil) "test -e /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | | 5 <- tramp-send-command: 21
| | | 4 <- tramp-file-name-handler: t
| | | 4 -> (tramp-send-command (tramp-file-name "ssh" nil nil "gandalf" nil "/tmp/tramp.aKjmrp" nil) "chown 1000:1000 /tmp/tramp.aKjmrp")
| | | 4 <- tramp-send-command: 1
| | 3 <- tramp-file-name-handler: 1
| | 3 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" "~/")
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler set-file-acl "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | 4 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" nil)
| | | 4 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 <- tramp-file-name-handler: nil
| | 3 -> (tramp-file-name-handler expand-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp" "~/")
| | 3 <- tramp-file-name-handler: "/ssh:gandalf:/tmp/tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler set-file-selinux-context "/ssh:gandalf:/tmp/tramp.aKjmrp" (nil nil nil nil))
| | 3 <- tramp-file-name-handler: nil
| | 3 -> (tramp-file-name-handler unlock-file "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | 4 -> (tramp-file-name-handler make-lock-file-name "/ssh:gandalf:/tmp/tramp.aKjmrp")
| | | 4 <- tramp-file-name-handler: nil
| | 3 <- tramp-file-name-handler: nil
| 2 <- tramp-file-name-handler: nil
| 2 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/home/albinus/.emacs" nil) "dd bs=1 skip=100 if=/home/albinus/.emacs of=/tmp/tramp.aKjmrp")
| 2 <- tramp-send-command: 98
| 2 -> (tramp-file-name-handler file-local-copy #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)))
| | 3 -> (tramp-file-name-handler file-truename #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)))
| | | 4 -> (tramp-file-name-handler file-remote-p #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) localname nil)
| | | | 5 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | | 5 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | 4 <- tramp-file-name-handler: "/tmp/tramp.aKjmrp"
| | | 4 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | 4 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | 4 -> (tramp-file-name-handler file-remote-p #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) localname nil)
| | | | 5 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | | 5 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | 4 <- tramp-file-name-handler: "/tmp/tramp.aKjmrp"
| | | 4 -> (tramp-file-name-handler file-remote-p #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil nil)
| | | | 5 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | | 5 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | 4 <- tramp-file-name-handler: #("/ssh:gandalf:" 5 12 (tramp-default t))
| | | 4 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/tramp.aKjmrp" nil) "\\readlink --canonicalize-missing /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | 4 <- tramp-send-command: 39
| | | 4 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | 4 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | 4 -> (tramp-file-name-handler file-symlink-p #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)))
| | | | 5 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | | 5 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | | 5 -> (tramp-file-name-handler file-attributes #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)))
| | | | | 6 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | | | 6 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | | | 6 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/tramp.aKjmrp" nil) "tramp_stat_file_attributes /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | | | 6 <- tramp-send-command: 151
| | | | 5 <- tramp-file-name-handler: (nil 1 1000 1000 (25340 45027 0 0) (25340 45027 0 0) (25340 45027 0 0) 40997 "-rw-r--r--" nil 862941 (-1 . 1))
| | | 4 <- tramp-file-name-handler: nil
| | 3 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | 3 -> (tramp-file-name-handler file-name-nondirectory #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)))
| | 3 <- tramp-file-name-handler: "tramp.aKjmrp"
| | 3 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | 3 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | 3 -> (tramp-file-name-handler file-attributes #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)))
| | | 4 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | 4 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | 4 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/tramp.aKjmrp" nil) "tramp_stat_file_attributes /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | 4 <- tramp-send-command: 151
| | 3 <- tramp-file-name-handler: (nil 1 1000 1000 (25340 45027 0 0) (25340 45027 0 0) (25340 45027 0 0) 40997 "-rw-r--r--" nil 862941 (-1 . 1))
| | 3 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t)) nil)
| | 3 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t))
| | 3 -> (tramp-file-name-handler file-writable-p #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t)))
| | | 4 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t)) nil)
| | | 4 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t))
| | | 4 -> (tramp-file-name-handler file-exists-p #("/ssh:gandalf:/tmp/" 5 12 (tramp-default t)))
| | | | 5 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/" nil) "test -e /tmp/ 2>/dev/null; echo tramp_exit_status $?")
| | | | 5 <- tramp-send-command: 21
| | | 4 <- tramp-file-name-handler: t
| | | 4 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/" nil) "test -w /tmp/ 2>/dev/null; echo tramp_exit_status $?")
| | | 4 <- tramp-send-command: 21
| | 3 <- tramp-file-name-handler: t
| | 3 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/tramp.aKjmrp" nil) "(env GZIP= gzip </tmp/tramp.aKjmrp | base64) 2>/dev/null; echo tramp_exit_status $?")
| | 3 <- tramp-send-command: 15235
| | 3 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | 3 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | 3 -> (tramp-file-name-handler file-modes #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | 4 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | 4 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | 4 -> (tramp-file-name-handler file-attributes #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)))
| | | | 5 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | | | 5 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | | | 5 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/tramp.aKjmrp" nil) "tramp_stat_file_attributes /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | | | 5 <- tramp-send-command: 151
| | | 4 <- tramp-file-name-handler: (nil 1 1000 1000 (25340 45027 0 0) (25340 45027 0 0) (25340 45027 0 0) 40997 "-rw-r--r--" nil 862941 (-1 . 1))
| | 3 <- tramp-file-name-handler: 420
| 2 <- tramp-file-name-handler: "/tmp/tramp.bQeiWI.aKjmrp"
| 2 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| 2 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| 2 -> (tramp-file-name-handler file-directory-p #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)))
| | 3 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/tramp.aKjmrp" nil) "test -d /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | 3 <- tramp-send-command: 21
| 2 <- tramp-file-name-handler: nil
| 2 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| 2 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| 2 -> (tramp-file-name-handler delete-file #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | 3 -> (tramp-file-name-handler expand-file-name #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t)) nil)
| | 3 <- tramp-file-name-handler: #("/ssh:gandalf:/tmp/tramp.aKjmrp" 5 12 (tramp-default t))
| | 3 -> (tramp-send-command (tramp-file-name "ssh" nil nil #("gandalf" 0 7 (tramp-default t)) nil "/tmp/tramp.aKjmrp" nil) "rm -f /tmp/tramp.aKjmrp 2>/dev/null; echo tramp_exit_status $?")
| | 3 <- tramp-send-command: 21
| 2 <- tramp-file-name-handler: nil
1 <- tramp-file-name-handler: (#("/ssh:gandalf:/home/albinus/.emacs" 5 12 (tramp-default t)) 40997)
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Making elp.el behave like a real profiler
2022-08-17 9:18 ` Michael Albinus
@ 2022-08-17 18:33 ` chad
0 siblings, 0 replies; 5+ messages in thread
From: chad @ 2022-08-17 18:33 UTC (permalink / raw)
To: Michael Albinus
Cc: Winston Carlile via Emacs development discussions.,
Winston Carlile
[-- Attachment #1: Type: text/plain, Size: 755 bytes --]
>
> In my experience, most time in Tramp is spent on wire. That is, sending
> commands to the remote shell, and reading the command's output. Compared
> with this, time spent in Elisp is not so important (although any
> optimization will be appreciated as well).
Based on this, I wonder how useful/difficult it would be to add a sort of
"ping timer" to buffers that make regular use of remote commands, measuring
the delta between just before the most recent send and the following
(assuming no interleaving) recv. With that raw data, it should be
relatively easy to add things like a moving average and/or an alert for
sudden spikes.
Would this be more likely to result in a useful diagnostic or a computed
indicator that slow things are slow?
~Chad
[-- Attachment #2: Type: text/html, Size: 996 bytes --]
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2022-08-17 18:33 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-08-15 19:22 Making elp.el behave like a real profiler Winston Carlile via Emacs development discussions.
2022-08-16 15:27 ` Stefan Monnier
2022-08-16 15:48 ` Stefan Kangas
2022-08-17 9:18 ` Michael Albinus
2022-08-17 18:33 ` chad
Code repositories for project(s) associated with this public inbox
https://git.savannah.gnu.org/cgit/emacs.git
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).