bug#10669: 24.0.93; Emacs daemon high CPU load

bug#10669: 24.0.93; Emacs daemon high CPU load

[Michael Welsh Duggan]

In certain circumstances, emacs running in daemon mode ends up in a high
CPU state, and fills the .xsession-errors log with large numbers of
"Back to top level." messages.  I am using a freshly bootstrapped bzr
trunk checkout of emacs from 2012.01.29.

Here follows the minimal set of steps I was able to determine that
recreates the problem.  Small deviations from this (such as not using
emacsclient) did not trigger the problem.  I am running Gnome 3 and the
gnome-shell, but have seen (although not tested in detail) this same
problem in a Gnome 2 desktop session.

In a Gnome desktop session:

1) Create a .emacs file containing the following single line:

   (server-start)

2) Start emacs using the following incantation:

   emacsclient -a "" -c -n

3) Log out of the desktop session.

4) Log in.

5) Run top.  See that emacs is taking up most of the CPU.

I have been able to attach gdb to the runaway process, but have as yet
been unable to determine what it is doing.  If others are unable to
recreate the problem, I am happy to try debugging on this end, with a
little guidance.



In GNU Emacs 24.0.93.1 (i686-pc-linux-gnu, X toolkit)
 of 2012-01-29 on maru
Windowing system distributor `The X.Org Foundation', version 11.0.11103901
Configured using:
 `configure '--enable-asserts' 'CFLAGS=-ggdb3 -O0'
 '--without-toolkit-scroll-bars' '--enable-maintainer-mode'
 '--with-x-toolkit=lucid''

Important settings:
  value of $LC_ALL: nil
  value of $LC_COLLATE: nil
  value of $LC_CTYPE: nil
  value of $LC_MESSAGES: nil
  value of $LC_MONETARY: nil
  value of $LC_NUMERIC: nil
  value of $LC_TIME: nil
  value of $LANG: en_US.utf8
  value of $XMODIFIERS: nil
  locale-coding-system: utf-8-unix
  default enable-multibyte-characters: t

-- 
Michael Welsh Duggan
(md5i@md5i.com)

bug#10669: 24.0.93; Emacs daemon high CPU load

[Michael Welsh Duggan]

> In certain circumstances, emacs running in daemon mode ends up in a high
> CPU state, and fills the .xsession-errors log with large numbers of
> "Back to top level." messages.  I am using a freshly bootstrapped bzr
> trunk checkout of emacs from 2012.01.29.

This bug may be related to the archived bug #5535.
<URL:http://debbugs.gnu.org/5535>

-- 
Michael Welsh Duggan
(md5i@md5i.com)

bug#10669: 24.0.93; Emacs daemon high CPU load

[Glenn Morris]

Michael Welsh Duggan wrote:

> This bug may be related to the archived bug #5535.
> <URL:http://debbugs.gnu.org/5535>

Sounds similar. It's not archived or resolved BTW.
The usual answer to such issues has been "use a lucid toolkit build
rather than a Gtk one". But, you are already doing that, so it can't be
the infamous Gtk+ bug that is responsible in this case.

bug#10669: 24.0.93; Emacs daemon high CPU load

[Michael Welsh Duggan]

Glenn Morris <rgm@gnu.org> writes:

> Michael Welsh Duggan wrote:
>
>> This bug may be related to the archived bug #5535.
>> <URL:http://debbugs.gnu.org/5535>
>
> Sounds similar. It's not archived or resolved BTW.

When I attempted to add to it, I got the following:

  You sent a message to the GNU bug tracking system, relating to bug#5536.
  
  Your message was dated Mon, 30 Jan 2012 17:21:52 -0500 and was sent to
  5536-submit@debbugs.gnu.org.  It had
  Message-ID: <87mx94g7b3.fsf@maru.md5i.com>
  and Subject: Emacs daemon high CPU load: New information
  
  This bug is currently in a read-only state.  This is because it has been
  closed and has received no comments for more than 28 days, until now.

