Question regarding performance of dovecot-1.0.15

[Hanno Wagner]

Hi,

I have a dovect 1.0.15 on my mailserver and as a Client I use  
offlineimap.

Since some time now my mailsynchronisation got slow - I don't know  
exactly where the problem is, but I tried to track it down. Usually  
the UID-Searches are fast (according to the offlineimap-debugging) but  
as soon as it comes to big folders it takes a long time:

[..]
DEBUG[imap]:   37:15.22 < * 1 RECENT
DEBUG[imap]:   37:15.22         matched r'\* (?P<data>\d+) (?P<type>[A-
Z-]+)( (?P<data2>.*))?' => ('1', 'RECENT', None, None)
DEBUG[imap]:   37:15.22 untagged_responses[RECENT] 1 += ["1"]
DEBUG[imap]:   37:15.22 < HAMH49 OK Append completed.
DEBUG[imap]:   37:15.22         matched r'(?P<tag>HAMH\d+) (?P<type>[A-
Z]+) (?P<data>.*)' => ('HAMH49', 'OK', 'Append completed.')
DEBUG[imap]:   37:15.22 > HAMH50 CHECK
DEBUG[imap]:   37:15.49 < HAMH50 OK Check completed.
DEBUG[imap]:   37:15.49         matched r'(?P<tag>HAMH\d+) (?P<type>[A-
Z]+) (?P<data>.*)' => ('HAMH50', 'OK', 'Check completed.')
DEBUG[imap]: savemessage: first attempt to get new UID
DEBUG[imap]: savemessage_searchforheader called for X-OfflineIMAP-
x601334136
-52656d6f7465496d61704976616e6f7661
-446174656e73636875747a2e4343432e646562617465:  
1257496634-0840104922121-v5.99.4
DEBUG[imap]:   37:15.49 > HAMH51 UID SEARCH HEADER X-OfflineIMAP-
x601334136
-52656d6f7465496d61704976616e6f7661
-446174656e73636875747a2e4343432e646562617465  
"1257496634-0840104922121-v5.99.4"
DEBUG[imap]:   42:46.80 < * SEARCH 24578
DEBUG[imap]:   42:46.80         matched r'\* (?P<type>[A-Z-]+)( (?
P<data>.*))?' => ('SEARCH', ' 24578', '24578')
DEBUG[imap]:   42:46.80 untagged_responses[SEARCH] 0 += ["24578"]
DEBUG[imap]:   42:46.80 < HAMH51 OK Search completed.
DEBUG[imap]:   42:46.80         matched r'(?P<tag>HAMH\d+) (?P<type>[A-
Z]+) (?P<data>.*)' => ('HAMH51', 'OK', 'Search completed.')
DEBUG[imap]:   42:46.80 untagged_responses[SEARCH] => ['24578']
DEBUG[imap]: savemessage_searchforheader got initial matchinguids:  
'24578'
DEBUG[imap]: savemessage_searchforheader: matchinguids now ['24578']
DEBUG[imap]: savemessage: returning 24578
Copy message 9480 Maildir[.Datenschutz.CCC.debate] ->  
IMAP[Datenschutz.CCC.debate], LocalStatus[.Datenschutz.CCC.debate]
DEBUG[imap]: savemessage: called
DEBUG[imap]: savemessage: using date "15-Mar-2009 18:04:01 +0100"
DEBUG[imap]: savemessage: initial content is: 'Return-path: [..] (here  
is the mail)

DEBUG[imap]: savemessage: new headers are: X-OfflineIMAP-
x1331546026
-52656d6f7465496d61704976616e6f7661
-446174656e73636875747a2e4343432e646562617465:  
1257496966-0335241954714-v5.99.4
DEBUG[imap]: savemessage_addheader: called to add X-OfflineIMAP-
x1331546026
-52656d6f7465496d61704976616e6f7661
-446174656e73636875747a2e4343432e646562617465:  
1257496966-0335241954714-v5.99.4
DEBUG[imap]: savemessage_addheader: insertionpoint = 63
DEBUG[imap]: savemessage_addheader: leader = 'Return-path: <debate-return-45711-wagner=fitug.de@...
 >'
DEBUG[imap]: savemessage_addheader: newline = '\r\nX-OfflineIMAP-
x1331546026
-52656d6f7465496d61704976616e6f7661
-446174656e73636875747a2e4343432e646562617465:  
1257496966-0335241954714-v5.99.4'
DEBUG[imap]: savemessage_addheader: trailer = '\r\nEnvelope-to:[..]  
the mail..




As you can see at the timestamp, it took roundabout 5 minutes to find  
the next mail. Is this normal? In this mailbox there are right now  
around 20.000 mails, which shouldn't be too hard then... or am I  
missing something there? Is there a way to see why dovecot needs so  
long to find the next mail to synchronise?






my configuration:

