Long wait for "Expiring Articles..."

Long wait for "Expiring Articles..."

[Jason L Tibbitts III]

Lately I've noticed the time taken to exit a group, when gnus shows
"Expiring Articles..." has been pretty long.  Even going into a group
with only a handful of articles, reading them and exiting can cause a
30+ second wait.  During this time, Emacs consumes 100% CPU while my
IMAP server is idle.

My desktop isn't particularly slow (i7-3770K, 32GB of RAM) so I'm not
sure what emacs could be doing for that long.  I'm just running the
versions that came with Fedora 20 (emacs 24.3, gnus 5.13).  My IMAP
server is Cyrus 2.3.16, in case that's missing some go-faster extension.

Has anyone seen this kind of thing?  Any hints on where I can start
looking for what's going on?

Thanks,

 - J<

Re: Long wait for "Expiring Articles..."

[Lars Ingebrigtsen]

"Jason L Tibbitts III" <tibbs@math.uh.edu> writes:

> Lately I've noticed the time taken to exit a group, when gnus shows
> "Expiring Articles..." has been pretty long.  Even going into a group
> with only a handful of articles, reading them and exiting can cause a
> 30+ second wait.  During this time, Emacs consumes 100% CPU while my
> IMAP server is idle.

`(setq nnimap-record-commands t)', and after you've seen this problem,
go to the *imap log* buffer and see what's there.  The commands are
timestamped, so it should give us an idea just what command is taking so
long.

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

Re: Long wait for "Expiring Articles..."

[Bjørn Mork]

Lars Ingebrigtsen <larsi@gnus.org> writes:
> "Jason L Tibbitts III" <tibbs@math.uh.edu> writes:
>
>> Lately I've noticed the time taken to exit a group, when gnus shows
>> "Expiring Articles..." has been pretty long.  Even going into a group
>> with only a handful of articles, reading them and exiting can cause a
>> 30+ second wait.  During this time, Emacs consumes 100% CPU while my
>> IMAP server is idle.
>
> `(setq nnimap-record-commands t)', and after you've seen this problem,
> go to the *imap log* buffer and see what's there.  The commands are
> timestamped, so it should give us an idea just what command is taking so
> long.

Was this patch from John Magorrian ever merged?:
http://article.gmane.org/gmane.emacs.gnus.general/80546

I've been using it for the last few years, and it is pretty essential if
you ever do expiry in an IMAP folder with high UIDs.


Bjørn

Re: Long wait for "Expiring Articles..."

[Lars Ingebrigtsen]

Bjørn Mork <bjorn@mork.no> writes:

> Was this patch from John Magorrian ever merged?:
> http://article.gmane.org/gmane.emacs.gnus.general/80546
>
> I've been using it for the last few years, and it is pretty essential if
> you ever do expiry in an IMAP folder with high UIDs.

Gnus tracks what articles exist now, so it shouldn't try to expire
articles that don't exist any more...

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

Re: Long wait for "Expiring Articles..."

[Jason L Tibbitts III]

>>>>> "LI" == Lars Ingebrigtsen <larsi@gnus.org> writes:

