Performance problem of imap move

Performance problem of imap move

[Mickaël Rémond]

Hello,

I am currently trying to trouble shoot performance problem of the nnimap
move methods. It takes more than 30 seconds here to move a mail (I am
using Gmail) on imap on the same server.

imap server is a secondary server.

Here is the result of elp instrument:
gnus-summary-move-article                                                     2           72.684064     36.342032
gnus-activate-group                                                           2           62.887769     31.4438845
gnus-group-get-new-news-this-group                                            1           62.887473     62.887473
gnus-group-completing-read                                                    2           8.951666      4.475833
gnus-completing-read                                                          2           8.9514789999  4.4757394999
gnus-emacs-completing-read                                                    2           8.951453      4.4757265
gnus-read-move-group-name                                                     2           4.755247      2.3776235
gnus-y-or-n-p                                                                 1           4.516911      4.516911
gnus-request-set-mark                                                         2           3.040978      1.520489
gnus-request-move-article                                                     1           1.9702929999  1.9702929999

Any idea what I should do to pinpoint the issue ?

Thanks !

-- 
Mickaël Rémond

Re: Performance problem of imap move

[Mickaël Rémond]

Hello,

On  6 Jan 2015, mremond@process-one.net wrote:

> Hello,
>
> I am currently trying to troubleshoot performance problems of the
> nnimap move methods. It takes more than 30 seconds here to move a mail
> (I am using Gmail) on imap on the same server.

I did more investigations enabling IMAP command logs.
I think the issue is that the last command done during a move is a fetch
of all FLAGS:

   474 UID FETCH 1:* FLAGS

I am not sure why this command is performed, but that mailbox has 250k
emails in it, so that may explain why the move is so slow.

Is it risky to remove that FLAGS download ?

-- 
Mickaël Rémond
 http://www.process-one.net/

Re: Performance problem of imap move

[Lars Ingebrigtsen]

mremond@process-one.net (Mickaël Rémond) writes:

> I did more investigations enabling IMAP command logs.
> I think the issue is that the last command done during a move is a fetch
> of all FLAGS:
>
>    474 UID FETCH 1:* FLAGS

Geez.  That's the result of a not very thought through calling
sequence.  It's calling `gnus-group-get-new-news-this-group' to update
the line of the group we've moved the message to, and that function is
also used for `M-g' to make nnimap completely rescan the group.

There doesn't seem to be any way in nnimap to get the new article count
for a single group without doing a total rescan of the group, and that
is, as you've found out, really slow.

This will have to be refactored a bit, and a new nnimap function will
have to be written, I think...

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

Re: Performance problem of imap move

[Lars Ingebrigtsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> This will have to be refactored a bit, and a new nnimap function will
> have to be written, I think...

I've now done this, so moving IMAP messages to large groups should be
faster again.

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

Re: Performance problem of imap move

[Tassilo Horn]

Lars Ingebrigtsen <larsi@gnus.org> writes:

>> This will have to be refactored a bit, and a new nnimap function will
>> have to be written, I think...
>
> I've now done this, so moving IMAP messages to large groups should be
> faster again.

I don't know if that's a side-effect of this change but with today's
Gnus version I sometimes get group lines like

    38289: nnimap+Server:some.group

where actually there are no unread articles in the group.  `M-g' on the
group or another `g' fixes the unread count again.

I also don't have a reproducible recipe but it seems to happen
sporadically with random nnimap groups.  Not sure what I did before.
Possibly, it happens when some.group is either my sent-mail or SPAM
group, and previously I've sent a new mail or exited some other group
where I've marked some messages as SPAM which are moved to my SPAM group
as a result...

Bye,
Tassilo

Re: Performance problem of imap move

[Steinar Bang]

>>>>> Tassilo Horn <tsdh@gnu.org>:

> where actually there are no unread articles in the group.  `M-g' on the
> group or another `g' fixes the unread count again.

M-g does "UID FETCH 1:* FLAGS", which I guess is what Lars have
removed...?  So maybe he removed one too many...?

Re: Performance problem of imap move

[Lars Ingebrigtsen]

Tassilo Horn <tsdh@gnu.org> writes:

> I don't know if that's a side-effect of this change but with today's
> Gnus version I sometimes get group lines like
>
>     38289: nnimap+Server:some.group

This is when just `g'-ing in the group buffer?  The changes I made
yesterday shouldn't affect that at all.   

