The curious case of (make-frame) delays
Posted on Sat 22 August 2009 by alex in geek
I had a problem on my home machine with the way emacs created new X frames. New frames would appear but then pause for 4-8 seconds before I could type any text. My question to the mailing list was met with a comment to get a faster graphics card. This seemed a little silly so this morning I put on my debugging head and tried to figure out what was going on.
First up was OProfile which confirmed that the problem wasn't CPU bound anywhere in the system. Then I threw the Emacs Lisp Profiler at the problem:
(load-library "elp") (elp-instrument-function 'make-frame) (elp-instrument-package "frame") (make-frame) (elp-results)
This confirmed that the "make-frame" function was indeed taking between 8-12 seconds to complete. However none of the other frame functions where taking that long. Time for another tack and breaking out strace. This did show that emacs was getting a lot of -EAGAIN's while reading from a Unix socket. Unfortunately it seems impossible to find out what the other end of the socket is connected to on Linux. I had some guesses but couldn't narrow it down.
Then I started emacs with "-q --daemon" so I could use Dope to profile by .emacs. A quick test showed that new frames popped up straight away before my init file was loaded. This really should have been the first thing I checked as often configurations can break things.
After some radical M-x comment-region surgery on the .emacs I found that unsurprisingly my display hacks seemed to be the culprit. I wasn't sure why so I started adding some (message) calls to the various functions to see if I could track down the delay. After instrumenting I found the problem had gone away which was very unexpected. In fact I tracked down the minimum diff to the following:
diff --git a/dotemacs b/dotemacs
index 55609aa..6948e3c 100644
--- a/dotemacs
+++ b/dotemacs
@@ -511,9 +511,11 @@ on the command line"
; First we need the colour-theme package
(if I-am-emacs-22+
+ (message "loading color-theme at %s" (current-time-string))
(if (maybe-load-library "color-theme")
(if (fboundp 'color-theme-initialize)
- (color-theme-initialize))))
+ (color-theme-initialize)))
+ (message "loading color-theme done at %s" (current-time-string)))
; Define the default frames sizes, shouldn't apply to a tty invocation
; TODO: handle remote sessions better, probably by probing remote X
This doesn't make any sense to me. For starters the colour-theme library is only loaded on start-up not for every frame. Besides why would an additional message change this behaviour? Have I just triggered some sort of weird racyness? And what an earth could this have to do with all the -EAGAIN's I saw emacs suffering from when talking to the unknown Unix socket?
One additional interesting data point from my investigation. Without the change the syscall count for a new frame looks like this:
11:22 alex@danny/x86_64 [elisp.git] >strace -c -p 6369 Process 6369 attached - interrupt to quit ^CProcess 6369 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 42.11 0.000435 0 6692 writev 40.08 0.000414 0 13674 poll 9.68 0.000100 0 16940 10341 read 4.55 0.000047 0 6637 1 rt_sigreturn 3.58 0.000037 0 3700 3696 open 0.00 0.000000 0 4 close 0.00 0.000000 0 4 stat 0.00 0.000000 0 2 fstat 0.00 0.000000 0 17 brk 0.00 0.000000 0 72 rt_sigprocmask 0.00 0.000000 0 269 1 select 0.00 0.000000 0 1 setitimer 0.00 0.000000 0 41 kill 0.00 0.000000 0 1 uname 0.00 0.000000 0 10 getdents ------ ----------- ----------- --------- --------- ---------------- 100.00 0.001033 48064 14039 total
And with the change we get this:
11:24 alex@danny/x86_64 [elisp.git] >strace -c -p 6441 Process 6441 attached - interrupt to quit ^CProcess 6441 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000040 0 1189 poll 0.00 0.000000 0 1135 706 read 0.00 0.000000 0 268 264 open 0.00 0.000000 0 4 close 0.00 0.000000 0 4 stat 0.00 0.000000 0 2 fstat 0.00 0.000000 0 16 brk 0.00 0.000000 0 114 rt_sigprocmask 0.00 0.000000 0 433 2 rt_sigreturn 0.00 0.000000 0 445 writev 0.00 0.000000 0 140 2 select 0.00 0.000000 0 3 setitimer 0.00 0.000000 0 18 kill 0.00 0.000000 0 1 uname 0.00 0.000000 0 10 getdents ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000040 3782 974 total
It's all very curious.
EDIT TO ADD: Doh! It's all the fault of color theme. I was spending so much time being confused why the (message) patch changed everything and it's obvious when you look at it cleanly. The first (message) passes the (if I-am-emacs-22+ stanza and the else leg which loads color-theme is never executed. It then become very clear where the delay is coming from when you profile color-theme:
(load-library "elp") (elp-instrument-package "color") (elp-instrument-function 'modify-frame-parameters) Function Name Call Count Elapsed Time Average Time ============================================== ========== ============ ============ color-theme-gnome2 1 6.949076 6.949076 color-theme-install 6 6.9489930000 1.1581655000 modify-frame-parameters 28 6.8929370000 0.2461763214 color-theme-install-frame-params 6 6.8865859999 1.1477643333 color-theme-blue-gnus 1 1.707156 1.707156 color-theme-salmon-font-lock 1 1.06505 1.06505 color-theme-blue-erc 1 1.045608 1.045608 color-theme-salmon-diff 1 1.041382 1.041382 color-theme-blue-eshell 1 1.040324 1.040324 color-theme-install-faces 6 0.062013 0.0103355 color-theme-spec-compat 218 0.0012549999 5.756...e-06 color-values 21 0.000656 3.123...e-05 color-theme-filter 18 0.000298 1.655...e-05 color-theme-install-variables 6 9.7e-05 1.616...e-05 color-theme-plist-delete 58 9.099...e-05 1.568...e-06 color-theme-alist-reduce 12 3.9e-05 3.25e-06 color-theme-canonic 6 3.700...e-05 6.166...e-06 color-theme-alist 12 1.100...e-05 9.166...e-07 color-theme-variables 6 9e-06 1.5e-06 color-theme-frame-params 6 5.999...e-06 1e-06 color-theme-faces 6 5.999...e-06 1e-06 color-theme-spec-filter 1 2e-06 2e-06
And it's very obvious that the extra eye candy is expensive, especially when applied to every frame.