Slow start of imap service

Sun Sep 30 22:32:03 EDT 2018

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

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

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. :)

Cheers,

ellie