We're having a problem where deletion of a user by the admin is taking
about 30 seconds. I've attached an abreviated truss of the imapd while
this is taking place. It shows a long string of:
18679: stat("/mail/vmb1/var/mailboxes.db", 0xFFBEEA68) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEEAE0) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEE9C8) = 0
18679: fstat(5, 0xFFBEEAF0) = 0
This is with 2.1.9, --with-mboxlist-db=skiplist --enable-fulldirhash.
Anyone have any suggestions on what might be wrong, or where to look next?
mailboxes.db is a bit under 2MB, and contains around 10k entries (as
counted by "ctl_mboxlist -d | wc -l").
The truss output with more context:
18679: poll(0xFFBEEEE8, 1, 1800000) (sleeping...)
18679: poll(0xFFBEEEE8, 1, 1800000) = 1
18679: time() = 1057743572
18679: read(0, " 2 d e l e t e u s e".., 4096) = 36
18679: fcntl(5, F_SETLKW, 0xFFBEE920) = 0
18679: fstat(5, 0xFFBEEA48) = 0
18679: stat("/mail/vmb1/var/mailboxes.db", 0xFFBEE9C0) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEEA38) = 0
18679: open("/mail/vmb1/spool/A/user/test9772__foo_net_au/cyrus.header", O_RDWR) = 9
18679: fstat(9, 0xFFBEDAD8) = 0
18679: mmap(0x00000000, 203, PROT_READ, MAP_SHARED, 9, 0) = 0xFEFF0000
18679: fcntl(9, F_SETLKW, 0xFFBEDA30) = 0
18679: fstat(9, 0xFFBEDAD8) = 0
18679: stat("/mail/vmb1/spool/A/user/test9772__foo_net_au/cyrus.header", 0xFFBED9A8)
= 0
18679: open("/mail/vmb1/spool/A/user/test9772__foo_net_au/cyrus.index", O_RDWR) = 10
18679: fstat(10, 0xFFBED9D8) = 0
18679: mmap(0x00000000, 16384, PROT_READ, MAP_SHARED, 10, 0) = 0xFED70000
18679: open("/mail/vmb1/spool/A/user/test9772__foo_net_au/cyrus.cache", O_RDWR) = 11
18679: fstat(11, 0xFFBEDAD8) = 0
18679: mmap(0x00000000, 16384, PROT_READ, MAP_SHARED, 11, 0) = 0xFED60000
18679: fstat(10, 0xFFBED9D8) = 0
18679: fcntl(10, F_SETLKW, 0xFFBED9B8) = 0
18679: fstat(10, 0xFFBEDAD8) = 0
18679: stat("/mail/vmb1/spool/A/user/test9772__foo_net_au/cyrus.index", 0xFFBEDA50) = 0
18679: fstat(10, 0xFFBED958) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEE9C0) = 0
18679: fstat(5, 0xFFBEEA68) = 0
18679: stat("/mail/vmb1/var/mailboxes.db", 0xFFBEE938) = 0
18679: lseek(5, 987556, SEEK_SET) = 987556
18679: write(5, "\00F1214", 4) = 4
18679: lseek(5, 1959640, SEEK_SET) = 1959640
18679: write(5, "\0\0\004\00F11AC", 8) = 8
18679: fdsync(5, O_RDONLY|O_DSYNC) = 0
18679: lseek(5, 1959648, SEEK_SET) = 1959648
18679: write(5, "\0\0\0FF", 4) = 4
18679: fdsync(5, O_RDONLY|O_DSYNC) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEEAC0) = 0
18679: open("/mail/vmb1/var/quota/A/user.test9772__foo_net_au", O_RDWR) = 12
18679: fcntl(12, F_SETLKW, 0xFFBECA38) = 0
18679: fstat(12, 0xFFBECAD8) = 0
18679: stat("/mail/vmb1/var/quota/A/user.test9772__foo_net_au", 0xFFBEC9B0) = 0
18679: fstat(12, 0xFFBEB958) = 0
18679: mmap(0x00000000, 10, PROT_READ, MAP_SHARED, 12, 0) = 0xFED50000
18679: munmap(0xFED50000, 10) = 0
18679: open("/mail/vmb1/var/quota/A/user.test9772__foo_net_au.NEW",
O_RDWR|O_CREAT|O_TRUNC, 0666) = 13
18679: fcntl(13, F_SETLKW, 0xFFBEB6C8) = 0
18679: write(13, " 0\n 2 0 0 0 0\n", 8) = 8
18679: fdsync(13, O_RDONLY|O_SYNC) = 0
18679: rename("/mail/vmb1/var/quota/A/user.test9772__foo_net_au.NEW",
"/mail/vmb1/var/quota/A/user.test9772__foo_net_au") = 0
18679: close(12) = 0
18679: fcntl(13, F_SETLKW, 0xFFBEDB38) = 0
18679: open64("/mail/vmb1/spool/A/user/test9772__foo_net_au", O_RDONLY|O_NDELAY) = 12
18679: fcntl(12, F_SETFD, 0x00000001) = 0
18679: fstat64(12, 0xFFBEDAD8) = 0
18679: getdents64(12, 0x0014A288, 1048) = 168
18679: unlink("/mail/vmb1/spool/A/user/test9772__foo_net_au/cyrus.header") = 0
18679: unlink("/mail/vmb1/spool/A/user/test9772__foo_net_au/cyrus.index") = 0
18679: unlink("/mail/vmb1/spool/A/user/test9772__foo_net_au/cyrus.cache") = 0
18679: unlink("/mail/vmb1/spool/A/user/test9772__foo_net_au/1.") = 0
18679: getdents64(12, 0x0014A288, 1048) = 32
18679: unlink("/mail/vmb1/spool/A/user/test9772__foo_net_au/.nfs0DA") = 0
18679: getdents64(12, 0x0014A288, 1048) = 0
18679: close(12) = 0
18679: rmdir("/mail/vmb1/spool/A/user/test9772__foo_net_au") Err#17 EEXIST
18679: close(9) = 0
18679: munmap(0xFEFF0000, 203) = 0
18679: close(10) = 0
18679: munmap(0xFED70000, 16384) = 0
18679: close(11) = 0
18679: munmap(0xFED60000, 16384) = 0
18679: close(13) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEEA48) = 0
18679: fstat(5, 0xFFBEEB70) = 0
18679: stat("/mail/vmb1/var/mailboxes.db", 0xFFBEEAE8) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEEB60) = 0
18679: unlink("/mail/vmb1/var/user/A/test9772__foo_net_au.seen") Err#2 ENOENT
18679: fstat(8, 0xFFBEEBE8) = 0
18679: time() = 1057743572
18679: getpid() = 18679 [7702]
18679: putmsg(8, 0xFFBEE2A0, 0xFFBEE294, 0) = 0
18679: open("/var/run/syslog_door", O_RDONLY) = 9
18679: door_info(9, 0xFFBEE1D8) = 0
18679: getpid() = 18679 [7702]
18679: door_call(9, 0xFFBEE1C0) = 0
18679: close(9) = 0
18679: unlink("/mail/vmb1/var/user/A/test9772__foo_net_au.sub") Err#2 ENOENT
18679: open64("/mail/vmb1/var/quota/A/", O_RDONLY|O_NDELAY) = 9
18679: fcntl(9, F_SETFD, 0x00000001) = 0
18679: fstat64(9, 0xFFBEEBB8) = 0
18679: getdents64(9, 0x0014A288, 1048) = 960
18679: getdents64(9, 0x0014A288, 1048) = 960
18679: getdents64(9, 0x0014A288, 1048) = 960
18679: getdents64(9, 0x0014A288, 1048) = 960
18679: getdents64(9, 0x0014A288, 1048) = 928
18679: unlink("/mail/vmb1/var/quota/A/user.test9772__foo_net_au") = 0
18679: getdents64(9, 0x0014A288, 1048) = 1016
18679: getdents64(9, 0x0014A288, 1048) = 976
18679: getdents64(9, 0x0014A288, 1048) = 976
18679: getdents64(9, 0x0014A288, 1048) = 968
18679: getdents64(9, 0x0014A288, 1048) = 976
18679: getdents64(9, 0x0014A288, 1048) = 992
18679: getdents64(9, 0x0014A288, 1048) = 984
18679: getdents64(9, 0x0014A288, 1048) = 960
18679: getdents64(9, 0x0014A288, 1048) = 992
18679: getdents64(9, 0x0014A288, 1048) = 984
18679: getdents64(9, 0x0014A288, 1048) = 952
18679: getdents64(9, 0x0014A288, 1048) = 968
18679: getdents64(9, 0x0014A288, 1048) = 976
18679: getdents64(9, 0x0014A288, 1048) = 984
18679: getdents64(9, 0x0014A288, 1048) = 960
18679: getdents64(9, 0x0014A288, 1048) = 968
18679: getdents64(9, 0x0014A288, 1048) = 1008
18679: getdents64(9, 0x0014A288, 1048) = 984
18679: getdents64(9, 0x0014A288, 1048) = 952
18679: getdents64(9, 0x0014A288, 1048) = 960
18679: getdents64(9, 0x0014A288, 1048) = 992
18679: getdents64(9, 0x0014A288, 1048) = 984
18679: getdents64(9, 0x0014A288, 1048) = 1000
18679: getdents64(9, 0x0014A288, 1048) = 968
18679: getdents64(9, 0x0014A288, 1048) = 376
18679: getdents64(9, 0x0014A288, 1048) = 0
18679: close(9) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEE9C8) = 0
18679: fstat(5, 0xFFBEEAF0) = 0
18679: stat("/mail/vmb1/var/mailboxes.db", 0xFFBEEA68) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEEAE0) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEE9C8) = 0
18679: fstat(5, 0xFFBEEAF0) = 0
18679: stat("/mail/vmb1/var/mailboxes.db", 0xFFBEEA68) = 0
[...last 4 lines repeated about 10k times, then...]
18679: fcntl(5, F_SETLKW, 0xFFBEEAE0) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEE9C8) = 0
18679: fstat(5, 0xFFBEEAF0) = 0
18679: stat("/mail/vmb1/var/mailboxes.db", 0xFFBEEA68) = 0
18679: fcntl(5, F_SETLKW, 0xFFBEEAE0) = 0
18679: open64("/mail/vmb1/var/sieve/t/test9772__foo_net_au", O_RDONLY|O_NDELAY) Err#2
ENOENT
18679: poll(0xFFBEEEE8, 1, 0) = 0
18679: write(1, " 2 O K C o m p l e t".., 16) = 16
18679: time() = 1057743623
18679: poll(0xFFBEEEE8, 1, 1800000) (sleeping...)
--
Andrew McNamara, Senior Developer, Object Craft
http://www.object-craft.com.au/
