Skip to content

Instantly share code, notes, and snippets.

@trishume
Last active October 25, 2020 21:43
Show Gist options
  • Star 5 You must be signed in to star a gist
  • Fork 1 You must be signed in to fork a gist
  • Save trishume/40bf7045a23412d4c016f5e8533437db to your computer and use it in GitHub Desktop.
Save trishume/40bf7045a23412d4c016f5e8533437db to your computer and use it in GitHub Desktop.
See new Github Repo version: https://github.com/aspiers/etrace - Emacs Latency Tracing for the Chromium Catapult Trace Event Format.
;; 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)

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
@aspiers
Copy link

aspiers commented Oct 18, 2020

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:

image

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

@aspiers
Copy link

aspiers commented Oct 18, 2020

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

image

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

@aspiers
Copy link

aspiers commented Oct 18, 2020

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

@mplscorwin
Copy link

+1

@munen
Copy link

munen commented Oct 19, 2020

+1

@trishume
Copy link
Author

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!

@aspiers
Copy link

aspiers commented Oct 19, 2020

Ok I'll do it.

@aspiers
Copy link

aspiers commented Oct 24, 2020

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

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

@trishume
Copy link
Author

@aspiers Nice readme! License looks okay, maybe change copyright line from my name to "Jane Street Group, LLC opensource@janestreet.com" 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.

@aspiers
Copy link

aspiers commented Oct 25, 2020

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!

@trishume
Copy link
Author

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

@aspiers
Copy link

aspiers commented Oct 25, 2020

Awesome, thanks :-)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment