Re: Gnus hangs after "Quickly checking mailbox INBOX" for way too long

[Tassilo Horn]

Sébastien Vauban <zthjwsqqafhv@spammotel.com>
writes:

Hi Sébastien,

>> I run a local dovecot imap server here, and even with my big
>> emacs-devel group (16.000+ messages) checking for new messages
>> finishes instantly.
>
> What a dream... Really.
>
>> Are you sure that the slowness comes from Gnus and not Courier? Maybe
>> test with another client.
>
> Tests from clients like Outlook or Thunderbird don't show such a
> slowness (20 seconds or more).

Hm, ok.

>> If the problem is Gnus, then set imap-debug, imap-log, and
>> nnimap-debug to t and look in the log/debug buffers what Gnus is
>> doing all the time.
>
> Good thing to do, yes.
>
> I did not see anything really special in it, but I've never seen debug
> logs from other Gnus systems either.

I've seen logs, but I cannot really make use with them.

> For privacy, I just replaced names of real boxes with XXX.
>
> Here are the logs:
>
> ======================================================================
> 1 -> nnimap-server-opened: server="mc"
> 1 <- nnimap-server-opened: t
> ======================================================================
> 1 -> nnimap-request-scan: group=nil server="mc"
> | 2 -> nnimap-split-articles: group=nil server="mc"
> | | 3 -> nnimap-possibly-change-server: server="mc"
> | | 3 <- nnimap-possibly-change-server: " *nnimap* mc"
> | | 3 -> nnimap-split-find-inbox: server="mc"
> | | 3 <- nnimap-split-find-inbox: ("INBOX")
> | | 3 -> nnimap-possibly-change-group: group="INBOX" server=nil
> | | | 4 -> nnimap-possibly-change-server: server=nil
> | | | 4 <- nnimap-possibly-change-server: " *nnimap* mc"
> | | | 4 -> nnimap-verify-uidvalidity: group="INBOX" server="mc"
> | | | 4 <- nnimap-verify-uidvalidity: t
> | | 3 <- nnimap-possibly-change-group: "INBOX"
> | | 3 -> nnimap-split-find-rule: server="mc" inbox="INBOX"
> | | 3 <- nnimap-split-find-rule: bbdb/gnus-split-method
> | 2 <- nnimap-split-articles: t
> 1 <- nnimap-request-scan: t
> ======================================================================
> 1 -> nnimap-server-opened: server="mc"
> 1 <- nnimap-server-opened: t
> ======================================================================
> 1 -> nnimap-retrieve-groups: groups=("shared.Spam-Reporting.Spam" 
> "shared.Spam-Reporting.Ham" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" 
> "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX-reviews" "INBOX.XXX" 
> "INBOX.XXX" "INBOX.XXX-reviews" "INBOX.XXX-reviews" "INBOX.XXX-diff" 
> "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" 
> "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" 
> "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" 
> "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" "INBOX.XXX" 
> "INBOX.XXX" "INBOX") server="mc"
> | 2 -> nnimap-possibly-change-server: server="mc"
> | 2 <- nnimap-possibly-change-server: " *nnimap* mc"
> | 2 -> nnimap-before-find-minmax-bugworkaround: 
> | 2 <- nnimap-before-find-minmax-bugworkaround: t
> | 2 -> nnimap-find-minmax-uid: group="INBOX" examine=examine
> | 2 <- nnimap-find-minmax-uid: (1459 78 91896)
> 1 <- nnimap-retrieve-groups: active
>
> Is it normal to see things like "possibly change server"?

Yes, I have pretty similar output, also with the "possibly change
server".

> The other log:
>
> 865 NOOP
> 865 OK NOOP completed
> 866 SELECT "INBOX"
> * FLAGS ($MDNSent gnus-forward NonJunk $Forwarded \Draft \Answered \Flagged 
> \Deleted \Seen \Recent)
> * OK [PERMANENTFLAGS ($MDNSent gnus-forward NonJunk $Forwarded \* \Draft 
> \Answered \Flagged \Deleted \Seen)] Limited
> * 1457 EXISTS
> * 0 RECENT
> * OK [UIDVALIDITY 1092655824] Ok
> * OK [MYRIGHTS "acdilrsw"] ACL
> 866 OK [READ-WRITE] Ok
> 867 UID SEARCH UNSEEN UNDELETED
> * SEARCH
> 867 OK SEARCH done.
> 868 EXPUNGE
> 868 OK EXPUNGE completed
> 869 CLOSE
> 869 OK mailbox closed.
> 870 NOOP
> 870 OK NOOP completed
> 871 STATUS "shared.Spam-Reporting.Spam" (UIDVALIDITY UIDNEXT UNSEEN)
> 872 STATUS "shared.Spam-Reporting.Ham" (UIDVALIDITY UIDNEXT UNSEEN)
> 873 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)

[...]

> 910 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
> 911 STATUS "INBOX" (UIDVALIDITY UIDNEXT UNSEEN)
> * STATUS "shared.Spam-Reporting.Spam" (UIDNEXT 7647 UIDVALIDITY 1093254155 
> UNSEEN 0)
> 871 OK STATUS Completed.

[...]

> * STATUS "INBOX.XXX" (UIDNEXT 191 UIDVALIDITY 1093254159 UNSEEN 0)
> 910 OK STATUS Completed.
> * STATUS "INBOX" (UIDNEXT 91897 UIDVALIDITY 1092655824 UNSEEN 2)
> 911 OK STATUS Completed.
> 912 EXAMINE "INBOX"
> * FLAGS ($MDNSent gnus-forward NonJunk $Forwarded \Draft \Answered \Flagged 
> \Deleted \Seen \Recent)
> * OK [PERMANENTFLAGS ()] No permanent flags permitted
> * 1459 EXISTS
> * 2 RECENT
> * OK [UIDVALIDITY 1092655824] Ok
> * OK [MYRIGHTS "acdilrsw"] ACL
> 912 OK [READ-ONLY] Ok
> 913 FETCH 1,* UID
> * 1 FETCH (UID 78)
> * 1459 FETCH (UID 91896)
> 913 OK FETCH completed.
> 914 STATUS "INBOX" (UIDNEXT)
> * STATUS "INBOX" (UIDNEXT 91897)
> 914 OK STATUS Completed.

This also looks pretty similar to what's logged here.

> When sniffing with wireshark, I see that each interaction between
> request and response takes a couple of 100 ms up to 6 seconds when
> it's querying the status of INBOX.work (which contains ~ 20,000
> mails).

That's pretty strange.  Especially, why do you the other clients you've
tried not suffer from that big latency?  Maybe they use some caching and
do time consuming queries in a separate thread, so that you don't notice
it.

> 40 times such a query explains why it takes in total something like 20
> seconds to complete the "refresh"... But it's still bad for me...

Sure.

> Any helping comment?

I'd recommend to ask on ding.  There're the IMAP experts.

Else I can only advertise my setup: I run a local dovecot IMAP server
and use offlineIMAP (via cron) to sync the messages from my 2 remote
IMAP accounts (private and work) with dovecot.  This works very nice,
the setup is quite easy and then access to your mail is super-fast.

Bye,
Tassilo