See new Github Repo version: https://github.com/aspiers/etrace - Emacs Latency Tracing for the Chromium Catapult Trace Event Format.

etrace.el

;; This gist has been superseded by a Github repo, new activity will
;; happen at https://github.com/aspiers/etrace

;;; etrace.el --- Emacs Lisp Tracer  -*- lexical-binding: t -*-
;; Released under the MIT license, Copyright Jane Street Group, LLC
;; This module modifies the instrumentation profiler included with
;; Emacs called "elp" to also record trace events for the beginning
;; and end of function calls, and provides a function to write out
;; those events in Chromium JSON trace format.
;;
;; First use elp commands to instrument the functions you want, then
;; do the thing you want to trace, then M-x etrace-write RET to write
;; out a trace to the configurable etrace-output-file. You can now
;; open chrome://tracing and load the resulting trace file to view it.

(require 'elp)

(defcustom etrace-output-file "~/etrace.json"
  "When calling etrace-write, write the trace to this file."
  :type 'file)

(defvar etrace--trace nil "Trace events")

(defun etrace--make-wrapper-advice (orig funsym)
  "Advice to make the piece of advice that instruments FUNSYM."
  (let ((elp-wrapper (funcall orig 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]."
      (let ((result))
        (push (list ?B funsym (current-time)) etrace--trace)
        (unwind-protect
          (setq result (apply elp-wrapper func args))
          (push (list ?E funsym (current-time)) etrace--trace))
        result))))

(advice-add #'elp--make-wrapper :around #'etrace--make-wrapper-advice)

(defun etrace-clear ()
  "Clear the etrace buffer"
  (interactive)
  (setq etrace--trace nil))

(defun etrace-write ()
  "Write out trace to etrace-output-file then clear the current trace variable"
  (interactive)
  (save-window-excursion
    (save-excursion
      (find-file-literally etrace-output-file)
      (erase-buffer)
      (insert "[")
      (let* ((first-el t)
             (trace (reverse etrace--trace))
             (start-time (if etrace--trace (float-time (nth 2 (car trace))) nil)))
        (dolist (ev trace)
          (if first-el
              (setq first-el nil)
            (insert ","))
          ;; Intentionally avoid using a proper JSON formatting library, traces can be
          ;; multiple megabytes and writing them this way is probably faster and produces
          ;; compact JSON but without everything being on one line.
          (insert
           (format
            "{\"name\":\"%s\",\"cat\":\"\",\"ph\":\"%c\",\"ts\":%d,\"pid\":0,\"tid\":0,\"args\":{}}\n"
            (nth 1 ev) (nth 0 ev) (truncate (* 1000000 (- (float-time (nth 2 ev)) start-time))))))
        (insert "]")
        (save-buffer))))
  (message "Wrote trace to etrace-output-file (%s)!" etrace-output-file)
  (etrace-clear))

(provide 'etrace)

etrace.md

Thanks to aspiers this is now a real project with a repo!

I posted this without any intention to maintain or extend it because I don't really use Emacs much, but @aspiers offered to turn it into a real repo people can contribute to, so check out the latest version there:

https://github.com/aspiers/etrace

Performance Tracing For Emacs

How To Use It

1. Either M-: (require 'etrace) or add (require 'etrace) to your Emacs config, or enable the micro-feature for it if you use micro-features from the non-Spacemacs Emacs config. (Optional) Run M-x customize-variable etrace-output-file to change where the trace will be written, it defaults to ~/etrace.json
2. Run M-x elp-instrument-package and type in a function prefix to instrument all the functions with that prefix. It uses a completion box so note that by default it'll complete to whatever's selected in there, if you want to complete to a prefix with no corresponding function you can press the up arrow until the text you typed is selected rather than any completion. There's also M-x elp-instrument-function for individual functions.
3. Run M-x etrace-clear
4. Do the thing you want a trace of
5. Run M-x etrace-write to write out the trace file.
6. Go to chrome://tracing in Chrome and click the load button and open the trace file. Use alt+scroll to zoom. Alternatively use https://ui.perfetto.dev/#!/ which is also good but in different ways, for example it can show you the total time and percentage of time taken by different functions in a selection range.
7. Make some changes and then repeat from step 4.
8. Run M-x elp-restore-all to un-instrument any instrumented functions

Here's a screenshot of what the resulting JSON trace file looks like in chrome://tracing:

This seems really cool, thanks a lot for sharing! I've tried it with an etrace.json I just generated by instrumenting org and running org-agenda. The resulting trace file is 21MB. I see some issues however:

• I see a lot of (Did Not Finish) in the graph even though org-agenda did complete. Is this expected?
• I don't understand how this is apparently rendering call trees when elp-results itself doesn't show call trees. Is elp capturing enough data to construct call trees and then failing to take advantage of that with its own reporting in a way which your etrace is doing, or am I misunderstanding something?
• Chrome is massively struggling to render the trace, e.g. when I select an area, the whole thing grinds to a halt for many seconds. Same with most operations. So it's not currently very usable for me. If there is a way to fix this I'd love to hear about it!

@aspiers Interesting.

• My guess for why you're getting so many (Did Not Finish) spans is that I didn't handle the case where a function is unwound by an exception. I think the solution is to record the end event using unwind-protect (https://www.gnu.org/software/emacs/manual/html_node/elisp/Cleanups.html#Cleanups). This may also have something to do with the performance problems.
• It records a separate trace using advice on the normal ELP recording. ELP indeed doesn't store enough info.
• That's unfortunate. It might get better if you have less unfinished spans, it also may be improved by using https://ui.perfetto.dev/#!/ to view the trace instead, or maybe https://speedscope.app.

Thanks, that's super helpful! Now I understand the point of etrace--make-wrapper-advice - very good to know. Also those two other renderer sites seem to perform a lot better than chrome://tracing, although I found that reducing the number of functions instrumented helps quite a lot, even though it only halves the size of etrace.json.

Wrapping (org-agenda) in (unwind-protect ...) didn't seem to make any difference, but I have noticed that org-agenda-skip ends with the code (throw :skip t), so I wonder if this could explain it? If so, is there an easy way for the trace to correctly handle catching of exceptions? I'm pretty sure that this graph is incorrect in depicting that each org-agenda-skip runs for a long time.

OK, now I'm finally getting somewhere! After adding (elp-restore-function 'org-agenda-skip) to my setup code and re-profiling, I get this:

So this suggests that the issue was indeed related to throw.

BTW I find that https://www.speedscope.app/ is the most usable interface of the three by a noticeable gap.

Also, I note that the wrapped instrumented functions have the extra This function has :around advice: ELP-instrumentation ... text near the top of the function's docstring, which kind of spoils some interfaces, e.g.:

So if possible, it would be better if it could add that advice text at the end of the docstring.

Also, this is definitely useful enough that it deserves to be promoted from a gist into its own repository - hint hint ;-)

+1

+1

One of you could do it! I don't really use Emacs anymore, so I don't plan on maintaining or improving this script, and it's only a few lines long so I didn't see a need for a repo. But one of you could make a legitimate version of it!

Ok I'll do it.

Here it is: https://github.com/aspiers/etrace

@trishume Please could you confirm you're OK with the LICENSE file I added?

@aspiers Nice readme! License looks okay, maybe change copyright line from my name to "Jane Street Group, LLC [email protected]" since I wrote this at work and got permission to post it as a gist under the MIT license.

Also I used it at work again the other day and ran into issues with spans not being closed that were fixed by using an unwind-protect. I pushed an update to the gist with the unwind-protect, so you probably want to add that to your version too.

That's all done, and I've invited you as a collaborator to the new repo, so maybe to minimise confusion we can retire this gist now by replacing its contents with a message redirecting people to the repo? I have a feeling quite a few people will find this useful and that it will probably evolve nicely over time as contributions come in!

@aspiers Thanks! I added clear redirection notices to all three parts but preserved the contents because I might as well.

Awesome, thanks :-)