> I also don't have a reproducible recipe but it seems to happen
> sporadically with random nnimap groups.  Not sure what I did before.
> Possibly, it happens when some.group is either my sent-mail or SPAM
> group, and previously I've sent a new mail or exited some other group
> where I've marked some messages as SPAM which are moved to my SPAM group
> as a result...

If you could find a pattern where this happens, that would be nice.  The
changes introduced yesterday does change what happens when you copy
articles to an nnimap group, either by Gcc-ing articles to it or
whatnot, so that does sound like a likely scenario...

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

Re: Performance problem of imap move

[Tassilo Horn]

Lars Ingebrigtsen <larsi@gnus.org> writes:

>> I don't know if that's a side-effect of this change but with today's
>> Gnus version I sometimes get group lines like
>>
>>     38289: nnimap+Server:some.group
>
> This is when just `g'-ing in the group buffer?  The changes I made
> yesterday shouldn't affect that at all.   
>
>> I also don't have a reproducible recipe but it seems to happen
>> sporadically with random nnimap groups.  Not sure what I did before.
>> Possibly, it happens when some.group is either my sent-mail or SPAM
>> group, and previously I've sent a new mail or exited some other group
>> where I've marked some messages as SPAM which are moved to my SPAM
>> group as a result...
>
> If you could find a pattern where this happens, that would be nice.

Found one.  I'm in nnimap+Server:some.group and write a reply to a mail
in there.  My posting styles for that group include (gcc-self . t), so a
copy of the sent reply is added to the group.  After exiting some.group,
the unread count is as shown above.

Bye,
Tassilo

Re: Performance problem of imap move

[Tassilo Horn]

Tassilo Horn <tsdh@gnu.org> writes:

>> If you could find a pattern where this happens, that would be nice.
>
> Found one.  I'm in nnimap+Server:some.group and write a reply to a
> mail in there.  My posting styles for that group include (gcc-self
> . t), so a copy of the sent reply is added to the group.  After
> exiting some.group, the unread count is as shown above.

And in another.group the gcc-self is set to that server's sent-mail
group, and when I write a message in there and exit, the sent-mail group
has the wrong unread count.

So maybe the right thing would be to do the "fast copy/move" for all
messages but the last one where you do the "full ceremony" as before?

Bye,
Tassilo

Re: Performance problem of imap move

[Lars Ingebrigtsen]

Tassilo Horn <tsdh@gnu.org> writes:

> Found one.  I'm in nnimap+Server:some.group and write a reply to a mail
> in there.  My posting styles for that group include (gcc-self . t), so a
> copy of the sent reply is added to the group.  After exiting some.group,
> the unread count is as shown above.

I've now tried this, and I'm not seeing this problem.  But the article
count isn't updating, either, so something isn't working the way it
should.

I Gcc'd to the Test group, and my *imap log* buffer says:

18:26:59 [hermes.netfonds.no] 2741 SELECT "Test".
18:27:00 [hermes.netfonds.no] 2742 APPEND "Test" {422}.
18:27:00 [hermes.netfonds.no] 2743 EXAMINE "Test" (QRESYNC (1286911992 20)).

Which is the right thing, I think.  What does yours say?

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

Re: Performance problem of imap move

[Tassilo Horn]

Lars Ingebrigtsen <larsi@gnus.org> writes:

>> Found one.  I'm in nnimap+Server:some.group and write a reply to a
>> mail in there.  My posting styles for that group include (gcc-self
>> . t), so a copy of the sent reply is added to the group.  After
>> exiting some.group, the unread count is as shown above.
>
> I've now tried this, and I'm not seeing this problem.

It seems that the problem doesn't always occur but it does at least most
of the time here.

> But the article count isn't updating, either, so something isn't
> working the way it should.
>
> I Gcc'd to the Test group, and my *imap log* buffer says:
>
> 18:26:59 [hermes.netfonds.no] 2741 SELECT "Test".
> 18:27:00 [hermes.netfonds.no] 2742 APPEND "Test" {422}.
> 18:27:00 [hermes.netfonds.no] 2743 EXAMINE "Test" (QRESYNC (1286911992 20)).
>
> Which is the right thing, I think.  What does yours say?

I'm testing now with this very mail which is gcc-ed to my
"nnimap+Fastmail:INBOX.Sent Items" group and to my local
nnml+archive:sent-mails group.  I'll report back in a minute.

Bye,
Tassilo

Re: Performance problem of imap move

[Tassilo Horn]

Tassilo Horn <tsdh@gnu.org> writes:

>> But the article count isn't updating, either, so something isn't
>> working the way it should.
>>
>> I Gcc'd to the Test group, and my *imap log* buffer says:
>>
>> 18:26:59 [hermes.netfonds.no] 2741 SELECT "Test".
>> 18:27:00 [hermes.netfonds.no] 2742 APPEND "Test" {422}.
>> 18:27:00 [hermes.netfonds.no] 2743 EXAMINE "Test" (QRESYNC (1286911992 20)).
>>
>> Which is the right thing, I think.  What does yours say?
>
> I'm testing now with this very mail which is gcc-ed to my
> "nnimap+Fastmail:INBOX.Sent Items" group and to my local
> nnml+archive:sent-mails group.  I'll report back in a minute.

That's what I got:

09:01:32 [mail.messagingengine.com] 1429 SELECT "INBOX.Sent Items"
09:01:32 [mail.messagingengine.com] 1430 APPEND "INBOX.Sent Items" {1953}
09:01:32 [mail.messagingengine.com] 1431 EXAMINE "INBOX.Sent Items" (QRESYNC (1103381936 206930))
09:01:32 [mail.messagingengine.com] 1432 SELECT "INBOX.Sent Items"
09:01:32 [mail.messagingengine.com] 1433 UID STORE 1:2385 +FLAGS.SILENT (\Seen)

And now after exiting the summary, my group line shows

  19739: nnimap+Fastmail:INBOX.mailinglists.ding

where 2 or 3 is actually the right unread count.  And this time, `g' or
`M-g' don't fix the unread count anymore.  I think the only difference
between this time and previous times where `g'/`M-g' fixed the problem
is that this time I exited the group with `q' and still two or three
articles were unread.  Before, I always caught up with `c' to exist the
group so the unread cound was zero.