LI> `(setq nnimap-record-commands t)', and after you've seen this
LI> problem, go to the *imap log* buffer and see what's there.

Well, I went into a pretty high-traffic group (which was fully caught
up), entered the group (asked for just one article when prompted),
exited without reading anything, then immediately went to my ding
folder.  Note the 50 second pause with no imap activity.  Emacs is
running full out during this time, and there doesn't appear to be
anything happening on the IMAP server.

16:54:45 [imap.math.uh.edu] 132446 SELECT "fedora-package-review"
16:54:45 [imap.math.uh.edu] 132447 UID FETCH 260829 (UID RFC822.SIZE BODYSTRUCTURE BODY.PEEK[HEADER.FIELDS (Subject From Date Message-Id References In-Reply-To Xref To Newsgroups Cc)])
16:54:46 [imap.math.uh.edu] 132448 UID SEARCH SENTBEFORE 01-FEB-2014
16:55:37 [imap.math.uh.edu] 132449 SELECT "ding"
16:55:37 [imap.math.uh.edu] 132450 UID FETCH 17530 (UID RFC822.SIZE BODYSTRUCTURE BODY.PEEK[HEADER.FIELDS (Subject From Date Message-Id References In-Reply-To Xref To Newsgroups Cc)])

Does that give any hints?

 - J<

Re: Long wait for "Expiring Articles..."

[Bjørn Mork]

Lars Ingebrigtsen <larsi@gnus.org> writes:
> Bjørn Mork <bjorn@mork.no> writes:
>
>> Was this patch from John Magorrian ever merged?:
>> http://article.gmane.org/gmane.emacs.gnus.general/80546
>>
>> I've been using it for the last few years, and it is pretty essential if
>> you ever do expiry in an IMAP folder with high UIDs.
>
> Gnus tracks what articles exist now, so it shouldn't try to expire
> articles that don't exist any more...

Ah, right.  I believe I got that explanation before. Should have
remembered...


Bjørn

Re: Long wait for "Expiring Articles..."

[Jason L Tibbitts III]

Decided to check how to profile elisp and instrumented the gnus package,
but the results don't seem particularly useful.  Here's the top ten functions:

The only function called more than a few times was gnus-remove-if at 307
times, but with a call time down in the noise.

gnus-summary-exit                                                             1           45.138563005  45.138563005
gnus-run-hooks                                                                8           45.091998884  5.6364998605
gnus-summary-expire-articles                                                  1           45.0919888    45.0919888
gnus-list-of-read-articles                                                    1           0.255410847   0.255410847
gnus-uncompress-range                                                         1           0.213805775   0.213805775
gnus-score-save                                                               1           0.043802103   0.043802103
gnus-list-range-difference                                                    2           0.04156259    0.020781295
gnus-write-buffer                                                             1           0.040823595   0.040823595
gnus-request-expire-articles                                                  1           0.017794266   0.017794266
gnus-prin1                                                                    1           0.002680406   0.002680406

Digging into my .gnus, I found this:

;(remove-hook 'gnus-summary-prepare-exit-hook 'gnus-summary-expire-articles)

Now, my .gnus really does date back from before the time Larsi started
working on it, so any memories of why I would have previously tried to
keep that function from being called are long gone.  But I eval'ed that
piece of code and group exiting is fast now.

So, what am I missing by doing this?  Is there a better way to handle
expiring read articles from my mail folders?  Or is there more I can do
to debug just why this is taking so long?  I used to actually know how
to do things in emacs but that, too, has been long forgotten.

 - J<

Re: Long wait for "Expiring Articles..."

[Jason L Tibbitts III]

And, to continue talking to myself, I learned about the debugger and
stepped into gnus-request-expire-articles.  Turns out this just gets
called with a nice big list containing the positive integers from 1 to
260000 or so.  Which explains why it takes so long to run.  Doesn't
explain why Gnus seems to not be keeping track of, or asking the server
for, the actual number of articles in the group which according to
previous discussion it's supposed to do.

And with that, I'm out of ideas but if anyone has any hints I'll do my
best to keep digging.

 - J<

Re: Long wait for "Expiring Articles..."

[Lars Ingebrigtsen]

"Jason L Tibbitts III" <tibbs@math.uh.edu> writes:

> And, to continue talking to myself, I learned about the debugger and
> stepped into gnus-request-expire-articles.  Turns out this just gets
> called with a nice big list containing the positive integers from 1 to
> 260000 or so.  Which explains why it takes so long to run.  Doesn't
> explain why Gnus seems to not be keeping track of, or asking the server
> for, the actual number of articles in the group which according to
> previous discussion it's supposed to do.

It sounds like the expiry function hasn't been made aware of the
"unexist" tracking.  I'll have a look.

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

Re: Long wait for "Expiring Articles..."

[Lars Ingebrigtsen]

"Jason L Tibbitts III" <tibbs@math.uh.edu> writes:

> And, to continue talking to myself, I learned about the debugger and
> stepped into gnus-request-expire-articles.  Turns out this just gets
> called with a nice big list containing the positive integers from 1 to
> 260000 or so.  Which explains why it takes so long to run.  Doesn't
> explain why Gnus seems to not be keeping track of, or asking the server
> for, the actual number of articles in the group which according to
> previous discussion it's supposed to do.

Hm; looking at the code I see that it tries to do unexist handling, so
it "should work".  >"?

If you step through `gnus-summary-expire-articles', what are the values
of `gnus-newsgroup-unexist', and what does `expirable' end up being here?

    (let* ((total (gnus-group-total-expirable-p gnus-newsgroup-name))
	   (expirable
	    (gnus-list-range-difference
	     (if total
		 (progn
		   ;; We need to update the info for
		   ;; this group for `gnus-list-of-read-articles'
		   ;; to give us the right answer.
		   (gnus-run-hooks 'gnus-exit-group-hook)
		   (gnus-summary-update-info)
		   (gnus-list-of-read-articles gnus-newsgroup-name))
	       (setq gnus-newsgroup-expirable
		     (sort gnus-newsgroup-expirable '<)))
	     gnus-newsgroup-unexist))
	   (expiry-wait (if now 'immediate
			  (gnus-group-find-parameter
			   gnus-newsgroup-name 'expiry-wait)))
	   (nnmail-expiry-target
	    (or (gnus-group-find-parameter gnus-newsgroup-name 'expiry-target)
		nnmail-expiry-target))
	   es)
-->   (when expirable


-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

Re: Long wait for "Expiring Articles..."

[Jason L Tibbitts III]

>>>>> "LI" == Lars Ingebrigtsen <larsi@gnus.org> writes:

LI> Hm; looking at the code I see that it tries to do unexist handling,
LI> so it "should work".  >"?

Well, the code that you include below is not the same as the code I
have.  I don't even have gnus-newsgroup-unexist there, so I'm guessing
that v5.13 simply doesn't have the necessary magic and everything is
basically working as expected given that there's no unexist handling.

expirable in that context just has (1 2 3 4 5 ...); (length expirable)
is 261091.  So, yeah.

Anyway, I guess I need to move to something newer.  Time to explore git
gnus.  Haven't tracked the development version since, well, sometime
last century.

 - J<

Re: Long wait for "Expiring Articles..."

[Jason L Tibbitts III]

And, yeah, I pulled the latest git and set things up to use that,
removed the bit of code to delete gnus-summary-expire-articles from
gnus-summary-prepare-exit-hook and tested things out; everything seems
to go nice and fast now.

So, thanks for the help, and sorry for wasting everyone's time.

 - J<

Re: Long wait for "Expiring Articles..."

[Lars Ingebrigtsen]

"Jason L Tibbitts III" <tibbs@math.uh.edu> writes:

> And, yeah, I pulled the latest git and set things up to use that,
> removed the bit of code to delete gnus-summary-expire-articles from
> gnus-summary-prepare-exit-hook and tested things out; everything seems
> to go nice and fast now.
>
> So, thanks for the help, and sorry for wasting everyone's time.

It's our (i.e., my) fault for not bumping the version number in Emacs
proper (it's been 5.13 for yonks).  It'll happen after Ma Gnus is
released, which should be this spring...

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/