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

[Sébastien Vauban]

Hi Tassilo,

Tassilo Horn wrote:
> Sébastien Vauban <zthjwsqqafhv@spammotel.com> writes:
>> nnimap slow on checking huge mailboxes?
>> ... still having the same problem with No Gnus v0.9 under GNU Emacs
>> 23.0.60.1 (in Ubuntu 8.04) with the email server being Courier,
>> located on a 1 Gbps LAN connection.
>>
>> Checking for new mails takes a very, very long time, to the
>> contrary of what's being said ("Quickly checking...").
>
> 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).


> 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.

For privacy, I just replaced names of real boxes with XXX.

Here are the logs:

--8<---------------cut here---------------start------------->8---
======================================================================
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
--8<---------------cut here---------------end--------------->8---

Is it normal to see things like "possibly change server"?

The other log:

--8<---------------cut here---------------start------------->8---
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)
874 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
875 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
876 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
877 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
878 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
879 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
880 STATUS "INBOX.XXX-reviews" (UIDVALIDITY UIDNEXT UNSEEN)
881 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
882 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
883 STATUS "INBOX.XXX-reviews" (UIDVALIDITY UIDNEXT UNSEEN)
884 STATUS "INBOX.XXX-reviews" (UIDVALIDITY UIDNEXT UNSEEN)
885 STATUS "INBOX.XXX-diff" (UIDVALIDITY UIDNEXT UNSEEN)
886 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
887 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
888 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
889 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
890 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
891 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
892 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
893 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
894 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
895 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
896 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
897 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
898 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
899 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
900 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
901 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
902 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
903 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
904 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
905 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
906 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
907 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
908 STATUS "INBOX.XXX" (UIDVALIDITY UIDNEXT UNSEEN)
909 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 "shared.Spam-Reporting.Ham" (UIDNEXT 9 UIDVALIDITY 1093254153 UNSEEN 0)
872 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 2 UIDVALIDITY 1225118032 UNSEEN 0)
873 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 253 UIDVALIDITY 1097511066 UNSEEN 0)
874 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 38 UIDVALIDITY 1104755534 UNSEEN 0)
875 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 55 UIDVALIDITY 1227183521 UNSEEN 0)
876 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 1272 UIDVALIDITY 1134325372 UNSEEN 0)
877 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 1060 UIDVALIDITY 1184568864 UNSEEN 0)
878 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 90 UIDVALIDITY 1117187892 UNSEEN 0)
879 OK STATUS Completed.
* STATUS "INBOX.XXX-reviews" (UIDNEXT 667 UIDVALIDITY 1190360239 UNSEEN 0)
880 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 50 UIDVALIDITY 1129917154 UNSEEN 0)
881 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 161 UIDVALIDITY 1097510878 UNSEEN 0)
882 OK STATUS Completed.
* STATUS "INBOX.XXX-reviews" (UIDNEXT 847 UIDVALIDITY 1180964956 UNSEEN 0)
883 OK STATUS Completed.
* STATUS "INBOX.XXX-reviews" (UIDNEXT 6636 UIDVALIDITY 1164274297 UNSEEN 0)
884 OK STATUS Completed.
* STATUS "INBOX.XXX-diff" (UIDNEXT 3 UIDVALIDITY 1210086407 UNSEEN 0)
885 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 21695 UIDVALIDITY 1097250695 UNSEEN 4)
886 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 742 UIDVALIDITY 1116949962 UNSEEN 2)
887 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 2 UIDVALIDITY 1218638916 UNSEEN 0)
888 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 3214 UIDVALIDITY 1097510127 UNSEEN 25)
889 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 1953 UIDVALIDITY 1097509441 UNSEEN 1)
890 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 2982 UIDVALIDITY 1104746101 UNSEEN 15)
891 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 37 UIDVALIDITY 1197372522 UNSEEN 0)
892 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 279 UIDVALIDITY 1165315272 UNSEEN 0)
893 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 416 UIDVALIDITY 1178457748 UNSEEN 0)
894 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 90 UIDVALIDITY 1104755421 UNSEEN 0)
895 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 174 UIDVALIDITY 1111575845 UNSEEN 0)
896 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 840 UIDVALIDITY 1097510984 UNSEEN 0)
897 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 14 UIDVALIDITY 1097511557 UNSEEN 0)
898 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 1184 UIDVALIDITY 1097510396 UNSEEN 2)
899 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 32 UIDVALIDITY 1199783046 UNSEEN 0)
900 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 1909 UIDVALIDITY 1224152257 UNSEEN 0)
901 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 184 UIDVALIDITY 1117791683 UNSEEN 0)
902 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 3 UIDVALIDITY 1225118033 UNSEEN 0)
903 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 199 UIDVALIDITY 1093254203 UNSEEN 0)
904 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 36581 UIDVALIDITY 1093254201 UNSEEN 0)
905 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 1 UIDVALIDITY 1093254200 UNSEEN 0)
906 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 2195 UIDVALIDITY 1093254180 UNSEEN 0)
907 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 227 UIDVALIDITY 1093254164 UNSEEN 0)
908 OK STATUS Completed.
* STATUS "INBOX.XXX" (UIDNEXT 4 UIDVALIDITY 1093254162 UNSEEN 0)
909 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.
--8<---------------cut here---------------end--------------->8---

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).

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...

Any helping comment?

Best regards,
  Seb

-- 
Sébastien Vauban