Re: Slow start of imap service
Paul van der Vlis <[email protected]>
| Newsgroups | gmane.mail.imap.cyrus |
|---|---|
| Message-ID | <[email protected]> |
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 <[email protected]>: >>> >>>> 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/ ---- Cyrus Home Page: http://www.cyrusimap.org/ List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/ To Unsubscribe: https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus