Slow start of imap service
Paul van der Vlis
paul at vandervlis.nl
Mon Oct 1 04:04:57 EDT 2018
Op 01-10-18 om 04:32 schreef ellie timoney:
>
>
> On Sat, Sep 29, 2018, at 8:59 AM, Paul van der Vlis wrote:
>> Op 28-09-18 om 15:34 schreef Michael Menge:
>>>
>>> Quoting Paul van der Vlis <paul at vandervlis.nl>:
>>>
>>>> Hello,
>>>>
>>>> I am using Cyrus-imapd from Debian stable (2.5.10-3), and starting up
>>>> takes very long. I see processes starting, but no imapd.
>>>>
>>>> In most cases I restart Cyrus more then ones before it works. Not sure I
>>>> have to wait longer, or restarting after some time helps.
>>>>
>>>> This problem occurs on only one machine, on two other less busy machine
>>>> with the same Cyrus I don't have problems.
>>>>
>>>> Maybe somebody here knows more about what could be wrong? Or how to
>>>> debug this?
>>>>
>>>
>>>
>>> What is cyrus logging to your logfiles when you restart?
>>
>> In my crontab I have this line:
>> 00 4 * * * root /usr/sbin/service cyrus-imapd restart
>>
>> First I see many of this lines in /var/log/mail.log:
>> Sep 25 04:00:01 sigmund cyrus/imap[21598]: graceful shutdown
>>
>> Then I see this between those lines this:
>> -----
>> Sep 25 04:00:02 sigmund cyrus/idled[5844]: graceful shutdown initiated
>> by unexpected process 5838 (/usr/sbin/cyrmaster -l 32 -C /etc/imapd.conf
>> -M /etc/cyrus.conf)
>> Sep 25 04:00:02 sigmund cyrus/imaps[16434]: IDLE: error sending message
>> DONE to idled for mailbox user.nospam.Junk: Connection refused.
>> -----
>>
>> This line:
>> Sep 25 04:00:02 sigmund cyrus/master[5838]: process type:SERVICE
>> name:notify path:/usr/lib/cyrus/bin/notifyd age:85080.426s pid:6024
>> exited, status 75
>>
>> Many of these lines:
>> Sep 25 04:00:02 sigmund cyrus/master[5838]: process type:SERVICE
>> name:imap path:/usr/lib/cyrus/bin/imapd age:85073.234s pid:6027 exited,
>> status 75
>>
>> Then this:
>> --------
>> Sep 25 04:00:05 sigmund cyrus/ctl_cyrusdb[21829]: skiplist: clean
>> shutdown file missing, updating recovery stamp
>> Sep 25 04:00:05 sigmund cyrus/ctl_cyrusdb[21829]: recovering cyrus databases
>> Sep 25 04:00:05 sigmund cyrus/ctl_cyrusdb[21829]: done recovering cyrus
>> databases
>> Sep 25 04:00:05 sigmund cyrus/cyr_expire[21834]: skiplist: recovered
>> /var/lib/cyrus/deliver.db (9290 records, 1759220 bytes) in 0 seconds
>> Sep 25 04:00:05 sigmund cyrus/cyr_expire[21834]: skiplist: checkpointed
>> /var/lib/cyrus/deliver.db (9290 records, 1412288 bytes) in 0.227 sec
>> Sep 25 04:00:19 sigmund cyrus/cyr_expire[21834]: Expired 0 and expunged
>> 0 out of 1312483 messages from 2984 mailboxes
>> Sep 25 04:00:19 sigmund cyrus/cyr_expire[21834]: duplicate_prune:
>> pruning back 3.00 days
>> Sep 25 04:00:30 sigmund cyrus/cyr_expire[21834]: skiplist: longlock
>> /var/lib/cyrus/deliver.db for 1.8 seconds
>> Sep 25 04:00:33 sigmund cyrus/cyr_expire[21834]: skiplist: longlock
>> /var/lib/cyrus/deliver.db for 2.2 seconds
>> Sep 25 04:00:39 sigmund cyrus/cyr_expire[21834]: skiplist: longlock
>> /var/lib/cyrus/deliver.db for 1.3 seconds
>> Sep 25 04:05:36 sigmund cyrus/cyr_expire[21834]: duplicate_prune: purged
>> 2217 out of 9290 entries
>> Sep 25 04:05:36 sigmund cyrus/tls_prune[21860]: skiplist: recovered
>> /var/lib/cyrus/tls_sessions.db (10219 records, 2235748 bytes) in 0 seconds
>> Sep 25 04:05:36 sigmund cyrus/tls_prune[21860]: skiplist: checkpointed
>> /var/lib/cyrus/tls_sessions.db (10219 records, 2147768 bytes) in 0.308 sec
>> Sep 25 04:09:47 sigmund cyrus/tls_prune[21860]: skiplist: longlock
>> /var/lib/cyrus/tls_sessions.db for 1.4 seconds
>> Sep 25 04:10:23 sigmund cyrus/tls_prune[21860]: skiplist: longlock
>> /var/lib/cyrus/tls_sessions.db for 2.2 seconds
>> Sep 25 04:10:45 sigmund cyrus/tls_prune[21860]: skiplist: longlock
>> /var/lib/cyrus/tls_sessions.db for 2.2 seconds
>> Sep 25 04:12:21 sigmund cyrus/tls_prune[21860]: skiplist: longlock
>> /var/lib/cyrus/tls_sessions.db for 1.3 seconds
>> Sep 25 04:12:47 sigmund cyrus/tls_prune[21860]: skiplist: longlock
>> /var/lib/cyrus/tls_sessions.db for 1.0 seconds
>> Sep 25 04:12:49 sigmund cyrus/tls_prune[21860]: skiplist: longlock
>> /var/lib/cyrus/tls_sessions.db for 1.8 seconds
>> Sep 25 04:17:33 sigmund cyrus/tls_prune[21860]: skiplist: longlock
>> /var/lib/cyrus/tls_sessions.db for 1.0 seconds
>> Sep 25 04:23:11 sigmund cyrus/tls_prune[21860]: skiplist: longlock
>> /var/lib/cyrus/tls_sessions.db for 1.0 seconds
>> Sep 25 04:25:31 sigmund cyrus/tls_prune[21860]: tls_prune: purged 4463
>> out of 10219 entries
>> Sep 25 04:25:31 sigmund cyrus/master[21826]: unable to
>> setsocketopt(IP_TOS) service lmtpunix/unix: Operation not supported
>> Sep 25 04:25:31 sigmund cyrus/master[21826]: unable to
>> setsocketopt(IP_TOS) service notify/unix: Operation not supported
>> Sep 25 04:25:31 sigmund cyrus/ctl_cyrusdb[22345]: checkpointing cyrus
>> databases
>> Sep 25 04:25:31 sigmund cyrus/ctl_cyrusdb[22345]: done checkpointing
>> cyrus databases
>> Sep 25 04:25:32 sigmund cyrus/imaps[22349]: inittls: Loading hard-coded
>> DH parameters
>> Sep 25 04:25:33 sigmund cyrus/imaps[22349]: starttls: TLSv1.2 with
>> cipher ECDHE-RSA-AES128-SHA (128/128 bits new) no authentication
>> Sep 25 04:26:20 sigmund cyrus/imap[22362]: inittls: Loading hard-coded
>> DH parameters
>> Sep 25 04:26:20 sigmund cyrus/imap[22363]: inittls: Loading hard-coded
>> DH parameters
>> ---------
>>
>> So you can see imap is active after 25 minutes...
>>
>>> What is in the START section of your /etc/cyrus.conf?
>> ----
>> START {
>> # do not delete this entry!
>> recover cmd="/usr/sbin/cyrus ctl_cyrusdb -r"
>>
>> # this is only necessary if idlemethod is set to "idled" in
>> # imapd.conf
>> idled cmd="idled"
>>
>> # this is useful on backend nodes of a Murder cluster
>> # it causes the backend to syncronize its mailbox list with
>> # the mupdate master upon startup
>> #mupdatepush cmd="/usr/sbin/cyrus ctl_mboxlist -m"
>>
>> # this is recommended if using duplicate delivery suppression
>> delprune cmd="/usr/sbin/cyrus expire -E 3"
>> # this is recommended if caching TLS sessions
>> tlsprune cmd="/usr/sbin/cyrus tls_prune"
>> }
>> ---------
>>
>> Thanks for you help!
>>
>> With regards,
>> Paul van der Vlis
>
> Looks like most of the time (nearly 20 minutes) is being taken up by tls_prune cleaning up the tls_sessions.db:
>
>> Sep 25 04:05:36 sigmund cyrus/tls_prune[21860]: skiplist: recovered
>> /var/lib/cyrus/tls_sessions.db (10219 records, 2235748 bytes) in 0 seconds
>> Sep 25 04:05:36 sigmund cyrus/tls_prune[21860]: skiplist: checkpointed
>> /var/lib/cyrus/tls_sessions.db (10219 records, 2147768 bytes) in 0.308 sec
>> [...]
>> Sep 25 04:25:31 sigmund cyrus/tls_prune[21860]: tls_prune: purged 4463
>> out of 10219 entries
Thanks for your conclusion!
> You could use the tls_sessions_db_path imapd.conf(5) option to put this database onto faster storage?
>
>> tls_sessions_db_path: <none>
>> The absolute path to the TLS sessions db file. If not specified, will be
>> configdirectory/tls_sessions.db
Interesting...
I use normal harddisks with software raid and LVM. And a qcow2-image for
the virtualisation.
> If you have the RAM for it, you should be able to put tls_sessions.db on a tmpfs filesystem. This database is only a cache, so nothing valuable will be lost if the machine is rebooted; and as a cache, it benefits from being on the fastest storage you have available. :)
I will think about it, not sure how big it is.
With regards,
Paul van der Vlis
--
Paul van der Vlis Linux systeembeheer Groningen
https://www.vandervlis.nl/
More information about the Info-cyrus
mailing list