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

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 :-)