Tracking down why emacsclient -c is so slow

Tracking down why emacsclient -c is so slow

[Alex Bennee]

On one of my machines there is a massive pause between a new frame
appearing and being able to edit the file. I'm wondering if there is
anything I can do to track down the slow bit.

I've added some (message)'s to two hooks to try and track it down. You
can see an example emacsclient -t gives:

after-make-frame-functions at Fri Aug 21 19:18:59 2009
server-visit-hook at Fri Aug 21 19:18:59 2009
When done with a buffer, type C-x #

However editing the same file with -c gives:

after-make-frame-functions at Fri Aug 21 19:18:21 2009
server-visit-hook at Fri Aug 21 19:18:25 2009
(No files need saving)

In fact this very message is being edited in a -c frame and shows a
fairly consistent 4 second delay:

after-make-frame-functions at Fri Aug 21 19:21:44 2009
enabling long lines for itsalltext [2 times]
server-visit-hook at Fri Aug 21 19:21:48 2009
When done with a buffer, type C-x #

Are there any other hooks run between after-make-frame-functions and
server-visit-hook I can hook to to see why it takes so long?


-- 
Alex, homepage: http://www.bennee.com/~alex/
http://www.half-llama.co.uk

Re: Tracking down why emacsclient -c is so slow

[Peter Dyballa]

Am 21.08.2009 um 20:25 schrieb Alex Bennee:

> Are there any other hooks run between after-make-frame-functions and
> server-visit-hook I can hook to to see why it takes so long?


Yes, they're called PCI, PCI-Express, AGP, and much more. Stick  
another and faster graphics card in such a slot and you'll less  
consumed to create a new frame.

There is also the OS QNX. It's Photon windowing system is as fast as  
a usual photon. Maybe Plan 9 is as fast as Photon.

--
Greetings

   Pete

Theory and practice are the same, in theory, but, in practice, they  
are different.

Re: Tracking down why emacsclient -c is so slow

[Alex Bennee]

2009/8/21 Peter Dyballa <Peter_Dyballa@web.de>:
>
> Am 21.08.2009 um 20:25 schrieb Alex Bennee:
>
>> Are there any other hooks run between after-make-frame-functions and
>> server-visit-hook I can hook to to see why it takes so long?
>
>
> Yes, they're called PCI, PCI-Express, AGP, and much more. Stick another and
> faster graphics card in such a slot and you'll less consumed to create a new
> frame.
>

The current delays I'm seeing are a little excessive, especially
considering that the rest of the OS doesn't seem to have too much
problem displaying compiz and full-rate HD video.

The results of the profile look like:

Function Name                    Call Count  Elapsed Time  Average Time
===============================  ==========  ============  ============
make-frame                       2           17.385781     8.6928905
frame-set-background-mode        14          0.0370519999  0.0026465714
frame-parameters                 54          0.0008449999  1.564...e-05
frame-parameter                  494         0.0007000000  1.417...e-06
framep                           956         0.0004720000  4.937...e-07
frame-list                       429         0.0003700000  8.624...e-07
frame-or-buffer-changed-p        39          0.0001459999  3.743...e-06
framep-on-display                202         0.0001409999  6.980...e-07
frame-selected-window            46          5.799...e-05  1.260...e-06
frame-live-p                     58          4.599...e-05  7.931...e-07
frame-visible-p                  53          2.800...e-05  5.283...e-07
frame-char-width                 13          1.200...e-05  9.230...e-07
frame-char-height                14          1.199...e-05  8.571...e-07

I thought I'd throw oprofile at the task but as far as it's concerned
emacs spends most of it's time in mark-object and Fbyte_code and isn't
actually a significant proportion of the CPU time. Something else
seems to be going on.

-- 
Alex, homepage: http://www.bennee.com/~alex/
http://www.half-llama.co.uk

Re: Tracking down why emacsclient -c is so slow

[Peter Dyballa]

Am 22.08.2009 um 10:10 schrieb Alex Bennee:

> The current delays I'm seeing are a little excessive


I'm using old Apple hardware (almost six years old), an old Apple OS  
(Tiger, i.e., Mac OS X 10.4), a slow CPU (PowerPC 7447A at 1.5 GHz,  
512 kB L2 cache), a slow graphics card (ATI Mobility Radeon 9700  
RV360M11 with 64 MB), and also an outdated X server (XFree 86 4.4.0  
based). The window manager is Blackbox. GNU Emacs 23.1.50 is compiled  
with debug support. After two, maybe three seconds, the first frame  
appears when I launch GNU Emacs with -Q, and also when I leave away  
the -Q, but then it takes some ten seconds until the Emacs desktop is  
rebuilt and I can start to use GNU Emacs. Emacsclient -c is faster,  
say, one second.

