Recent recentf slowdown?

Recent recentf slowdown?

[Stephen Berman]

Since updating to GNU Emacs 23.1.50.1 (i686-pc-linux-gnu, GTK+ Version
2.14.4) of 2009-06-23 on escher I've twice experienced a long pause
during startup, apparently while the recentf list is being cleaned up.
The *Messages* buffer shows this after the second occurrence:

Loading /home/steve/.emacs.d/.recentf...done
Cleaning up the recentf list...
File /mnt/etc/samba/smb.conf removed from the recentf list
File /mnt/etc/samba/ removed from the recentf list [3 times]
Cleaning up the recentf list...done (2 removed)

During startup, when the third of these messages is displayed in the
echo area, Emacs appears to just stop: no redisplay, keyboard or mouse
response at all, but also no noticeable increase in CPU activity.  The
first time this happened I thought Emacs was hanging and killed the
process.  When I restarted, it came up as (fast as) usual.  Now (the
next day) it happened again and this time I waited longer.  I neglected
to look at the time but I guess it was at least a minute, maybe two.  I
was just about to try attaching the Emacs process to gdb when it resumed
and completed startup, displaying the last two messages above.  It
appears to be functioning normally since then.

According to the ChangeLog there hasn't been anything change to recentf
for a long time.  Perhaps the pause is due to the tramp update, though I
was not using tramp to visit the file being cleaned up when Emacs
paused.  Has anyone else experienced this or does anyone have an idea
what the cause could be?

Steve Berman

Re: Recent recentf slowdown?

[Michael Albinus]

Stephen Berman <stephen.berman@gmx.net> writes:

> According to the ChangeLog there hasn't been anything change to recentf
> for a long time.  Perhaps the pause is due to the tramp update, though I
> was not using tramp to visit the file being cleaned up when Emacs
> paused.  Has anyone else experienced this or does anyone have an idea
> what the cause could be?

I'm not aware of a Tramp change which could explain this behaviour. You
might add (setq tramp-verbose 8) in your .emacs, in case of Tramp
activities we can check them in Tramp's debug buffer, including timestamps.

> Steve Berman

Best regards, Michael.

Re: Recent recentf slowdown?

[Stephen Berman]

On Fri, 26 Jun 2009 05:44:12 +0200 Michael Albinus <michael.albinus@gmx.de> wrote:

> Stephen Berman <stephen.berman@gmx.net> writes:
>
>> According to the ChangeLog there hasn't been anything change to recentf
>> for a long time.  Perhaps the pause is due to the tramp update, though I
>> was not using tramp to visit the file being cleaned up when Emacs
>> paused.  Has anyone else experienced this or does anyone have an idea
>> what the cause could be?
>
> I'm not aware of a Tramp change which could explain this behaviour. You
> might add (setq tramp-verbose 8) in your .emacs, in case of Tramp
> activities we can check them in Tramp's debug buffer, including timestamps.

Thanks for the suggestion.  I added it before starting Emacs today.
Tramp is apparently not involved, since no Tramp debug buffer or any
other Tramp buffer came up and there's no mention of Tramp in
*Messages*.  But at startup there was again a pause when the echo area
displayed the message "Cleaning up the recentf list...".  This time it
lasted about 30 seconds, then startup completed and Emacs appears to be
running normally.  However, the complete recentf message is "Cleaning up
the recentf list...done (0 removed)", so I assume 30 seconds is too long
and indicative of a problem.  With this emacs process running I started
another Emacs with my initializations, including the same recentf file,
and it came up without a pause.  Same thing with `emacs -Q --eval
"(recentf-mode 1)"'.

Steve Berman

Re: Recent recentf slowdown?

[Stephen Berman]

On Fri, 26 Jun 2009 09:11:11 +0200 Stephen Berman <stephen.berman@gmx.net> wrote:

> *Messages*.  But at startup there was again a pause when the echo area
> displayed the message "Cleaning up the recentf list...".  This time it
> lasted about 30 seconds, then startup completed and Emacs appears to be
> running normally.  However, the complete recentf message is "Cleaning up
> the recentf list...done (0 removed)", so I assume 30 seconds is too long
> and indicative of a problem.  With this emacs process running I started
> another Emacs with my initializations, including the same recentf file,
> and it came up without a pause.  Same thing with `emacs -Q --eval
> "(recentf-mode 1)"'.

