[Opendnssec-user] enforcerd opening (soft)hsm taking too long

[Tom Hendrikx]

Hi,

Since some time noticed I have some issues restarting opendnssec (in
both v1.3.12 and v1.3.13). It seems that opening the HSM (softhsm
v1.3.4) takes most of the time. During startup, logging looks like
(notice timestamps):

2013-03-26T17:10:52+01:00 christine ods-enforcerd: opendnssec starting...
2013-03-26T17:10:52+01:00 christine ods-enforcerd: opendnssec Parent
exiting...
2013-03-26T17:10:52+01:00 christine ods-enforcerd: opendnssec forked OK...
2013-03-26T17:10:52+01:00 christine ods-enforcerd: group set to:
opendnssec (101)
2013-03-26T17:10:52+01:00 christine ods-enforcerd: user set to:
opendnssec (103)
2013-03-26T17:10:52+01:00 christine ods-enforcerd: opendnssec started
(version 1.3.13), pid 22843
2013-03-26T17:11:01+01:00 christine ods-enforcerd: HSM opened successfully.
2013-03-26T17:11:01+01:00 christine ods-enforcerd: Checking database
connection...
2013-03-26T17:11:01+01:00 christine ods-enforcerd: Database connection ok.
2013-03-26T17:11:01+01:00 christine ods-enforcerd: Reading config
"/etc/opendnssec/conf.xml"

Note that this is a small setup, with only 16 keys in the hsm. I tried
to do some housecleaning (ods-ksmutil key purge, softhsm --optimize) but
that didn't help.

This is also reproducable using 'ods-hsmutil list', which was a lot
easier to debug. While stracing that, I noticed that directly after
opening /dev/urandom, there are many blocks similar to this:

17:43:14.914952 clock_gettime(CLOCK_REALTIME, {1364316194, 915069224}) = 0
17:43:14.915365 clock_gettime(CLOCK_MONOTONIC, {3062, 8439749}) = 0
17:43:14.915886 clock_gettime(CLOCK_MONOTONIC_RAW, {3061, 968719894}) = 0
17:43:14.916717 clock_gettime(0xfffffffa /* CLOCK_??? */, {0,
110459369}) = 0
17:43:14.917219 clock_gettime(0xfffffffe /* CLOCK_??? */, {0,
110618298}) = 0
17:43:14.917628 select(4, [3], NULL, NULL, {0, 100000}) = 0 (Timeout)
17:43:15.023668 select(5, [4], NULL, NULL, {0, 100000}) = 1 (in [4],
left {0, 99995})
17:43:15.024321 read(4, "", 0)    = 0

grep shows 84 occurances, taking up most time between 17:43:14.807874
and 17:43:23.946592 (i.e. ~9.1 seconds), while total runtime is around
9.5 seconds.

This startup time isn't really an issue if it's to be expected, however
combined with the included ods-control script that reports a daemon as
'failed to start' after 5 seconds of waiting, this makes me wonder... ;)

Any ideas?

Kind regards,
	Tom

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 899 bytes
Desc: OpenPGP digital signature
URL: <http://lists.opendnssec.org/pipermail/opendnssec-user/attachments/20130326/8f58b92d/attachment.bin>