LIST is slow for 35K mailboxes
Ian G Batten
ian.batten at uk.fujitsu.com
Tue Oct 9 11:12:33 EDT 2007
On 09 Oct 07, at 1550, Wesley Craig wrote:
> What's your authentication & authorization infrastructure look like?
sasl into yellow pages.
> Every mailbox has an associated ACL, which must be canonicalized to
> determine whether the user in question gets to see it.
> ctl_mboxlist just lists whatever it finds. I've seen Kerberos
> cause LIST * to take a long time -- and I have patches to fix the
> problem. Your high CPU load suggests a similar problem. Try
> sampling (Solaris: truss, dtrace?) a process that is spinning like
> this, to see what kinds of actions it's taking. In the case of
> Kerberos, the stock Cyrus distribution will repeatedly open the
> krb5.conf file once for each mailbox it examines, i.e., 35K times
> in your case.
Well, in system call terms it's just jumping up and down on mailboxes.db
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
write(1, " . j u n k s t u f f "\r".., 4096) = 4096
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
So it's not talking to the authentication infrastructure, as that
would require system calls.
But in userspace (thanks for the prod to make me look at this) it's a
lot messier, and looks like, as you say, it's doing a lot of
authentication stuff: assuming that the stat()s of mailboxes.db are
one per mailbox, and using truss -u to get the calls made by imapd
and by libsasl, we see the below. 35K in 243s is about 144/sec, so
it's not unreasonable that a lot of userspace calls are enough to
slow things down. So I can see where the time's going, but I'd
rather it came back...
ian
1: stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
/1 at 1: -> map_refresh(0x6, 0x0, 0x1f2304, 0x1f230c)
/1 at 1: -> bsearch_mem(0xffbfca38, 0x1, 0xfd580000,
0x25a510)
/1 at 1: -> find_p(0xffbfe208, 0xfd3beaec, 0x1b, 0xfd3beb08)
/1 at 1: -> glob_test(0x1f9560, 0xffbfdb2b, 0x18, 0xffbfdb24)
/1 at 1: -> cyrus_acl_myrights(0x1f94f8, 0x21c318,
0xffffffff, 0x0)
/1 at 1: -> auth_memberof(0x1f94f8, 0x21c318, 0x66ff6367,
0x80808080)
/1 at 1: -> auth_fromname(0x1f94f8, 0x21c318,
0xffffffff, 0x0)
/1 at 1: -> libcyrus_config_getstring(0xd, 0x21c318,
0x66ff6367, 0x80808080)
/1 at 1: -> mymemberof(0x1f94f8, 0x21c318, 0xffffffff, 0x0)
/1 at 1: -> cyrus_acl_strtomask(0x21c31c, 0x21c318,
0x66ff6367, 0x80808080)
/1 at 1: -> libcyrus_config_getstring(0x10, 0x21c326,
0xffffffff, 0x0)
/1 at 1: -> auth_memberof(0x1f94f8, 0x21c326, 0x696c66ff,
0x80808080)
/1 at 1: -> auth_fromname(0x1f94f8, 0x21c326,
0xffffffff, 0x0)
/1 at 1: -> libcyrus_config_getstring(0xd, 0x21c326,
0x696c66ff, 0x80808080)
/1 at 1: -> mymemberof(0x1f94f8, 0x21c326, 0xffffffff, 0x0)
/1 at 1: -> find_cb(0xffbfe208, 0xfd3beaec, 0x1b, 0xfd3beb08)
/1 at 1: -> glob_test(0x1f9560, 0xffbfdb2b, 0x18, 0xffbfdb24)
/1 at 1: -> listdata(0xffbfdb2b, 0x18, 0x1, 0xffbfe378)
/1 at 1: -> mstringdata(0x1b1ab8, 0xffbfdb2b, 0x18, 0x1)
/1 at 1: -> prot_printf(0x1f72e8, 0x1b19f8, 0x1b1ab8,
0x672e5365)
/1 at 1: -> prot_write(0x1f72e8, 0x1b19f8, 0x2,
0x80808080)
/1 at 1: -> prot_write(0x1f72e8, 0x1b1ab8, 0x4,
0x80808080)
/1 at 1: -> prot_write(0x1f72e8, 0x1b19fc, 0x2,
0x80808080)
/1 at 1: -> prot_printf(0x1f72e8, 0x1b1a78, 0x1aed00,
0x1b1a68)
/1 at 1: -> prot_write(0x1f72e8, 0x1b1a78, 0x0,
0x80808080)
/1 at 1: -> prot_write(0x1f72e8, 0x1aed00, 0x0,
0x80808080)
/1 at 1: -> prot_write(0x1f72e8, 0x1b1a7a, 0x0,
0x80808080)
/1 at 1: -> prot_write(0x1f72e8, 0x1b1a68, 0xe,
0x80808080)
/1 at 1: -> prot_write(0x1f72e8, 0x1b1a7c, 0x0,
0x80808080)
/1 at 1: -> prot_printf(0x1f72e8, 0x1b1a30, 0x2e,
0xffbfc998)
/1 at 1: -> prot_write(0x1f72e8, 0x1b1a30, 0x3,
0x80808080)
/1 at 1: -> prot_write(0x1f72e8, 0x1b1a35, 0x2,
0x80808080)
/1 at 1: -> mboxname_toexternal(0x1efe7c, 0x1dfb40,
0x1f02d0, 0xffbfca38)
/1 at 1: -> mboxname_hiersep_toexternal(0x1efe7c,
0xffbfca38, 0x0, 0x7300)
/1 at 1: -> printstring(0xffbfca38, 0x1dfb40, 0x1f02d0,
0xffbfca38)
/1 at 1: -> prot_printf(0x1f72e8, 0x1af2a0, 0xffbfca38,
0xffbfca38)
/1 at 1: -> prot_write(0x1f72e8, 0x1af2a0, 0x1,
0x80808080)
/1 at 1: -> prot_write(0x1f72e8, 0xffbfca38, 0x11,
0x80808080)
/1 at 1: -> prot_write(0x1f72e8, 0x1af2a3, 0x1,
0x80808080)
/1 at 1: -> prot_printf(0x1f72e8, 0x1af918, 0xffbfca38,
0xffbfc998)
/1 at 1: -> prot_write(0x1f72e8, 0x1af918, 0x2,
0x80808080)
/1 at 1: -> mboxname_tointernal(0x1efe7c, 0x1b0218,
0x1f02d0, 0xffbfca38)
/1 at 1: -> mboxname_hiersep_tointernal(0x1efe7c,
0xffbfca40, 0x0, 0x1f02d0)
/1 at 1: -> mboxlist_detail(0xffbfca38, 0xffbfca34, 0x0,
0x0)
/1 at 1: -> mboxlist_mylookup(0xffbfca38, 0xffbfca34,
0x0, 0x0)
/1 at 1: -> fetch(0x1f22f8, 0xffbfca38, 0x1b, 0xffbfc9b4)
/1 at 1: -> myfetch(0x1f22f8, 0xffbfca38, 0x1b,
0xffbfc9b4)
/1 at 1: -> starttxn_or_refetch(0x1f22f8, 0x0, 0x0,
0x0)
/1: stat("/var/imap/mailboxes.db", 0xFFBFC838) = 0
>
> :wes
>
> On 09 Oct 2007, at 09:19, Ian G Batten wrote:
>> WeBut at root I don't understand why LIST "" * should take any
>> longer than, for example, ctl_mboxlist -d.
More information about the Info-cyrus
mailing list