I continue to see this misbehavior, i.e. a ca. 30 stillstand while the
recentf list is being cleaned up, even with 0 files removed.  Today I
reproduced it with -Q -l test.el, the latter file consisting solely of
this:

(custom-set-variables
 '(recentf-mode t))

This was with my recentf file.  Again there was a ca. 30 second pause
(one file was removed).  I have not been able to reproduce the pause by
repeating this with a new emacs process but the same login session.
Does anyone have an idea what the problem could be, or a suggestion
about how to try and track it down?

Steve Berman

Recent recentf slowdown due to "/ftp:..."

[Stephen Berman]

On Thu, 02 Jul 2009 10:56:09 +0200 Stephen Berman <stephen.berman@gmx.net> wrote:

> On Fri, 26 Jun 2009 09:11:11 +0200 Stephen Berman <stephen.berman@gmx.net> wrote:
>
>> *Messages*.  But at startup there was again a pause when the echo area
>> displayed the message "Cleaning up the recentf list...".  This time it
>> lasted about 30 seconds, then startup completed and Emacs appears to be
>> running normally.  However, the complete recentf message is "Cleaning up
>> the recentf list...done (0 removed)", so I assume 30 seconds is too long
>> and indicative of a problem.  With this emacs process running I started
>> another Emacs with my initializations, including the same recentf file,
>> and it came up without a pause.  Same thing with `emacs -Q --eval
>> "(recentf-mode 1)"'.
>
> I continue to see this misbehavior, i.e. a ca. 30 stillstand while the
> recentf list is being cleaned up, even with 0 files removed.  Today I
> reproduced it with -Q -l test.el, the latter file consisting solely of
> this:
>
> (custom-set-variables
>  '(recentf-mode t))
>
> This was with my recentf file.  Again there was a ca. 30 second pause
> (one file was removed).  I have not been able to reproduce the pause by
> repeating this with a new emacs process but the same login session.
> Does anyone have an idea what the problem could be, or a suggestion
> about how to try and track it down?

I've narrowed it down to the above sexp as the entire content of
~/.emacs and this ~/.recentf:

,----
| ;;; Automatically generated by `recentf' on Fri Jul  3 12:53:43 2009.
| 
| (setq recentf-list
|       '(
|         "/ftp:anonymous@ftp.bla.org:/"
|         ))
| 
| (setq recentf-filter-changer-current 'nil)
| 
| \f
| ;; Local Variables:
| ;; coding: utf-8-emacs
| ;; End:
`----

The above ftp site is made up but it still resulted in a 30 second pause
(I have real ftp sites in my normal recentf-file).  Again, this only
happens with the first Emacs started in a given login session, and I've
only been experiencing this since updating from the trunk after the 23.1
branch was created.  That update included the new Tramp update and Tramp
appears to be implicated by the above ftp line, though, as I already
mentioned, adding (setq tramp-verbose 8) to ~/.emacs produces no Tramp
debug buffer.

Steve Berman

Re: Recent recentf slowdown due to "/ftp:..."

[Stephen Berman]

On Fri, 03 Jul 2009 13:21:24 +0200 Stephen Berman <stephen.berman@gmx.net> wrote:

> On Thu, 02 Jul 2009 10:56:09 +0200 Stephen Berman <stephen.berman@gmx.net> wrote:
>
>> On Fri, 26 Jun 2009 09:11:11 +0200 Stephen Berman <stephen.berman@gmx.net> wrote:
>>
>>> *Messages*.  But at startup there was again a pause when the echo area
>>> displayed the message "Cleaning up the recentf list...".  This time it
>>> lasted about 30 seconds, then startup completed and Emacs appears to be
>>> running normally.  However, the complete recentf message is "Cleaning up
>>> the recentf list...done (0 removed)", so I assume 30 seconds is too long
>>> and indicative of a problem.  With this emacs process running I started
>>> another Emacs with my initializations, including the same recentf file,
>>> and it came up without a pause.  Same thing with `emacs -Q --eval
>>> "(recentf-mode 1)"'.
>>
>> I continue to see this misbehavior, i.e. a ca. 30 stillstand while the
>> recentf list is being cleaned up, even with 0 files removed.  Today I
>> reproduced it with -Q -l test.el, the latter file consisting solely of
>> this:
>>
>> (custom-set-variables
>>  '(recentf-mode t))
>>
>> This was with my recentf file.  Again there was a ca. 30 second pause
>> (one file was removed).  I have not been able to reproduce the pause by
>> repeating this with a new emacs process but the same login session.
>> Does anyone have an idea what the problem could be, or a suggestion
>> about how to try and track it down?
>
> I've narrowed it down to the above sexp as the entire content of
> ~/.emacs and this ~/.recentf:
>
> ,----
> | ;;; Automatically generated by `recentf' on Fri Jul  3 12:53:43 2009.
> | 
> | (setq recentf-list
> |       '(
> |         "/ftp:anonymous@ftp.bla.org:/"
> |         ))
> | 
> | (setq recentf-filter-changer-current 'nil)
> | 
> | \f
> | ;; Local Variables:
> | ;; coding: utf-8-emacs
> | ;; End:
> `----
>
> The above ftp site is made up but it still resulted in a 30 second pause
> (I have real ftp sites in my normal recentf-file).  Again, this only
> happens with the first Emacs started in a given login session, and I've
> only been experiencing this since updating from the trunk after the 23.1
> branch was created.  That update included the new Tramp update and Tramp
> appears to be implicated by the above ftp line, though, as I already
> mentioned, adding (setq tramp-verbose 8) to ~/.emacs produces no Tramp
> debug buffer.

I have confirmed that while the problem occurs with my first post-branch
build, GNU Emacs 23.1.50.1 (i686-pc-linux-gnu, GTK+ Version 2.14.4) of
2009-06-23 on escher (and still with current build of 2009-06-30), it
does not occur with my last pre-branch build, GNU Emacs 23.0.94.2
(i686-pc-linux-gnu, GTK+ Version 2.14.4) of 2009-06-14 on escher.
Whatever causes the pause seems to leave a trace in resident memory that
prevents the pause, so testing requires a fresh login session.  Because
of this, unfortunately, I do not have time to revert from CVS to find
the problematic change.  Unless someone can suggest another way to
locate it, I'll just add this to the bugtracker and hope it gets fixed.

Steve Berman

Re: Recent recentf slowdown due to "/ftp:..."

[Michael Albinus]

Stephen Berman <stephen.berman@gmx.net> writes:

> I have confirmed that while the problem occurs with my first post-branch
> build, GNU Emacs 23.1.50.1 (i686-pc-linux-gnu, GTK+ Version 2.14.4) of
> 2009-06-23 on escher (and still with current build of 2009-06-30), it
> does not occur with my last pre-branch build, GNU Emacs 23.0.94.2
> (i686-pc-linux-gnu, GTK+ Version 2.14.4) of 2009-06-14 on escher.
> Whatever causes the pause seems to leave a trace in resident memory that
> prevents the pause, so testing requires a fresh login session.  Because
> of this, unfortunately, I do not have time to revert from CVS to find
> the problematic change.  Unless someone can suggest another way to
> locate it, I'll just add this to the bugtracker and hope it gets fixed.

I've tried to reproduce the problem exactly as you have described, it
doesn't happen to me.

What is the exact GNU/Linux distribution you are using? Which desktop
are you using (Gnome? KDE? Something different?) Is GVFS running after
your login? Is GVFS running after the first Emacs start, including the
pause?

I'm checking, whether the new tramp-gvfs.el package is involved.

> Steve Berman

Best regards, Michael.

Re: Recent recentf slowdown due to "/ftp:..."

[Stephen Berman]

On Sun, 05 Jul 2009 17:53:47 +0200 Michael Albinus <michael.albinus@gmx.de> wrote:

> Stephen Berman <stephen.berman@gmx.net> writes:
>
>> I have confirmed that while the problem occurs with my first post-branch
>> build, GNU Emacs 23.1.50.1 (i686-pc-linux-gnu, GTK+ Version 2.14.4) of
>> 2009-06-23 on escher (and still with current build of 2009-06-30), it
>> does not occur with my last pre-branch build, GNU Emacs 23.0.94.2
>> (i686-pc-linux-gnu, GTK+ Version 2.14.4) of 2009-06-14 on escher.
>> Whatever causes the pause seems to leave a trace in resident memory that
>> prevents the pause, so testing requires a fresh login session.  Because
>> of this, unfortunately, I do not have time to revert from CVS to find
>> the problematic change.  Unless someone can suggest another way to
>> locate it, I'll just add this to the bugtracker and hope it gets fixed.
>
> I've tried to reproduce the problem exactly as you have described, it
> doesn't happen to me.
>
> What is the exact GNU/Linux distribution you are using? 

openSUSE 11.1 (i586)
VERSION = 11.1

>                                                         Which desktop
> are you using (Gnome? KDE? Something different?) 

My regular desktop is KDE 4.2.4 (KDE 4.2.4) "release 2" and that's what
I was using in all my previous reports on this problem (in addition, I
use the gtk-qt engine from the rpm kcm_gtk-1.1-5.5).  This morning I
logged on to Gnome after booting the machine and ran my test case, and
here too I got the ~30s pause (actually closer to 27-8 seconds).  Then I
logged out of Gnome, logged on to KDE, ran my test case, and did not get
the pause.  Then I restarted the X server, logged on to KDE again, ran
my test case and still got no pause.  So I conclude that the pause only
happens with the first Emacs started after booting the machine.  (But I
have not yet tried my test case with -nw.)

>                                                  Is GVFS running after
> your login? Is GVFS running after the first Emacs start, including the
> pause?

Gnome both before and after starting Emacs (here with the pause):
steve@escher:~> ps -ef --cols 100 | grep gvfs | grep -v grep
steve     4553     1  0 09:01 ?        00:00:00 /usr/lib/gvfs/gvfsd
steve     4562     1  0 09:01 ?        00:00:00 /usr/lib/gvfs//gvfs-fuse-daemon /home/steve/.gvfs
steve     4736     1  0 09:02 ?        00:00:00 /usr/lib/gvfs/gvfs-hal-volume-monitor
steve     4739     1  0 09:02 ?        00:00:00 /usr/lib/gvfs/gvfs-gphoto2-volume-monitor
steve     4775     1  0 09:02 ?        00:00:00 /usr/lib/gvfs/gvfsd-trash --spawner :1.10 /org/gtk/g
steve     4814     1  0 09:02 ?        00:00:00 /usr/lib/gvfs/gvfsd-burn --spawner :1.10 /org/gtk/gv
s

KDE both before and after starting Emacs:
steve@escher:~> ps -ef --cols 100 | grep gvfs | grep -v grep
steve     5747     1  0 09:10 ?        00:00:00 /usr/lib/gvfs/gvfsd
steve     5756     1  0 09:10 ?        00:00:00 /usr/lib/gvfs//gvfs-fuse-daemon /home/steve/.gvfs

The directory  /home/steve/.gvfs is empty.

> I'm checking, whether the new tramp-gvfs.el package is involved.

Thanks.

Steve Berman

Re: Recent recentf slowdown due to "/ftp:..."

[Stephen Berman]

On Mon, 06 Jul 2009 10:06:38 +0200 Stephen Berman <stephen.berman@gmx.net> wrote:

> On Sun, 05 Jul 2009 17:53:47 +0200 Michael Albinus <michael.albinus@gmx.de> wrote:
[...]
>>                                                         Which desktop
>> are you using (Gnome? KDE? Something different?) 
>
> My regular desktop is KDE 4.2.4 (KDE 4.2.4) "release 2" and that's what
> I was using in all my previous reports on this problem (in addition, I
> use the gtk-qt engine from the rpm kcm_gtk-1.1-5.5).  This morning I
> logged on to Gnome after booting the machine and ran my test case, and
> here too I got the ~30s pause (actually closer to 27-8 seconds).  Then I
> logged out of Gnome, logged on to KDE, ran my test case, and did not get
> the pause.  Then I restarted the X server, logged on to KDE again, ran
> my test case and still got no pause.  So I conclude that the pause only
> happens with the first Emacs started after booting the machine.  (But I
> have not yet tried my test case with -nw.)

Today after booting the machine I logged on at a virtual tty instead of
starting an X desktop.  I ran my test and got no pause.  Then I logged
out, logged on to the desktop (KDE 4.2.4), ran my test and got the
pause.

>>                                                  Is GVFS running after
>> your login? Is GVFS running after the first Emacs start, including the
>> pause?

After the tty login GVFS was not running, but after the desktop login it was.

Steve Berman