Bye,
Tassilo

Re: Performance problem of imap move

[Lars Ingebrigtsen]

Tassilo Horn <tsdh@gnu.org> writes:

>>> 18:26:59 [hermes.netfonds.no] 2741 SELECT "Test".
>>> 18:27:00 [hermes.netfonds.no] 2742 APPEND "Test" {422}.
>>> 18:27:00 [hermes.netfonds.no] 2743 EXAMINE "Test" (QRESYNC (1286911992 20)).

[...]

> 09:01:32 [mail.messagingengine.com] 1429 SELECT "INBOX.Sent Items"
> 09:01:32 [mail.messagingengine.com] 1430 APPEND "INBOX.Sent Items" {1953}
> 09:01:32 [mail.messagingengine.com] 1431 EXAMINE "INBOX.Sent Items" (QRESYNC (1103381936 206930))

So that's basically the same as what happens in my group...

> 09:01:32 [mail.messagingengine.com] 1432 SELECT "INBOX.Sent Items"
> 09:01:32 [mail.messagingengine.com] 1433 UID STORE 1:2385 +FLAGS.SILENT (\Seen)

But that's odd.  It's marking articles 1 to 2385 as seen?  I would have
expected it to mark at most one article...

> And now after exiting the summary, my group line shows
>
>   19739: nnimap+Fastmail:INBOX.mailinglists.ding
>
> where 2 or 3 is actually the right unread count.  And this time, `g' or
> `M-g' don't fix the unread count anymore.

That is even weirder.  `M-g' is supposed to do a complete rescan, making
Gnus reflect the state of the messages on the IMAP server totally.

This is very odd.

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

Re: Performance problem of imap move

[Eric Abrahamsen]

Tassilo Horn <tsdh@gnu.org> writes:

> Lars Ingebrigtsen <larsi@gnus.org> writes:
>
>>> This will have to be refactored a bit, and a new nnimap function will
>>> have to be written, I think...
>>
>> I've now done this, so moving IMAP messages to large groups should be
>> faster again.
>
> I don't know if that's a side-effect of this change but with today's
> Gnus version I sometimes get group lines like
>
>     38289: nnimap+Server:some.group
>
> where actually there are no unread articles in the group.  `M-g' on the
> group or another `g' fixes the unread count again.
>
> I also don't have a reproducible recipe but it seems to happen
> sporadically with random nnimap groups.  Not sure what I did before.
> Possibly, it happens when some.group is either my sent-mail or SPAM
> group, and previously I've sent a new mail or exited some other group
> where I've marked some messages as SPAM which are moved to my SPAM group
> as a result...
>
> Bye,
> Tassilo

I see something like this (and have for a very long time, this isn't
new) when moving messages between nnimap groups. When I open an imap
group containing new messages, and decide that one of the
(newly-received but now marked "read") messages belongs in a different
group on the same server, I move it to that group, return to the *Group*
buffer, and see that the group I moved the message to now has an
(apparently random) unread count. Hitting "g" or actually entering the
group makes the unread count go away -- the messages aren't actually
marked as unread.

Might be unrelated, though: as I said, it's done this (fairly
reproducibly) for a long time.

Re: Performance problem of imap move

[Lars Ingebrigtsen]

Eric Abrahamsen <eric@ericabrahamsen.net> writes:

> Might be unrelated, though: as I said, it's done this (fairly
> reproducibly) for a long time.

Huh.  Hm.  Perhaps it depends on what IMAP server is being used?  What
server are you seeing this on?

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

Re: Performance problem of imap move

[Eric Abrahamsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Eric Abrahamsen <eric@ericabrahamsen.net> writes:
>
>> Might be unrelated, though: as I said, it's done this (fairly
>> reproducibly) for a long time.
>
> Huh.  Hm.  Perhaps it depends on what IMAP server is being used?  What
> server are you seeing this on?

A local dovecot server, synced with gmail via isync.

I've always meant to go and follow the code, but it's never been
annoying enough for me to actually do it. But if you're messing nnimap
at the moment anyway, maybe now's a good time.

Re: Performance problem of imap move

[Lars Ingebrigtsen]

Eric Abrahamsen <eric@ericabrahamsen.net> writes:

> A local dovecot server, synced with gmail via isync.

Ah.  For some reason, it seems that people running local IMAP servers
triggers a lot of bugs in Gnus...

> I've always meant to go and follow the code, but it's never been
> annoying enough for me to actually do it. But if you're messing nnimap
> at the moment anyway, maybe now's a good time.

Please do.  :-)

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

Re: Performance problem of imap move

[Steinar Bang]

>>>>> Lars Ingebrigtsen <larsi@gnus.org>:

> Ah.  For some reason, it seems that people running local IMAP servers
> triggers a lot of bugs in Gnus...

Timing-related...?

Re: Performance problem of imap move

[Dave Goldberg]

It appears that the change associated with this thread has caused a problem for me at work.  After doing a git pull and recompiling (as usual) I noticed some strangeness with some of the groups on our office365 set up.  I use a group line format of

 %S%p%P%(%G [(%y new,%T !,%I ?)/~%t]%)

A number of groups, though not all, initially showed up with all the article counts showing as a '*'.  Running M-g on the group resulted in an error that I regret not recording.  I then ran M-c to clear data and M-g again and the article counts showed as ridiculously high and Emacs hung long enough when trying to enter the group that Gnome offered to kill it off for lack of response.  I ran git bisect and it determined that this

447c56af7cb2afac14a0f3ed23f85d907c443a5d is the first bad commit
commit 447c56af7cb2afac14a0f3ed23f85d907c443a5d
Author: Lars Ingebrigtsen <larsi@gnus.org>
Date:   Mon Jan 26 13:50:20 2015 +1100

    Make moving IMAP articles faster in large groups
    
    * lisp/gnus-group.el (gnus-group-get-new-news-this-group): Explicitly
    request rescans when being run interactively.
    
    * lisp/gnus-int.el (gnus-request-group-scan): New backend function.
    
    * lisp/nnimap.el (nnimap-request-scan-group): Implement in on IMAP.
    
    * lisp/nnimap.el (nnimap-request-group): Don't rescan the group here,
    because that can be very slow in large groups.

:040000 040000 3164108231527becdb471bfe74ce22bdd3bc5b4f
d424a0d925e35e71fc30863580e2ca949559505e M lisp

While many of the affected groups don't really matter much to me (they mostly represent archives) a couple of them regularly receive messages either as a result of server side splitting or article moves so I'm currently running a detached checkout on the last working commit.  I am happy to take some time to try to help debug this but I need some guidance on what to do and what to look for.  I've stepped through the lisp debugger in the past but I wouldn't even know where to begin in this case.  In particular if I need to look at what's going on IMAP-wise I don't know how to do that.

Thanks,
-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: Performance problem of imap move

[Dave Goldberg]

> It appears that the change associated with this thread has caused a problem
>  for me at work.  After doing a git pull and recompiling (as usual) I
>  noticed some strangeness with some of the groups on our office365 set up.
>   I use a group line format of
>
>  %S%p%P%(%G [(%y new,%T !,%I ?)/~%t]%)
>
> A number of groups, though not all, initially showed up with all the article counts showing as a '*'.  Running M-g on the group resulted in an error that I regret not recording.  I then ran M-c to clear data and M-g again and the article counts showed as ridiculously high and Emacs hung long enough when trying to enter the group that Gnome offered to kill it off for lack of response.  I ran git bisect and it determined that this
>
> 447c56af7cb2afac14a0f3ed23f85d907c443a5d is the first bad commit
> commit 447c56af7cb2afac14a0f3ed23f85d907c443a5d
> Author: Lars Ingebrigtsen <larsi@gnus.org>
> Date:   Mon Jan 26 13:50:20 2015 +1100
>
>     Make moving IMAP articles faster in large groups
>     
>     * lisp/gnus-group.el (gnus-group-get-new-news-this-group): Explicitly
>     request rescans when being run interactively.
>     
>     * lisp/gnus-int.el (gnus-request-group-scan): New backend function.
>     
>     * lisp/nnimap.el (nnimap-request-scan-group): Implement in on IMAP.
>     
>     * lisp/nnimap.el (nnimap-request-group): Don't rescan the group here,
>     because that can be very slow in large groups.
>
> :040000 040000 3164108231527becdb471bfe74ce22bdd3bc5b4f
> d424a0d925e35e71fc30863580e2ca949559505e M lisp
 [...]

The latest checkout seems to have resolved the problem.

Thanks,
-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: Performance problem of imap move

[Eric Abrahamsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Eric Abrahamsen <eric@ericabrahamsen.net> writes:
>
>> A local dovecot server, synced with gmail via isync.
>
> Ah.  For some reason, it seems that people running local IMAP servers
> triggers a lot of bugs in Gnus...
>
>> I've always meant to go and follow the code, but it's never been
>> annoying enough for me to actually do it. But if you're messing nnimap
>> at the moment anyway, maybe now's a good time.
>
> Please do.  :-)

Doing this bit by bit, first of all here are the imap commands resulting
from moving article 39339 from INBOX to [Gmail].Trash, where it became
article 175. Upon leaving the INBOX group, [Gmail].Trash was marked as
containing 36 unread articles, when in fact it had none -- refreshing
Gnus reset the unread count to the proper value. Stepping through
`gnus-summary-move-article' and `nnimap-request-move-article' didn't
show anything immediately out of the ordinary, but I don't really
understand imap all that well.