# 1.0.15: /etc/dovecot/dovecot.conf
log_path: /home/rince/dovecot-debug.log
info_log_path: /home/rince/dovecot-debug.log
log_timestamp: %Y-%m-%d %H:%M:%S
protocols: imaps pop3s imap
listen(default): 10.11.12.1
listen(imap): 10.11.12.1
listen(pop3): *
ssl_cert_file: /etc/ssl/certs/ivanova.crt
ssl_key_file: /etc/ssl/private/ivanova.key
login_dir: /var/run/dovecot/login
login_executable(default): /usr/lib/dovecot/imap-login
login_executable(imap): /usr/lib/dovecot/imap-login
login_executable(pop3): /usr/lib/dovecot/pop3-login
login_user: dovecot-login
mail_privileged_group: mail
mail_debug: yes
mail_executable(default): /usr/lib/dovecot/imap
mail_executable(imap): /usr/lib/dovecot/imap
mail_executable(pop3): /usr/lib/dovecot/pop3
mail_plugin_dir(default): /usr/lib/dovecot/modules/imap
mail_plugin_dir(imap): /usr/lib/dovecot/modules/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/modules/pop3
pop3_uidl_format(default):
pop3_uidl_format(imap):
pop3_uidl_format(pop3): %08Xu%08Xv
auth default:
   user: dovecot-auth
   passdb:
     driver: passwd-file
     args: /etc/dovecot/passwd
   userdb:
     driver: passwd
   userdb:
     driver: passwd-file
     args: /etc/dovecot/passwd

Unfortunately, except the starting-up message, there comes nothing in  
the debug-logfiles.

Ciao, Hanno
--
Let me get this straight: You think that your client, one of the  
wealthiest,
most powerful men in the world, is secretly a vigilante who spends his  
nights
beating criminals to a pulp with his bare hands. And your plan is to  
blackmail
this person? Good luck.        (Lucius Fox, Morgan Freeman, The Dark  
Knight)

[Timo Sirainen]

On Fri, 2009-11-06 at 11:53 +0100, Hanno Wagner wrote:
> DEBUG[imap]:   37:15.49 > HAMH51 UID SEARCH HEADER X-OfflineIMAP-
> x601334136

Dovecot should serve this request from dovecot.index.cache file, which
should be pretty fast.

> my configuration:

There's no mention of mail_location setting. Are you using mbox or
maildir? If you're using mbox, you could try if setting
mbox_very_dirty_syncs=yes helps. Also you could stracing the imap
process to see what exactly it's doing.
http://wiki.dovecot.org/Debugging/ProcessTracing

[Hanno Wagner]

Hiho,

Am 06.11.2009 um 21:01 schrieb Timo Sirainen:

> There's no mention of mail_location setting. Are you using mbox or
> maildir? If you're using mbox, you could try if setting
> mbox_very_dirty_syncs=yes helps. Also you could stracing the imap
> process to see what exactly it's doing.
> http://wiki.dovecot.org/Debugging/ProcessTracing

Sorry, it is Maildir.

And interesting enough, now I have two problems ;)

One is a panic in Dovecot, the second the performance. I made an  
strace as you propsed, I put it on http://www.rince.de/dovecot.log

Ciao, Hanno
--
Let me get this straight: You think that your client, one of the  
wealthiest,
most powerful men in the world, is secretly a vigilante who spends his  
nights
beating criminals to a pulp with his bare hands. And your plan is to  
blackmail
this person? Good luck.        (Lucius Fox, Morgan Freeman, The Dark  
Knight)

[Timo Sirainen]

On Fri, 2009-11-06 at 21:33 +0100, Hanno Wagner wrote:
> And interesting enough, now I have two problems ;)
>
> One is a panic in Dovecot, the second the performance. I made an  
> strace as you propsed, I put it on http://www.rince.de/dovecot.log

The strace shows the crash instead of the long wait. And for crashes
straces are nearly useless. Showing the actual panic message and perhaps
gdb backtrace would be a lot more helpful.

Anyway, since v1.0 is in security-fixes-only mode now, finding the cause
of the crash isn't very useful either. You'll probably get rid of it by
just deleting dovecot.index* files.

[Hanno Wagner]

Good evening,

Am 06.11.2009 um 23:42 schrieb Timo Sirainen:

> The strace shows the crash instead of the long wait. And for crashes
> straces are nearly useless. Showing the actual panic message and  
> perhaps
> gdb backtrace would be a lot more helpful.

Okay, but I just remove d the dovecot.index*-files and it works again.

Now I made a trace for the long waits. I put another strace-log on the  
webserver, http://www.rince.de/dovecot.log.gz (since it is unpacked  
300MB)

Thank you for looking into my problems here!

Ciao, Hanno
--
"You all were watching, I take it?"
"Yes"
"Did you see us fight?"
"No"
"Trap"

[Timo Sirainen]

On Sat, 2009-11-07 at 00:06 +0100, Hanno Wagner wrote:
> Now I made a trace for the long waits. I put another strace-log on the  
> webserver, http://www.rince.de/dovecot.log.gz (since it is unpacked  
> 300MB)

Looks like it's opening the maildir files every time and parsing their
headers, instead of using the cache file. I don't really know why it's
doing that, but it looks like a bug. But like I said, no more bug fixes
to v1.0.. Upgrading to v1.1 or v1.2 probably helps.

[Hanno Wagner]

Hiho,

Am 07.11.2009 um 00:24 schrieb Timo Sirainen:

> Looks like it's opening the maildir files every time and parsing their
> headers, instead of using the cache file. I don't really know why it's
> doing that, but it looks like a bug. But like I said, no more bug  
> fixes
> to v1.0.. Upgrading to v1.1 or v1.2 probably helps.

Okay, I did that - and it worked, thanks! So my problem is solved ;)

Ciao, Hanno
--
Let me get this straight: You think that your client, one of the  
wealthiest,
most powerful men in the world, is secretly a vigilante who spends his  
nights
beating criminals to a pulp with his bare hands. And your plan is to  
blackmail
this person? Good luck.        (Lucius Fox, Morgan Freeman, The Dark  
Knight)