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

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