Compared to native Aqua/Quartz applications it's lightning fast.  
Compared to GNU Emacs 18.57 (?) it's slower than a snail.

How much time do you have to wait until OpenOffice appears on your  
screen? Gkrellm? You can also use the *trace commands in Linux to see  
what happens at launch time. And afterwards.

Is the situation improved when you use GNU Emacs 23.1 from some  
installer package? Or is it improved when you compile it yourself,  
optimised for your hard- and software?

--
Greetings

   Pete

Chicago, n.:
         Where the dead still vote ... early and often!

Re: Tracking down why emacsclient -c is so slow

[Alex Bennee]

2009/8/22 Peter Dyballa <Peter_Dyballa@web.de>:
>
> Am 22.08.2009 um 10:10 schrieb Alex Bennee:
>
>> The current delays I'm seeing are a little excessive
>
> I'm using old Apple hardware (almost six years old), an old Apple OS (Tiger,
> i.e., Mac OS X 10.4), a slow CPU (PowerPC 7447A at 1.5 GHz, 512 kB L2
> cache), a slow graphics card (ATI Mobility Radeon 9700 RV360M11 with 64 MB),
> and also an outdated X server (XFree 86 4.4.0 based). The window manager is
> Blackbox. GNU Emacs 23.1.50 is compiled with debug support. After two, maybe
> three seconds, the first frame appears when I launch GNU Emacs with -Q, and
> also when I leave away the -Q, but then it takes some ten seconds until the
> Emacs desktop is rebuilt and I can start to use GNU Emacs. Emacsclient -c is
> faster, say, one second.
>
> Compared to native Aqua/Quartz applications it's lightning fast. Compared to
> GNU Emacs 18.57 (?) it's slower than a snail.

It's definitely something other than graphics performance. The frame
actually appears very quickly it just takes a while before I can start
editing.

> Is the situation improved when you use GNU Emacs 23.1 from some installer
> package? Or is it improved when you compile it yourself, optimised for your
> hard- and software?

I'm running the current Gentoo 23.1 ebuild, compiled obviously for my machine.

-- 
Alex, homepage: http://www.bennee.com/~alex/
http://www.half-llama.co.uk

Re: Tracking down why emacsclient -c is so slow

[Peter Dyballa]

Am 22.08.2009 um 13:33 schrieb Alex Bennee:

> It's definitely something other than graphics performance. The frame
> actually appears very quickly it just takes a while before I can start
> editing.


So it is your init file/customisation.

--
Greetings

   Pete

Government is actually the worst failure of civilized man. There has  
never been a really good one, and even those that are most tolerable  
are arbitrary, cruel, grasping and unintelligent.
				– H. L. Mencken

Re: Tracking down why emacsclient -c is so slow

[Alex Bennee]

2009/8/22 Peter Dyballa <Peter_Dyballa@web.de>:
>
> Am 22.08.2009 um 13:33 schrieb Alex Bennee:
>
>> It's definitely something other than graphics performance. The frame
>> actually appears very quickly it just takes a while before I can start
>> editing.
>
> So it is your init file/customisation.

Apparently so, although it's unclear what in it is causing the slow
down. Adding a few (message) lines to the .emacs makes it work fine
again [1]. I suspect it's triggering a very odd bug in emacs as I
can't see what would cause the slowdown in the customisation code.


[1] http://www.bennee.com/~alex/news.php?wl_mode=more&wl_eid=1292

-- 
Alex, homepage: http://www.bennee.com/~alex/
http://www.half-llama.co.uk

Re: Tracking down why emacsclient -c is so slow

[Alex Bennee]

2009/8/22 Peter Dyballa <Peter_Dyballa@web.de>:
>
> Am 22.08.2009 um 13:33 schrieb Alex Bennee:
>
>> It's definitely something other than graphics performance. The frame
>> actually appears very quickly it just takes a while before I can start
>> editing.
>
> So it is your init file/customisation.

Having dug deeper into what was going on it seems to be
color-theme-related, although for the life of me I'm not sure what is
happening.

If I apply the following patch to my .emacs everything is dine:

--- a/dotemacs
+++ b/dotemacs
@@ -514,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)))

But what is really revealing is the results of "elp" while profiling
the color-theme-gnome2 I was using:

Results with (message) hack
Function Name            Call Count  Elapsed Time  Average Time
=======================  ==========  ============  ============
modify-frame-parameters  10          0.023506      0.0023506
color-values             3           0.000159      5.299...e-05

Results without (message) hack
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

Curiously the colours seem to be set up correctly each time, but this
really shouldn't be the case. Looking at the definition of
color-theme-gnome2 is looks to be recursive?