I thought that meant archived, but I may have the terminology wrong.

-- 
Michael Welsh Duggan
(md5i@md5i.com)

bug#10669: 24.0.93; Emacs daemon high CPU load

[Glenn Morris]

Michael Welsh Duggan wrote:

>>> This bug may be related to the archived bug #5535.
>>> <URL:http://debbugs.gnu.org/5535>
>>
>> Sounds similar. It's not archived or resolved BTW.
>
> When I attempted to add to it, I got the following:
>
>   You sent a message to the GNU bug tracking system, relating to bug#5536.
                                                                       ^^^^

:)

bug#10669: 24.0.93; Emacs daemon high CPU load

[Michael Welsh Duggan]

Glenn Morris <rgm@gnu.org> writes:

> Michael Welsh Duggan wrote:
>
>>>> This bug may be related to the archived bug #5535.
>>>> <URL:http://debbugs.gnu.org/5535>
>>>
>>> Sounds similar. It's not archived or resolved BTW.
>>
>> When I attempted to add to it, I got the following:
>>
>>   You sent a message to the GNU bug tracking system, relating to bug#5536.
>                                                                        ^^^^
> :)

Mea maxima culpa.  :)

-- 
Michael Welsh Duggan
(md5i@md5i.com)

bug#10669: 24.0.93; Emacs daemon high CPU load

[Jan Djärv]

Hello. 


31 jan 2012 kl. 01:44 skrev Glenn Morris <rgm@gnu.org>:

> Michael Welsh Duggan wrote:
> 
>> This bug may be related to the archived bug #5535.
>> <URL:http://debbugs.gnu.org/5535>
> 
> Sounds similar. It's not archived or resolved BTW.
> The usual answer to such issues has been "use a lucid toolkit build
> rather than a Gtk one". But, you are already doing that, so it can't be
> the infamous Gtk+ bug that is responsible in this case.

It can still be related. If Gconf or Gsettings is used, glib is managing the input loop, as in the Gtk case. 

   Jan D. 

bug#10669: 24.0.93; Emacs daemon high CPU load

[Michael Welsh Duggan]

Jan Djärv <jan.h.d@swipnet.se> writes:

> 31 jan 2012 kl. 01:44 skrev Glenn Morris <rgm@gnu.org>:
>
>> Michael Welsh Duggan wrote:
>> 
>>> This bug may be related to the archived bug #5535.
>>> <URL:http://debbugs.gnu.org/5535>
>> 
>> Sounds similar. It's not archived or resolved BTW.
>> The usual answer to such issues has been "use a lucid toolkit build
>> rather than a Gtk one". But, you are already doing that, so it can't be
>> the infamous Gtk+ bug that is responsible in this case.
>
> It can still be related. If Gconf or Gsettings is used, glib is
> managing the input loop, as in the Gtk case.

I just reconfigured like below.  The problem still exists in this
configuration.  The loop it ends up in endlessly writes "Back to top
level." into the .xsession-errors.

Anything I can do to help debug this?  I am a moderately experienced gdb
user.

In GNU Emacs 24.0.93.3 (i686-pc-linux-gnu, X toolkit)
 of 2012-02-01 on maru
Windowing system distributor `The X.Org Foundation', version 11.0.11103901
Configured using:
 `configure '--without-gconf' '--without-gsettings'
 '--without-toolkit-scroll-bars' '--with-x-toolkit=lucid''

-- 
Michael Welsh Duggan
(md5i@md5i.com)

bug#10669: 24.0.93; Emacs daemon high CPU load

[Chong Yidong]

Michael Welsh Duggan <md5i@md5i.com> writes:

> In certain circumstances, emacs running in daemon mode ends up in a high
> CPU state, and fills the .xsession-errors log with large numbers of
> "Back to top level." messages.  I am using a freshly bootstrapped bzr
> trunk checkout of emacs from 2012.01.29.
>
> Here follows the minimal set of steps I was able to determine that
> recreates the problem.  Small deviations from this (such as not using
> emacsclient) did not trigger the problem.  I am running Gnome 3 and the
> gnome-shell, but have seen (although not tested in detail) this same
> problem in a Gnome 2 desktop session.

