RMAIL slows

["Robert J. Chassell" <bob@rattlesnake.com>]

Sunday's GNU Emacs CVS snapshot, Sun, 2005 Mar 13
GNU Emacs 22.0.50.22 (i686-pc-linux-gnu, GTK+ Version 2.6.2)

vrs

Friday's GNU Emacs CVS snapshot, Fri, 2005 Mar 18
GNU Emacs 22.0.50.26 (i686-pc-linux-gnu, GTK+ Version 2.6.2)

    both started with the same, long .emacs file

Deletion in RMAIL slows after an instance of GNU Emacs has been
running for several days.  The time to delete the same 50 messages,
all marked with `d', is double in the five day older instance than in
the newer instance.

This has been going on for months, but I have not been able to find
the bug.  That is why I have not reported this earlier.  I cannot find
anything wrong with Emacs!

There are no memory leaks that I can find and the backtraces are
nearly the same, being different only in addresses.

When deleting 50 messages, I found that in the older instance, each
call to `rmail-summary-goto-msg' takes nearly twice the Elapsed Time
as in the newer instance of Emacs,

Here are the five most frequently called functions from when I
instrumented `rmail-summary-' using `elp' and deleted 50 messages (the
same messages from the same RMAIL file each time):

older

Function Name                        Call Count  Elapsed Time  Average Time
===================================  ==========  ============  ============
rmail-summary-update-highlight       156         0.0032450000  2.080...e-05
rmail-summary-goto-msg               150         3.5518869999  0.0236792466
rmail-summary-exists                 51          0.0013599999  2.666...e-05
rmail-summary-displayed              50          0.0023839999  4.767...e-05
rmail-summary-mark-deleted           50          0.1103629999  0.00220726


younger
Function Name                        Call Count  Elapsed Time  Average Time
===================================  ==========  ============  ============
rmail-summary-update-highlight       166         0.0089219999  5.374...e-05
rmail-summary-goto-msg               153         1.9204319999  0.0125518431
rmail-summary-exists                 56          0.0013960000  2.492...e-05
rmail-summary-displayed              52          0.0021609999  4.155...e-05
rmail-summary-mark-deleted           50          0.0944409999  0.0018888199

The time sink is `rmail-summary-goto-msg'. 

I profiled one deletion on that function.  `rmail-summary-goto-msg'
continues as the time sink.  The function takes longer over time.

older
Function Name                        Call Count  Elapsed Time  Average Time
===================================  ==========  ============  ============
rmail-summary-goto-msg               6           0.057814      0.0096356666
rmail-summary-rmail-update           6           0.0381699999  0.0063616666
rmail-summary-undelete               1           0.016846      0.016846
rmail-summary-delete-forward         1           0.013405      0.013405


younger
Function Name                        Call Count  Elapsed Time  Average Time
===================================  ==========  ============  ============
rmail-summary-construct-io-menu      1           0.141289      0.141289
rmail-summary-rmail-update           8           0.0816259999  0.0102032499
rmail-summary-delete-forward         1           0.032636      0.032636
rmail-summary-goto-msg               4           0.0205899999  0.0051474999

Unfortunately, I am now lost.  On glancing at the source for
`rmail-summary-goto-msg' I don't see anything obviously wrong.  What
should I do next?

I normally do not run an instance of Emacs so long, since I like to
update and run new CVS versions.  But I will keep this older version
sitting on my desktop ready for any tests you might suggest.



Here is the backtrace for the older instance.  In both instances, I
went to the most recent message, # 247, then to the previous message,
then to the next (i.e., most recent message) again, then suspended the
instance and ran `bt'.

Program received signal SIGTSTP, Stopped (user).
0x407eee12 in select () from /lib/libc.so.6
(gdb) bt
#0  0x407eee12 in select () from /lib/libc.so.6
#1  0x00000007 in ?? ()
#2  0x00000000 in ?? ()
#3  0xbfffef20 in ?? ()
#4  0x081b2069 in wait_reading_process_output (time_limit=157, microsecs=0, 
    read_kbd=-1, do_display=1, wait_for_cell=137576249, wait_proc=0x0, 
    just_wait_proc=0) at process.c:4350
#5  0x0808a957 in sit_for (sec=157, usec=0, reading=1, display=1, 
    initial_display=0) at dispnew.c:6367
#6  0x081220d6 in read_char (commandflag=1, nmaps=4, maps=0xbffff19c, 
    prev_event=137576249, used_mouse_menu=0xbffff1d8) at keyboard.c:2769
#7  0x08128b64 in read_key_sequence (keybuf=0xbffff300, bufsize=30, 
    prompt=137576249, dont_downcase_last=0, can_return_switch_frame=1, 
    fix_current_buffer=1) at keyboard.c:8803
#8  0x0811f323 in command_loop_1 () at keyboard.c:1538
#9  0x081806fe in internal_condition_case (bfun=0x811f190 <command_loop_1>, 
    handlers=137637249, hfun=0x811ec80 <cmd_error>) at eval.c:1385
#10 0x0811efde in command_loop_2 () at keyboard.c:1319
#11 0x081801fb in internal_catch (tag=-514, func=0x811efb0 <command_loop_2>, 
    arg=137576249) at eval.c:1144
#12 0x0811ef83 in command_loop () at keyboard.c:1298
#13 0x0811e9e4 in recursive_edit_1 () at keyboard.c:991
#14 0x0811eb21 in Frecursive_edit () at keyboard.c:1052

Here is the backtrace of the first four stack frames of the newer
instance, just to show you its near identity with the backtrace of the
older instance.

Program received signal SIGTSTP, Stopped (user).
0x407eee12 in select () from /lib/libc.so.6
(gdb) bt
#0  0x407eee12 in select () from /lib/libc.so.6
#1  0x00000000 in ?? ()
#2  0x00000000 in ?? ()
#3  0xbfffef20 in ?? ()
#4  0x081b2239 in wait_reading_process_output (time_limit=157, microsecs=0, 
    read_kbd=-1, do_display=1, wait_for_cell=137573145, wait_proc=0x0, 
    just_wait_proc=0) at process.c:4350

As I said, I cannot find anything wrong with either instance of Emacs
except that RMAIL deletions in the older instance take longer and
longer.

-- 
    Robert J. Chassell                         
    bob@rattlesnake.com                         GnuPG Key ID: 004B4AC8
    http://www.rattlesnake.com                  http://www.teak.cc