In a bit, I'll try it again and step through `nnimap-request-set-mark'.
That's what's being used to update marks on [Gmail].Trash, and seems
like the next most likely place to find bugs. Like I said, though, I
don't know imap all that well, so someone tell me if I should be looking
elsewhere.

10:03:59 [localhost] 128 NOOP
10:03:59 [localhost] 129 NOOP
10:03:59 [localhost] 130 NOOP
10:03:59 [localhost] 131 NOOP
10:03:59 [localhost] 132 NOOP
10:07:19 [localhost] 133 SELECT "INBOX"
10:07:19 [localhost] 134 UID STORE 39339 FLAGS.SILENT (\Seen)
10:07:19 [localhost] 135 UID STORE 39339 -FLAGS.SILENT (\Flagged \Answered gnus-expire gnus-dormant gnus-score gnus-save gnus-download gnus-forward)
10:11:30 [localhost] 136 SELECT "INBOX"
10:11:30 [localhost] 137 UID FETCH 39339 (UID RFC822.SIZE BODYSTRUCTURE BODY.PEEK[HEADER.FIELDS (Subject From Date Message-Id References In-Reply-To Xref To Newsgroups Cc)])
10:12:02 [localhost] 138 UID COPY 39339 "[Gmail].Trash"
10:12:24 [localhost] 139 UID STORE 39339 +FLAGS.SILENT (\Deleted)
10:12:24 [localhost] 140 UID EXPUNGE 39339
10:18:59 [localhost] 141 NOOP
10:18:59 [localhost] 142 NOOP
10:18:59 [localhost] 143 NOOP
10:18:59 [localhost] 144 NOOP
10:18:59 [localhost] 145 NOOP
10:19:18 [localhost] 146 SELECT "[Gmail].Trash"
10:19:18 [localhost] 147 UID STORE 175 +FLAGS.SILENT (\Seen)
10:20:30 [localhost] 148 EXAMINE "[Gmail].Trash" (QRESYNC (1410345743 155))
10:20:43 [localhost] 149 SELECT "INBOX"
10:20:43 [localhost] 150 UID SEARCH SENTBEFORE 21-JAN-2015
10:20:46 [localhost] 151 SELECT "INBOX"
10:20:46 [localhost] 152 UID STORE 39339 +FLAGS.SILENT (\Seen)

