Tips for profiling misbehaving Emacs Lisp?

Question

I customize Emacs a lot. Recently, I added something to my .emacs configuration that sporadically pegs my CPU at 100%, but I really don't know what it is.

If I press C-g a bunch of times, eventually I'll get a message below the minibuffer asking me if I want to auto save my files and then if I want to abort emacs entirely. If I keep saying no and keeping pressing C-g, eventually I can get back to running emacs as normal. An hour or so later it will happen again.

I could keep going about like I am, commenting out various things I've added recently, restarting emacs, trying to narrow down the culprit, but it's slow going.

Is there a way I can profile emacs directly to figure out what lisp function is hogging the CPU?

Answer 1

The suggestion of setting debug-on-quit to t so that you can find out what Emacs is up to is a good one. You can think of this as being a form of sampling profiling with a single sample: often a single sample is all you need.

---

Update: Starting with version 24.3, Emacs contains two profilers. There's a (new) sampling profiler in profiler.el, and an (old) instrumenting profiler in elp.el.

The sampling profiler is documented here. It's pretty straightforward to use:

To begin profiling, type M-x profiler-start. You can choose to profile by processor usage, memory usage, or both. After doing some work, type M-x profiler-report to display a summary buffer for each resource that you chose to profile. When you have finished profiling, type M-x profiler-stop.

Here's some example output from a cpu+mem profiler session with the Perforce/Emacs integration that I maintain. I've expanded the topmost function (progn) in order to find out where the CPU time and memory use is coming from.

Function                                            Bytes    % - progn                                        26,715,850  29%   - let                                        26,715,850  29%     - while                                    26,715,850  29%       - let                                    26,715,850  29%         - cond                                 26,715,850  29%           - insert                             26,715,850  29%             + c-after-change                   26,713,770  29%             + p4-file-revision-annotate-links       2,080   0% + let                                          20,431,797  22% + call-interactively                           12,767,261  14% + save-current-buffer                          10,005,836  11% + while                                         8,337,166   9% + p4-annotate-internal                          5,964,974   6% + p4-annotate                                   2,821,034   3% + let*                                          2,089,810   2% 

You can see that the culprit is c-after-change, so it looks as though I could save a lot of CPU time and memory by locally binding inhibit-modification-hooks to t around this code.

---

You can also use the Emacs Lisp Profiler. This is rather under-documented: you'll have to read the comments in elp.el for the details, but basically you run elp-instrument-package to turn on profiling for all the functions with a given prefix, and then elp-results to see the results.

Here's some typical output after typing M-x elp-instrument-package RET c- RET, fontifying 4,000 lines of C, and then running elp-results (and using elp-sort-by-function to sort by call count):

Function Name                  Call Count  Elapsed Time  Average Time =============================  ==========  ============  ============ c-skip-comments-and-strings    107         0.0           0.0 c-valid-offset                 78          0.0           0.0 c-set-offset                   68          0.031         0.0004558823 c-end-of-macro                 52          0.0           0.0 c-neutralize-CPP-line          52          0.0           0.0 c-font-lock-invalid-string     20          0.0           0.0 c-set-style-1                  19          0.031         0.0016315789 ... 

In your particular case the profiler doesn't help immediately, because you don't know which package is at fault. But if you can make a guess (or use debug-on-quit to find it for sure) then the profiler can help you diagnose the problem in detail.