Dan Price
2007-Feb-14 22:24 UTC
[Dovecot] severe performance problem (mail cache related?)
Hi all, we're having a bad day with email :)
I have a user who was complaining of poor performance today when
opening mailboxes. Total time to open the box was about 1 minute.
Upon truss'ing the imap process during an open, I saw the trace quoted
below at the end of the email.
As you can see, for each "FETCH" line of response, we were seeing
dovecot do a ton of work-- mmaping anon, lots of munmaps(), etc. --
mmap() and munmap() are not free.
The stack trace of at least one of the munmaps is captured below,
as well-- deep inside of the mail caching code.
Then, I moved aside the user's .imap directory, assuming that forcing
dovecot to rebuild its indices and caches could help-- and sure enough
the user reported that mailbox open times had dropped to 18 seconds. I
truss'd that open, briefly, and it was just a ton of preads at high
speed.
So I don't know why this user was fine for a week, then suddenly hit this.
This is a grave concern if I'm going to roll this out from 15 test users
to 250 production users. Thanks for your help.
PS: Raw logs are also attached below.
-dp
write(1, " * 1 0 7 9 5 F E T C".., 2050) = 2050
mmap64(0x00000000, 7356416, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANON, -1, 0) =
0xFD800000
munmap(0xFE602000, 1048576) = 0
munmap(0xFE502000, 1048576) = 0
munmap(0xFE402000, 1048576) = 0
munmap(0xFE302000, 1048576) = 0
munmap(0xFE202000, 1048576) = 0
munmap(0xFE102000, 1048576) = 0
munmap(0xFE002000, 1048576) = 0
munmap(0xFE000000, 8192) = 0
pread64(9, " n c o m @ o s s 1 >\n\0".., 8192, 7340032) = 8192
mmap64(0x00000000, 7364608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANON, -1, 0) =
0xFE800000
munmap(0xFDE04000, 1048576) = 0
munmap(0xFDD04000, 1048576) = 0
munmap(0xFDC04000, 1048576) = 0
munmap(0xFDB04000, 1048576) = 0
munmap(0xFDA04000, 1048576) = 0
munmap(0xFD904000, 1048576) = 0
munmap(0xFD804000, 1048576) = 0
munmap(0xFD802000, 8192) = 0
munmap(0xFD800000, 8192) = 0
pread64(9, " l @ p l a t i n u m >\n".., 8192, 7348224) = 8192
mmap64(0x00000000, 7372800, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANON, -1, 0) =
0xFE000000
munmap(0xFEE06000, 1048576) = 0
munmap(0xFED06000, 1048576) = 0
munmap(0xFEC06000, 1048576) = 0
munmap(0xFEB06000, 1048576) = 0
munmap(0xFEA06000, 1048576) = 0
munmap(0xFE906000, 1048576) = 0
munmap(0xFE806000, 1048576) = 0
munmap(0xFE802000, 16384) = 0
munmap(0xFE800000, 8192) = 0
pread64(9, "\0\0\0 0\0\0\0\0 C c : ".., 8192, 7356416) = 8192
---------- ---------- ---------- ---------- ---------- ---------- ----------
ff1c3e14 munmap (100000, bdc000, fe6de000, 2dc000, 0, 1ef0) + 8
00080bb4 file_cache_set_size (c03a0, 0, bdc110, 408, 0, 110) + e0
00080cec file_cache_read (0, bdbd08, bdbd08, 408, 0, 684a8) + a4
000594a0 mail_cache_map (191268, bdbd08, 408, ffbff274, 3, fffffffc) + ec
0005ae20 mail_cache_get_record (0, bdbd08, ffbff274, ffbff274, 0, 0) + 20
0005b00c mail_cache_foreach_rec (1959c8, ffbff2ec, 5b3d8, 0, b5760, 7ed8) + 10
0005b2bc mail_cache_foreach (1, 47ae, 5b3d8, 0, 0, 0) + b4
0005b47c mail_cache_field_exists (0, 47ae, 0, c0000000, b4f10, 88184) + 84
0005b64c mail_cache_lookup_field (1959c8, b5898, 47ae, 0, 191d48, 195560) + c
000531ac index_mail_get_fixed_field (195dd8, 0, 195ea0, 4, ffffffff, ffffffff) +
4c
000545e8 index_mail_set_seq (195dd8, 47ae, 19a1c8, b4b4f, 0, 47ae) + bc
00070dac mail_set_seq (195dd8, 47ae, 1, c2ce8, 0, 39c) + c
0005770c index_storage_search_next (1, 195dd8, 1, bd778, 5769c, c8ae0) + 70
00072024 mailbox_search_next (19a1c8, 195dd8, 3, 2, 0, c2b50) + 14
0002b3bc imap_fetch (c4e20, c4de8, ffbff748, 5, c2eb0, 80000000) + 6c
00026210 cmd_fetch (1, c2e88, 0, 75696400, 26054, 80000000) + 1bc
00029000 cmd_uid (0, c22f8, 0, 8, 2a134, c22f8) + 8c
00029b58 client_handle_input (c2b94, c2e80, b5760, bd778, 7ef8, 2000000) + 138
00029ad0 client_handle_input (0, 2f05e860, b5760, bd778, 45d3834d, b5000) + b0
00029cb0 _client_input (c2b50, c2b50, 26ee, 0, 1, 0) + 68
00086338 io_loop_handler_run (c0348, 0, 0, ffbffa14, 4c, 80000000) + 140
00085c14 io_loop_run (c0348, ff212cb0, 1, b573c, bae80, ff215dbc) + 34
00032064 main (ffbffc18, b4400, b5000, b573c, c1314, ff3a0180) + 3f8
00024b18 _start (0, 0, 0, 0, 0, 0) + 5c
------ ------ ------ ------ ------ ------ ------ ------ ------ ------
[in]
3 select "Mail/OpenSolaris/discuss"
4 UID fetch 1:* (FLAGS)
5 IDLE
DONE
6 close
7 logout
------ ------ ------ ------ ------ ------ ------ ------ ------ ------
[out, taking 1+ minutes]
* OK [RAWLOG TIMESTAMP] 2007-02-14 14:05:35
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft NonJunk $Forwarded Junk)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft NonJunk
$Forwarded Junk \*)] Flags permitted.
* 20462 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1159980013] UIDs valid
* OK [UIDNEXT 20487] Predicted next UID
3 OK [READ-WRITE] Select completed.
* 1 FETCH (FLAGS (\Seen) UID 1)
* 2 FETCH (FLAGS (\Seen) UID 2)
* 3 FETCH (FLAGS (\Seen) UID 3)
* 4 FETCH (FLAGS (\Seen) UID 4)
* 5 FETCH (FLAGS (\Seen) UID 5)
* 6 FETCH (FLAGS (\Seen) UID 6)
* 7 FETCH (FLAGS (\Seen) UID 7)
* 8 FETCH (FLAGS (\Seen) UID 8)
* 9 FETCH (FLAGS (\Seen) UID 9)
* 10 FETCH (FLAGS (\Seen) UID 10)
* 11 FETCH (FLAGS (\Seen) UID 11)
* 12 FETCH (FLAGS (\Seen) UID 12)
* 13 FETCH (FLAGS (\Seen) UID 13)
* 14 FETCH (FLAGS (\Seen) UID 14)
* 15 FETCH (FLAGS (\Seen) UID 15)
* 16 FETCH (FLAGS (\Seen) UID 16)
* 17 FETCH (FLAGS (\Seen) UID 17)
* 18 FETCH (FLAGS (\Seen) UID 18)
* 19 FETCH (FLAGS (\Seen) UID 19)
* 20 FETCH (FLAGS (\Seen) UID 20)
* 21 FETCH (FLAGS (\Seen) UID 21)
* 22 FETCH (FLAGS (\Seen) UID 22)
* 23 FETCH (FLAGS (\Seen) UID 23)
[-----elided-----]
* 20459 FETCH (FLAGS (\Seen) UID 20483)
* 20460 FETCH (FLAGS (\Seen) UID 20484)
* 20461 FETCH (FLAGS (\Seen) UID 20485)
* 20462 FETCH (FLAGS (\Seen) UID 20486)
4 OK Fetch completed.
+ idling
5 OK Idle completed.
6 OK Close completed.
* BYE Logging out
7 OK Logout completed.
--
Daniel Price - Solaris Kernel Engineering - dp at eng.sun.com - blogs.sun.com/dp
Dan Price
2007-Feb-16 08:20 UTC
[Dovecot] severe performance problem (mail cache related?)
On Wed 14 Feb 2007 at 02:24PM, Dan Price wrote:> write(1, " * 1 0 7 9 5 F E T C".., 2050) = 2050 > mmap64(0x00000000, 7356416, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xFD800000 > munmap(0xFE602000, 1048576) = 0 > munmap(0xFE502000, 1048576) = 0 > munmap(0xFE402000, 1048576) = 0 > munmap(0xFE302000, 1048576) = 0 > munmap(0xFE202000, 1048576) = 0 > munmap(0xFE102000, 1048576) = 0 > munmap(0xFE002000, 1048576) = 0 > munmap(0xFE000000, 8192) = 0I was sad to see no response about this issue. I'm now seeing this on my *own* mailbox which is disturbing. Here is an example: pread64(9, " p o s a l s\n\0\0\0\013".., 8192, 7241728) = 8192 pread64(9, " < S t e v e n . L u c".., 8192, 7249920) = 8192 pread64(9, "\0\0\01F\0\0\0\0 T o : ".., 8192, 7258112) = 8192 mmap64(0x00000000, 13058048, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xFE400000 munmap(0xFDF72000, 1048576) = 0 munmap(0xFDE72000, 1048576) = 0 munmap(0xFDD72000, 1048576) = 0 munmap(0xFDC72000, 1048576) = 0 munmap(0xFDB72000, 1048576) = 0 munmap(0xFDA72000, 1048576) = 0 munmap(0xFD972000, 1048576) = 0 munmap(0xFD872000, 1048576) = 0 munmap(0xFD772000, 1048576) = 0 munmap(0xFD672000, 1048576) = 0 munmap(0xFD572000, 1048576) = 0 munmap(0xFD472000, 1048576) = 0 munmap(0xFD402000, 458752) = 0 munmap(0xFD400000, 8192) = 0 So here we see dovecot allocate a whopping 12MB of anonymous memory, then munmap it all away in 1MB chunks. Timo, do you know why this is happening? It is ruining performance for me. -dp -- Daniel Price - Solaris Kernel Engineering - dp at eng.sun.com - blogs.sun.com/dp
Bill Boebel
2007-Feb-16 12:40 UTC
[Dovecot] severe performance problem (mail cache related?)
On Fri, February 16, 2007 6:39 am, Timo Sirainen <tss at iki.fi> said:> On Fri, 2007-02-16 at 03:29 -0800, Dan Price wrote: >> Well there you go, I'm a dope. I think I set mmap_disable=yes because I >> was seeing strange things happening where there would be thousands >> (millions?) of madvise(DONTNEED) calls-- seemingly forever in a loop. I >> have not yet tracked that problem down-- next time I see it, I will >> make sure to get to the bottom of it. > > Actually the only place where madvise(MADV_DONTNEED) is called is in the > file-cache code which is used only with mmap_disable=yes.I'm not sure if this is related or not, but we set mmap_disable=yes last week and since then have seen what appears to be an occasional infinite loops. I have been trying to track down some more details before posting to the list, but here is what I have so far. There is no error logged in the dovecot log when this occurs, and it only stops by "kill -9" on the process... # top -c PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME CPU COMMAND 7832 virtual 25 0 580 496 376 R 71.5 0.0 70:59 0 imap [user at example.com 192.168.1.14] # lsof -p 7832 COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME imap 7832 virtual cwd DIR 147,0 600 2372995 /data1/mail/ex/example.com/us/user imap 7832 virtual rtd DIR 3,3 4096 2 / imap 7832 virtual txt REG 3,3 412996 789553 /usr/libexec/dovecot/imap imap 7832 virtual mem REG 3,3 33856 771355 /usr/lib/dovecot/lib10_quota_plugin.so imap 7832 virtual mem REG 3,3 7720 771364 /usr/lib/dovecot/imap/lib11_imap_quota_plugin.so imap 7832 virtual mem REG 3,3 106912 278626 /lib/ld-2.3.2.so imap 7832 virtual mem REG 3,3 14868 278653 /lib/libdl-2.3.2.so imap 7832 virtual mem REG 3,3 1571824 278633 /lib/tls/libc-2.3.2.so imap 7832 virtual 0u IPv4 -1140164370 TCP vip.mail17a.r4.iad.mlsrvr.com:imap->director2.r2.iad.emailsrvr.com:56195 (ESTABLISHED) imap 7832 virtual 1u IPv4 -1140164370 TCP vip.mail17a.r4.iad.mlsrvr.com:imap->director2.r2.iad.emailsrvr.com:56195 (ESTABLISHED) imap 7832 virtual 2w FIFO 0,5 3154802927 pipe imap 7832 virtual 3r CHR 1,9 599160 /dev/urandom imap 7832 virtual 4r FIFO 0,5 3154802928 pipe imap 7832 virtual 5w FIFO 0,5 3154802928 pipe imap 7832 virtual 6r FIFO 0,5 3154802929 pipe imap 7832 virtual 7w FIFO 0,5 3154802929 pipe imap 7832 virtual 8u REG 22,1 11112 6602923 /var/index/data1/mail/ex/example.com/us/user/.Elementos enviados/dovecot.index imap 7832 virtual 9u REG 22,1 50824 6602903 /var/index/data1/mail/ex/example.com/us/user/.Elementos enviados/dovecot.index.log imap 7832 virtual 10u REG 147,0 3074 6346008 /data1/mail/ex/example.com/us/user/maildirsize imap 7832 virtual 11w REG 147,0 905650 7062984 /data1/mail/ex/example.com/us/user/.Elementos enviados/tmp/1171483586.P7832Q0M770594.mail17a.r4.iad.mlsrvr.com # strace -p 7832 read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable) read(0, 0x96ca1f0, 3992) = -1 EAGAIN (Resource temporarily unavailable)
Bill Boebel
2007-Feb-16 14:13 UTC
[Dovecot] severe performance problem (mail cache related?)
On Fri, February 16, 2007 9:03 am, Timo Sirainen <tss at iki.fi> said:> Looks like my rc22 fix broke that then. It didn't loop forever, only > until client sent the whole message or until it disconnected, but it did > eat all the CPU while waiting. > > Fix here: > http://dovecot.org/list/dovecot-cvs/2007-February/007721.html > > I guess this is good enough reason for rc23. >Nice. Thanks for the quick fix. Bill