Re: Performance problem of imap move

[Eric Abrahamsen]

Eric Abrahamsen <eric@ericabrahamsen.net> writes:

> Lars Ingebrigtsen <larsi@gnus.org> writes:
>
>> Eric Abrahamsen <eric@ericabrahamsen.net> writes:
>>
>>> A local dovecot server, synced with gmail via isync.
>>
>> Ah.  For some reason, it seems that people running local IMAP servers
>> triggers a lot of bugs in Gnus...
>>
>>> I've always meant to go and follow the code, but it's never been
>>> annoying enough for me to actually do it. But if you're messing nnimap
>>> at the moment anyway, maybe now's a good time.
>>
>> Please do.  :-)
>
> Doing this bit by bit, first of all here are the imap commands resulting
> from moving article 39339 from INBOX to [Gmail].Trash, where it became
> article 175. Upon leaving the INBOX group, [Gmail].Trash was marked as
> containing 36 unread articles, when in fact it had none -- refreshing
> Gnus reset the unread count to the proper value. Stepping through
> `gnus-summary-move-article' and `nnimap-request-move-article' didn't
> show anything immediately out of the ordinary, but I don't really
> understand imap all that well.
>
> In a bit, I'll try it again and step through `nnimap-request-set-mark'.
> That's what's being used to update marks on [Gmail].Trash, and seems
> like the next most likely place to find bugs. Like I said, though, I
> don't know imap all that well, so someone tell me if I should be looking
> elsewhere.

A little progress: `nnimap-request-set-mark' also looked normal, so I
followed the `gnus-group-get-new-news-this-group' call at the end of
`gnus-summary-move-article' instead.

In the `let' in the middle of that (gnus-group.el:4081 in current Gnus),
we call both `gnus-get-info' and `gnus-active' on the "group" variable.
The return value of `gnus-get-info' indicates a "seen" range of (1 .
177), which is correct. The return value of `gnus-active' is (1 . 211),
which isn't correct, and leads to the bogus unread count.

Off to look at what's happening in `gnus-active'...

E

Re: Performance problem of imap move

[Eric Abrahamsen]

Eric Abrahamsen <eric@ericabrahamsen.net> writes:

> Eric Abrahamsen <eric@ericabrahamsen.net> writes:
>
>> Lars Ingebrigtsen <larsi@gnus.org> writes:
>>
>>> Eric Abrahamsen <eric@ericabrahamsen.net> writes:
>>>
>>>> A local dovecot server, synced with gmail via isync.
>>>
>>> Ah.  For some reason, it seems that people running local IMAP servers
>>> triggers a lot of bugs in Gnus...
>>>
>>>> I've always meant to go and follow the code, but it's never been
>>>> annoying enough for me to actually do it. But if you're messing nnimap
>>>> at the moment anyway, maybe now's a good time.
>>>
>>> Please do.  :-)
>>
>> Doing this bit by bit, first of all here are the imap commands resulting
>> from moving article 39339 from INBOX to [Gmail].Trash, where it became
>> article 175. Upon leaving the INBOX group, [Gmail].Trash was marked as
>> containing 36 unread articles, when in fact it had none -- refreshing
>> Gnus reset the unread count to the proper value. Stepping through
>> `gnus-summary-move-article' and `nnimap-request-move-article' didn't
>> show anything immediately out of the ordinary, but I don't really
>> understand imap all that well.
>>
>> In a bit, I'll try it again and step through `nnimap-request-set-mark'.
>> That's what's being used to update marks on [Gmail].Trash, and seems
>> like the next most likely place to find bugs. Like I said, though, I
>> don't know imap all that well, so someone tell me if I should be looking
>> elsewhere.
>
> A little progress: `nnimap-request-set-mark' also looked normal, so I
> followed the `gnus-group-get-new-news-this-group' call at the end of
> `gnus-summary-move-article' instead.
>
> In the `let' in the middle of that (gnus-group.el:4081 in current Gnus),
> we call both `gnus-get-info' and `gnus-active' on the "group" variable.
> The return value of `gnus-get-info' indicates a "seen" range of (1 .
> 177), which is correct. The return value of `gnus-active' is (1 . 211),
> which isn't correct, and leads to the bogus unread count.
>
> Off to look at what's happening in `gnus-active'...

Ugh, it looks at gnus-active-hashtb. I think this is where I pass the
baton to someone else.

Re: Performance problem of imap move

[Eric Abrahamsen]

Eric Abrahamsen <eric@ericabrahamsen.net> writes:

> Eric Abrahamsen <eric@ericabrahamsen.net> writes:
>
>> Eric Abrahamsen <eric@ericabrahamsen.net> writes:
>>
>>> Lars Ingebrigtsen <larsi@gnus.org> writes:
>>>
>>>> Eric Abrahamsen <eric@ericabrahamsen.net> writes:
>>>>
>>>>> A local dovecot server, synced with gmail via isync.
>>>>
>>>> Ah.  For some reason, it seems that people running local IMAP servers
>>>> triggers a lot of bugs in Gnus...
>>>>
>>>>> I've always meant to go and follow the code, but it's never been
>>>>> annoying enough for me to actually do it. But if you're messing nnimap
>>>>> at the moment anyway, maybe now's a good time.
>>>>
>>>> Please do.  :-)
>>>
>>> Doing this bit by bit, first of all here are the imap commands resulting
>>> from moving article 39339 from INBOX to [Gmail].Trash, where it became
>>> article 175. Upon leaving the INBOX group, [Gmail].Trash was marked as
>>> containing 36 unread articles, when in fact it had none -- refreshing
>>> Gnus reset the unread count to the proper value. Stepping through
>>> `gnus-summary-move-article' and `nnimap-request-move-article' didn't
>>> show anything immediately out of the ordinary, but I don't really
>>> understand imap all that well.
>>>
>>> In a bit, I'll try it again and step through `nnimap-request-set-mark'.
>>> That's what's being used to update marks on [Gmail].Trash, and seems
>>> like the next most likely place to find bugs. Like I said, though, I
>>> don't know imap all that well, so someone tell me if I should be looking
>>> elsewhere.
>>
>> A little progress: `nnimap-request-set-mark' also looked normal, so I
>> followed the `gnus-group-get-new-news-this-group' call at the end of
>> `gnus-summary-move-article' instead.
>>
>> In the `let' in the middle of that (gnus-group.el:4081 in current Gnus),
>> we call both `gnus-get-info' and `gnus-active' on the "group" variable.
>> The return value of `gnus-get-info' indicates a "seen" range of (1 .
>> 177), which is correct. The return value of `gnus-active' is (1 . 211),
>> which isn't correct, and leads to the bogus unread count.
>>
>> Off to look at what's happening in `gnus-active'...
>
> Ugh, it looks at gnus-active-hashtb. I think this is where I pass the
> baton to someone else.

