Since posting the previous thread we've setup a new system (Opteron 2.0ghz, 1gb ram, Fedora 6) for testing. I am hoping somebody very familiar with the indexing portion of dovecot can shed some light on this for me.
After much testing, I've come to one primary conclusion that dovecot is possibly unnecessarily scanning or reading files within the maildir directories. Take a mailbox for instance (my test one has 71570 emails in the cur/ folder so the process runs long enough to get data of what it's doing). Follow these steps:
- First pop3 connection. With no index files whatsoever, it takes nearly a full 10 minutes at 100% io load to scan the 71570 files (748M) directory and build the index files from scratch which look like this: -rw------- 1 postfix postdrop 839K Feb 1 00:43 dovecot.index -rw------- 1 postfix postdrop 1.9M Feb 1 00:57 dovecot.index.cache -rw------- 1 postfix postdrop 560K Feb 1 00:43 dovecot.index.log -rw------- 1 postfix postdrop 3.1M Feb 1 00:43 dovecot-uidlist
While it's building index i see a lot of these fly by in lsof pop3 2023 postfix 8r REG 8,3 14425 285947 /var/spool/mail/test.visp.net/natetest/cur/1128488047.V902I7d42e.s3.visp.net:2,
No problem here, the disk can only go as fast as the disk can go and thats a *lot* of mail. Although, one curious thing here, it appears that dovecot is reading or at least scanning the entire contents of the files within the cur/ directory to generate an index. I assume this by watching my disk cache go from 100MB to 600MB. Is it necessary to do that or only read the top X lines of each file, is that even possible?
- Second connection. Near instantaneous results from a login and LIST. Cannot perform an lsof fast enough to see what files it's opening. This step can be repeated with nearly the same results.
*rebooted machine to clear all cache*
- Third connection. It takes ~40 seconds to display a LIST after login. The index files are untouched; however, during the 40 seconds I'm waiting, I can catch a few of these in lsof. pop3 1971 postfix 10r REG 8,3 4196 205963 /var/spool/mail/test.visp.net/natetest/cur/1157863512.V902I1f3867.s3.visp.net:2,S
This tells me even though there is no new email, it is re-scanning the cur/ directory somewhat. It doesn't take near as long as the initial index build, but certainly takes longer than it would for the system to read any or all of the listed index files above. Why would dovecot need to even enter cur/ if the index file is up to date? Is it verifying that the index file is up to date by re-reading some or all of the many files in cur/? If so, could it not get the info it needs by simply doing the equivalent of a ls, which would take considerably less time?
The disk cache is only filled up an additional 30meg vs an additional 500meg from connection 1, so it's certainly not reading as much data. (also makes me wonder why the initial scan/index build could not use this lesser time consuming function if thats what it's doing).
Additional information: Running strace on the initial indexing looks like this...
open("/var/spool/mail/test.visp.net/natetest/cur/1115929738.V902I67c13.test.visp.net:2,",
O_RDONLY) = 8
fstat(8, {st_mode=S_IFREG|0600, st_size=4667, ...}) = 0
pread(8, "Return-Path:
Running strace on the 3rd connection looks like this...
open("/var/spool/mail/test.visp.net/natetest/cur/1114490671.V902I6011f.test.visp.net:2,",
O_RDONLY) = 10
fstat(10, {st_mode=S_IFREG|0600, st_size=5367, ...}) = 0
pread(10, "Return-Path:
Thank you for the help!
- Nate
Running strace on the 3rd connection looks like this...
open("/var/spool/mail/test.visp.net/natetest/cur/1114490671.V902I6011f.test.visp.net:2,",
O_RDONLY) = 10
fstat(10, {st_mode=S_IFREG|0600, st_size=5367, ...}) = 0
pread(10, "Return-Path: Thank you for the help!