(defun color-theme-gnome2 ()
  "Wheat on darkslategrey scheme.
`color-theme-gnome' started it all.

This theme supports standard faces, font-lock, eshell, info, message,
gnus, custom, widget, woman, diary, cperl, bbdb, and erc.  This theme
includes faces for Emacs and XEmacs.

The theme does not support w3 faces because w3 faces can be controlled
by your default style sheet.

This is what you should put in your .Xdefaults file, if you want to
change the colors of the menus in Emacs 20 as well:

emacs*Background:		DarkSlateGray
emacs*Foreground:		Wheat"
  (interactive)
  (color-theme-blue-gnus)
  (let ((color-theme-is-cumulative t))
    (color-theme-blue-erc)
    (color-theme-blue-eshell)
    (color-theme-salmon-font-lock)
    (color-theme-salmon-diff)
    (color-theme-install
     '(color-theme-gnome2
       ((foreground-color . "wheat")
	(background-color . "darkslategrey")
	(mouse-color . "Grey")
	(cursor-color . "LightGray")
	(border-color . "black")
	(background-mode . dark))
       ((apropos-keybinding-face . underline)
	(apropos-label-face . italic)
	(apropos-match-face . secondary-selection)
	(apropos-property-face . bold-italic)
	(apropos-symbol-face . info-xref)
	(goto-address-mail-face . message-header-to-face)
	(goto-address-mail-mouse-face . secondary-selection)
	(goto-address-url-face . info-xref)
	(goto-address-url-mouse-face . highlight)
	(list-matching-lines-face . bold)
	(view-highlight-face . highlight))
       (default ((t (nil))))
       (bbdb-company ((t (:foreground "pale green"))))
       (bbdb-name ((t (:bold t :foreground "pale green"))))
       (bbdb-field-name ((t (:foreground "medium sea green"))))
       (bbdb-field-value ((t (:foreground "dark sea green"))))
       (bold ((t (:bold t))))
       (bold-italic ((t (:italic t :bold t :foreground "beige"))))
       (calendar-today-face ((t (:underline t))))
       (comint-highlight-prompt ((t (:foreground "medium aquamarine"))))
       (cperl-array-face ((t (:foreground "Yellow"))))
       (cperl-hash-face ((t (:foreground "White"))))
       (cperl-nonoverridable-face ((t (:foreground "SkyBlue"))))
       (custom-button-face ((t (:underline t :foreground "MediumSlateBlue"))))
       (custom-documentation-face ((t (:foreground "Grey"))))
       (custom-group-tag-face ((t (:foreground "MediumAquamarine"))))
       (custom-state-face ((t (:foreground "LightSalmon"))))
       (custom-variable-tag-face ((t (:foreground "Aquamarine"))))
       (diary-face ((t (:foreground "IndianRed"))))
       (dired-face-directory ((t (:bold t :foreground "sky blue"))))
       (dired-face-permissions ((t (:foreground "aquamarine"))))
       (dired-face-flagged ((t (:foreground "tomato"))))
       (dired-face-marked ((t (:foreground "light salmon"))))
       (dired-face-executable ((t (:foreground "green yellow"))))
       (fringe ((t (:background "darkslategrey"))))
       (highlight ((t (:background "PaleGreen" :foreground "DarkGreen"))))
       (highline-face ((t (:background "SeaGreen"))))
       (holiday-face ((t (:background "DimGray"))))
       (hyper-apropos-hyperlink ((t (:bold t :foreground "DodgerBlue1"))))
       (hyper-apropos-documentation ((t (:foreground "LightSalmon"))))
       (info-header-xref ((t (:foreground "DodgerBlue1" :bold t))))
       (info-menu-5 ((t (:underline t))))
       (info-node ((t (:underline t :bold t :foreground "DodgerBlue1"))))
       (info-xref ((t (:bold t :foreground "DodgerBlue1"))))
       (isearch ((t (:background "sea green"))))
       (italic ((t (:italic t))))
       (menu ((t (:foreground "wheat" :background "darkslategrey"))))
       (modeline ((t (:background "dark olive green" :foreground "wheat"))))
       (modeline-buffer-id ((t (:background "dark olive green"
:foreground "beige"))))
       (modeline-mousable ((t (:background "dark olive green"
:foreground "yellow green"))))
       (modeline-mousable-minor-mode ((t (:background "dark olive
green" :foreground "wheat"))))
       (region ((t (:background "dark cyan" :foreground "cyan"))))
       (secondary-selection ((t (:background "Aquamarine" :foreground
"SlateBlue"))))
       (show-paren-match-face ((t (:bold t :background "Aquamarine"
:foreground "steel blue"))))
       (show-paren-mismatch-face ((t (:background "Red" :foreground "White"))))
       (underline ((t (:underline t))))
       (widget-field-face ((t (:foreground "LightBlue"))))
       (widget-inactive-face ((t (:foreground "DimGray"))))
       (widget-single-line-field-face ((t (:foreground "LightBlue"))))
       (w3m-anchor-face ((t (:bold t :foreground "DodgerBlue1"))))
       (w3m-arrived-anchor-face ((t (:bold t :foreground "DodgerBlue3"))))
       (w3m-header-line-location-title-face ((t (:foreground "beige"
:background "dark olive green"))))
       (w3m-header-line-location-content-face ((t (:foreground "wheat"
:background "dark olive green"))))
       (woman-bold-face ((t (:bold t))))
       (woman-italic-face ((t (:foreground "beige"))))
       (woman-unknown-face ((t (:foreground "LightSalmon"))))
       (zmacs-region ((t (:background "dark cyan" :foreground "cyan"))))))))

But I'm still puzzled as to why putting a (message) in before loading
color-theme causes this drastic change in behaviour? It can't be a
race condition surely? Emacs is single threaded is it not?


>
> --
> Greetings


-- 
Alex, homepage: http://www.bennee.com/~alex/
http://www.half-llama.co.uk

Re: Tracking down why emacsclient -c is so slow

[Alex Bennee]

2009/8/22 Alex Bennee <kernel-hacker@bennee.com>:
> 2009/8/22 Peter Dyballa <Peter_Dyballa@web.de>:
>> Am 22.08.2009 um 13:33 schrieb Alex Bennee:
>
> If I apply the following patch to my .emacs everything is dine:
>
> --- a/dotemacs
> +++ b/dotemacs
> @@ -514,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)))

Doh. Of course the extra message make the whole color-theme start not
load, therefore no colour theme switches, therefore no slow frames.
>
> --
> Alex, homepage: http://www.bennee.com/~alex/
> http://www.half-llama.co.uk
>



-- 
Alex, homepage: http://www.bennee.com/~alex/
http://www.half-llama.co.uk

Re: Tracking down why emacsclient -c is so slow

[A.Politz]

On Aug 22, 10:10 am, Alex Bennee <kernel-hac...@bennee.com> wrote:
> 2009/8/21 Peter Dyballa <Peter_Dyba...@web.de>:
>
>
>
> > Am 21.08.2009 um 20:25 schrieb Alex Bennee:
>
> >> Are there any other hooks run between after-make-frame-functions and
> >> server-visit-hook I can hook to to see why it takes so long?
>
> > Yes, they're called PCI, PCI-Express, AGP, and much more. Stick another and
> > faster graphics card in such a slot and you'll less consumed to create a new
> > frame.
>
> The current delays I'm seeing are a little excessive, especially
> considering that the rest of the OS doesn't seem to have too much
> problem displaying compiz and full-rate HD video.
>
> The results of the profile look like:
>
> Function Name                    Call Count  Elapsed Time  Average Time
> ===============================  ==========  ============  ============
> make-frame                       2           17.385781     8.6928905

>after-make-frame-functions at Fri Aug 21 19:18:21 2009
>server-visit-hook at Fri Aug 21 19:18:25 2009
>(No files need saving)

This together seem to imply, that the time is spent in one of the
after-make-frame-functions.

Have you done this with 'emacs -Q --daemon' ?

elp-instrument-list won't allow to profile all functions,
but you can do it anyway. Expect your emacs to be broken
afterwards.

(progn
  (require 'elp)
  (elp-instrument-list
   (mapcar #'intern
	   (all-completions "" obarray
			    #'(lambda (sym)
				(and (elp-profilable-p sym)
				     (not (eq sym '+))))))))


-ap

Re: Tracking down why emacsclient -c is so slow

[Alex Bennee]

2009/8/22 A.Politz <politza@googlemail.com>:
> On Aug 22, 10:10 am, Alex Bennee <kernel-hac...@bennee.com> wrote:
<snip>
>
>>after-make-frame-functions at Fri Aug 21 19:18:21 2009
>>server-visit-hook at Fri Aug 21 19:18:25 2009
>>(No files need saving)
>
> This together seem to imply, that the time is spent in one of the
> after-make-frame-functions.
>
> Have you done this with 'emacs -Q --daemon' ?
>

Yes, it does seem to be something introduced by my .emacs frame
modification functions. Adding some additional instrumentation made it
go away although I have no idea why [1].

> elp-instrument-list won't allow to profile all functions,
> but you can do it anyway. Expect your emacs to be broken
> afterwards.
>
> (progn
>  (require 'elp)
>  (elp-instrument-list
>   (mapcar #'intern
>           (all-completions "" obarray
>                            #'(lambda (sym)
>                                (and (elp-profilable-p sym)
>                                     (not (eq sym '+))))))))

Hmm, my version of elp doesn't have the elp-profilable-p

[1] http://www.bennee.com/~alex/news.php?wl_mode=more&wl_eid=1292
-- 
Alex, homepage: http://www.bennee.com/~alex/
http://www.half-llama.co.uk