Can you reproduce this with Emacs 23.4, or is this specific to the
trunk?

bug#10669: 24.0.93; Emacs daemon high CPU load

[Michael Welsh Duggan]

Chong Yidong <cyd@gnu.org> writes:

> Michael Welsh Duggan <md5i@md5i.com> writes:
>
>> In certain circumstances, emacs running in daemon mode ends up in a high
>> CPU state, and fills the .xsession-errors log with large numbers of
>> "Back to top level." messages.  I am using a freshly bootstrapped bzr
>> trunk checkout of emacs from 2012.01.29.
>>
>> Here follows the minimal set of steps I was able to determine that
>> recreates the problem.  Small deviations from this (such as not using
>> emacsclient) did not trigger the problem.  I am running Gnome 3 and the
>> gnome-shell, but have seen (although not tested in detail) this same
>> problem in a Gnome 2 desktop session.
>
> Can you reproduce this with Emacs 23.4, or is this specific to the
> trunk?

I can reproduce this with Emacs 23.4.

-- 
Michael Welsh Duggan
(md5i@md5i.com)

bug#10669: More debugging

[Michael Welsh Duggan]

Okay.  Here's what the infinite loop actually is:

The C function 'command_loop' calls 'top_level_1', which eventually
evals 'top-level', which is 'normal-top-level'.  'normal-top-level'
notes that 'command-line-processed' is t, calls (message "Back to top
level."), and then returns.

Back to 'command_loop, which then calls 'command_loop_2', which calls
command_loop_1', which calls 'read_key_sequence', which calls
'read_char'.

'read_char' eventually calls 'kbd_buffer_get_event' at keyboard.c:2797.
This ends up calling getchar(), since we are running as a daemon
(keyboard.c:3796).  This getchar() returns -1.  'read_char' returns this
-1.

'read_key_sequence' takes this -1, and sets its return value to 0
(keyboard.c:9373).

'command_loop_1' takes this 0, and returns nil (keyboard.c:1463).
'command_loop_2' returns nil on nil.

'command_loop' then continues in its loop, calling 'top_level_1' again,
followed by 'command_loop_2'.

-- 
Michael Welsh Duggan
(md5i@md5i.com)

bug#10669: More debugging

[Michael Welsh Duggan]

Michael Welsh Duggan <md5i@md5i.com> writes:

> Okay.  Here's what the infinite loop actually is:
>
> The C function 'command_loop' calls 'top_level_1', which eventually
> evals 'top-level', which is 'normal-top-level'.  'normal-top-level'
> notes that 'command-line-processed' is t, calls (message "Back to top
> level."), and then returns.
>
> Back to 'command_loop, which then calls 'command_loop_2', which calls
> command_loop_1', which calls 'read_key_sequence', which calls
> 'read_char'.
>
> 'read_char' eventually calls 'kbd_buffer_get_event' at keyboard.c:2797.
> This ends up calling getchar(), since we are running as a daemon
> (keyboard.c:3796).  This getchar() returns -1.  'read_char' returns this
> -1.

So, at this point, daemon_pipe[] == {3, 4}.  It looks to me that
'daemon-initialized' isn't being called by 'command-line'.  This may be
due to the --eval "(server-start)"?  I think I may need some help
debugging further than this.

-- 
Michael Welsh Duggan
(md5i@md5i.com)

bug#10669: More debugging

[Stefan Kangas]

Michael Welsh Duggan <md5i@md5i.com> writes:

> Michael Welsh Duggan <md5i@md5i.com> writes:
>
>> Okay.  Here's what the infinite loop actually is:
>>
>> The C function 'command_loop' calls 'top_level_1', which eventually
>> evals 'top-level', which is 'normal-top-level'.  'normal-top-level'
>> notes that 'command-line-processed' is t, calls (message "Back to top
>> level."), and then returns.
>>
>> Back to 'command_loop, which then calls 'command_loop_2', which calls
>> command_loop_1', which calls 'read_key_sequence', which calls
>> 'read_char'.
>>
>> 'read_char' eventually calls 'kbd_buffer_get_event' at keyboard.c:2797.
>> This ends up calling getchar(), since we are running as a daemon
>> (keyboard.c:3796).  This getchar() returns -1.  'read_char' returns this
>> -1.
>
> So, at this point, daemon_pipe[] == {3, 4}.  It looks to me that
> 'daemon-initialized' isn't being called by 'command-line'.  This may be
> due to the --eval "(server-start)"?  I think I may need some help
> debugging further than this.

That was 8 years ago.  Is this still an issue using modern versions of
Emacs?

Best regards,
Stefan Kangas

bug#10669: More debugging

[Michael Welsh Duggan]

Stefan Kangas <stefan@marxist.se> writes:

> Michael Welsh Duggan <md5i@md5i.com> writes:
>
>> Michael Welsh Duggan <md5i@md5i.com> writes:
>>
>>> Okay.  Here's what the infinite loop actually is:
>>>
>>> The C function 'command_loop' calls 'top_level_1', which eventually
>>> evals 'top-level', which is 'normal-top-level'.  'normal-top-level'
>>> notes that 'command-line-processed' is t, calls (message "Back to top
>>> level."), and then returns.
>>>
>>> Back to 'command_loop, which then calls 'command_loop_2', which calls
>>> command_loop_1', which calls 'read_key_sequence', which calls
>>> 'read_char'.
>>>
>>> 'read_char' eventually calls 'kbd_buffer_get_event' at keyboard.c:2797.
>>> This ends up calling getchar(), since we are running as a daemon
>>> (keyboard.c:3796).  This getchar() returns -1.  'read_char' returns this
>>> -1.
>>
>> So, at this point, daemon_pipe[] == {3, 4}.  It looks to me that
>> 'daemon-initialized' isn't being called by 'command-line'.  This may be
>> due to the --eval "(server-start)"?  I think I may need some help
>> debugging further than this.
>
> That was 8 years ago.  Is this still an issue using modern versions of
> Emacs?

I think you can close this.  If I encounter it again, I will just create
a new bug.

-- 
Michael Welsh Duggan
(md5i@md5i.com)

bug#5535: bug#10669: More debugging

[Stefan Kangas]

Michael Welsh Duggan <mwd@md5i.com> writes:

> I think you can close this.  If I encounter it again, I will just create
> a new bug.

Thanks, closing this bug now.

Best regards,
Stefan Kangas

Re: bug#10669: More debugging

[scytale]

data point:

running 24.1.50.1 on Ubuntu 12.04 via cassou ppa.

I can trigger this with an init.el consisting solely of:

(custom-set-variables
 '(desktop-base-file-name "emacs.desktop")
 '(desktop-save t)
 '(desktop-save-mode t)
)

no other custom configuration file is present.
If i remove those lines from init.el and instead set the vars using setq in my personal config file things work ok. 

When the bug is triggered I have two emacs daemon processes running:
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
scytale      12847  0.0  0.1 200180  4884 pts/0    S+   15:24   0:00 /usr/bin/emacs --daemon
scytale      12848  0.0  0.3 209936 14540 ?        Ss   15:24   0:00 /usr/bin/emacs --daemon

I'm guessing the whole daemonize-fork-pass-fd dance is getting fouled up somehow.

I found a reference to what sounds like a very similar problem here:
http://forums.gentoo.org/viewtopic-p-5998467.html?sid=f177a9491dffb58f06b39b58ab4024d1#5998467

afaict this poster believed that in his case the problem was caused by two emacs processes trying to access the same emacs.desktop file. In my case neither of the two daemon processes have the file open by the time I can run lsof on them. 

I'll do some tracing/debugging when I get the chance.