Because this is driving me nuts...

I'm able to consistently reproduce the following:

1. (gnus-active "nnimap+PR:[Gmail].Trash") --> (1 . 178) ; correct
2. Move article into Trash
3. (gnus-active "nnimap+PR:[Gmail].Trash") --> (1 . 211) ; wrong
4. Update Gnus, or just the Trash group
5. (gnus-active "nnimap+PR:[Gmail].Trash") --> (1 . 179) ; correct

Guess what's weird! It looks like, in my current session, moving any
article into any group causes `gnus-active' to return (1 . 211) for that
group.

If the group has fewer than that many messages, that manifests as an
immediate unread count, representing the difference.

If the group has more than 211 messages, nothing immediately happens,
but the next time I refresh Gnus the group suddenly has a *whole lot*
more unread messages, and they are actually unread -- I can go into the
group and see them marked as unread.

I just experimented with a different group. Its correct active count was
(1 . 609). I moved a message into it -- didn't see anything funny. Next
time I refreshed Gnus it was marked as containing 399 unread messages,
and `gnus-active' returned the dreaded (1 . 211). When I entered the
group, it asked how many messages I wanted to see, default 403. I hit
return, and the summary buffer contained 399 unread messages. Some of
those messages I had previously ticked, but now they appeared completely
bare. I caught up and exited with "c", and the group went back to
normal. Next time I entered the group, all the old marks (ticks, etc)
were properly restored.

So: gremlins. 211 of them. Next time I restart Gnus I'll try this again,
and see if I get a new magic number. Back to work for now...

E

Re: Performance problem of imap move

[Lars Ingebrigtsen]

Eric Abrahamsen <eric@ericabrahamsen.net> writes:

> 3. (gnus-active "nnimap+PR:[Gmail].Trash") --> (1 . 211) ; wrong

211 is a very suspicious number, because it's the hard-coded return code
on every line.  Like here:

	(insert (format "211 %d %d %d %S\n"
			(- (cdr active) (car active))
			(car active)
			(cdr active)
			group))

Eurhm.  Is that statement being interpreted as something else?

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

Re: Performance problem of imap move

[Lars Ingebrigtsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> 211 is a very suspicious number, because it's the hard-coded return code
> on every line.  Like here:

There was a missing `erase-buffer' there.  Oops.  Can you check whether
the fix I just pushed fixes this?

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

Re: Performance problem of imap move

[Eric Abrahamsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Lars Ingebrigtsen <larsi@gnus.org> writes:
>
>> 211 is a very suspicious number, because it's the hard-coded return code
>> on every line.  Like here:
>
> There was a missing `erase-buffer' there.  Oops.  Can you check whether
> the fix I just pushed fixes this?

Looking good! Thanks *very* much for getting this. I'll let you know if
anything else goes wonky, but so far it seems okay.

Re: Performance problem of imap move

[Tassilo Horn]

Lars Ingebrigtsen <larsi@gnus.org> writes:

>> 211 is a very suspicious number, because it's the hard-coded return
>> code on every line.  Like here:
>
> There was a missing `erase-buffer' there.  Oops.  Can you check
> whether the fix I just pushed fixes this?

Is it possible that this commit also fixed the "broken unread count
after imap move/copy" issue I've had?  At least it didn't happen to me
today.

Bye,
Tassilo

Re: Performance problem of imap move

[Lars Ingebrigtsen]

Tassilo Horn <tsdh@gnu.org> writes:

> Lars Ingebrigtsen <larsi@gnus.org> writes:
>
>>> 211 is a very suspicious number, because it's the hard-coded return
>>> code on every line.  Like here:
>>
>> There was a missing `erase-buffer' there.  Oops.  Can you check
>> whether the fix I just pushed fixes this?
>
> Is it possible that this commit also fixed the "broken unread count
> after imap move/copy" issue I've had?  At least it didn't happen to me
> today.

Yes, it's quite possible.

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