[Opendnssec-develop] performance

Fri Sep 11 19:31:11 UTC 2009

I am testing to sign a 1000 domains. Having found the major  
performance issue in SoftHSM I found out that the signing of 1000  
domains takes forever. I guess that there is a lot of sleeping going on.

Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 6 acquiring lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 6 acquired lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 6 released lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: Got task for worker 6
Sep 11 21:28:19 mask OpenDNSSEC signer engine: Worker 6 run task
Sep 11 21:28:19 mask OpenDNSSEC signer engine: Zone action to perform: 6
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 7 acquiring lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 7 acquired lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: no task for worker 7,  
sleep for 22.8428030014
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 7 released lock  
by going to wait (for ttime)
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 8 acquiring lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 8 acquired lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: no task for worker 8,  
sleep for 22.8425970078
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 8 released lock  
by going to wait (for ttime)
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 5 acquiring lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 5 acquired lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: no task for worker 5,  
sleep for 22.8424079418
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 5 released lock  
by going to wait (for ttime)
Sep 11 21:28:19 mask OpenDNSSEC signer engine: Run command: '/usr/ 
local/libexec/opendnssec/signer -c /etc/opendnssec/conf.xml -p /var/ 
opendnssec/tmp/459manyzones.signed -w /var/opendnssec/tmp/ 
459manyzones.signed2 -r'
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 1 acquiring lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 1 acquired lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: no task for worker 1,  
sleep for 22.8420629501
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 1 released lock  
by going to wait (for ttime)
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 3 acquiring lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 3 acquired lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: no task for worker 3,  
sleep for 22.8418889046
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 3 released lock  
by going to wait (for ttime)
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 4 acquiring lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 4 acquired lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: no task for worker 4,  
sleep for 22.841711998
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 4 released lock  
by going to wait (for ttime)
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 2 acquiring lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 2 acquired lock
Sep 11 21:28:19 mask OpenDNSSEC signer engine: no task for worker 2,  
sleep for 22.8298828602
Sep 11 21:28:19 mask OpenDNSSEC signer engine: worker 2 released lock  
by going to wait (for ttime)
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to subp:
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to subp: :origin  
459manyzones
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to subp: :soa_ttl  
3600
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to  
subp: :soa_minimum 3600
Sep 11 21:28:19 mask OpenDNSSEC signer engine: set serial to 1252697299
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to  
subp: :expiration 20090918192819
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to  
subp: :expiration_denial 20090918192819
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to subp: :jitter  
43200
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to  
subp: :inception 20090911192319
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to subp: :refresh  
20090915192819
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to  
subp: :refresh_denial 20090915192819
Sep 11 21:28:19 mask OpenDNSSEC signer engine: use signature key:  
a1724d88fbb45b1142ff5bdde3e3f385
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to subp: :add_ksk  
a1724d88fbb45b1142ff5bdde3e3f385 7 257
Sep 11 21:28:19 mask OpenDNSSEC signer engine: use signature key:  
53305ef26679e5467409d8fbe68e8b17
Sep 11 21:28:19 mask OpenDNSSEC signer engine: write to subp: :add_zsk  
53305ef26679e5467409d8fbe68e8b17 7 256
Sep 11 21:28:20 mask communicated: INFO: Promoting ZSK from publish to  
active as this is the first pass for the zone
Sep 11 21:28:21 mask communicated: WARNING: Making non-backed up ZSK  
active, PLEASE make sure that you know the potential problems of using  
keys which are not recoverable
Sep 11 21:28:22 mask keygend: /var/opendnssec/kasp.db.our_lock already  
locked, sleep
Sep 11 21:28:25 mask OpenDNSSEC signer engine: signer stderr: signer:  
number of signatures created: 1 (0 rr/sec)
Sep 11 21:28:25 mask OpenDNSSEC signer engine: No new signatures,  
keeping zone
Sep 11 21:28:25 mask OpenDNSSEC signer engine: worker 6 acquiring lock
Sep 11 21:28:25 mask OpenDNSSEC signer engine: worker 6 acquired lock
Sep 11 21:28:25 mask OpenDNSSEC signer engine: no task for worker 6,  
sleep for 16.4016799927
Sep 11 21:28:25 mask OpenDNSSEC signer engine: worker 6 released lock  
by going to wait (for ttime)
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Received command:  
'update 670manyzones'
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Zone 670manyzones locked
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Scheduling task to sign  
zone 670manyzones at 1252678193.9 with resign time 7200
Sep 11 21:28:28 mask OpenDNSSEC signer engine: acquire cond
Sep 11 21:28:28 mask OpenDNSSEC signer engine: notify
Sep 11 21:28:28 mask OpenDNSSEC signer engine: release cond
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Releasing lock on zone  
670manyzones
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Scheduling task to sign  
zone 670manyzones at 1252678193.9 with resign time 7200
Sep 11 21:28:28 mask OpenDNSSEC signer engine: acquire cond
Sep 11 21:28:28 mask OpenDNSSEC signer engine: notify
Sep 11 21:28:28 mask OpenDNSSEC signer engine: release cond
Sep 11 21:28:28 mask OpenDNSSEC signer engine: acquire cond
Sep 11 21:28:28 mask OpenDNSSEC signer engine: notify
Sep 11 21:28:28 mask OpenDNSSEC signer engine: release cond
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Releasing lock on engine
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Sending response: Zone  
now has config#012
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Done handling command
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Connection closed by peer
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 5 acquiring lock
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 5 acquired lock
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 5 released lock
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Got task for worker 5
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Worker 5 run task
Sep 11 21:28:28 mask OpenDNSSEC signer engine: Zone action to perform: 3
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 8 acquiring lock
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 3 acquiring lock
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 3 acquired lock
Sep 11 21:28:28 mask OpenDNSSEC signer engine: no task for worker 3,  
sleep for 13.7042028904
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 3 released lock  
by going to wait (for ttime)
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 1 acquiring lock
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 1 acquired lock
Sep 11 21:28:28 mask OpenDNSSEC signer engine: no task for worker 1,  
sleep for 13.7039978504
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 1 released lock  
by going to wait (for ttime)
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 7 acquiring lock
Sep 11 21:28:28 mask OpenDNSSEC signer engine: worker 7 acquired lock

So this is what I get timing wise:

-rw-r--r-- 1 root root 10591 2009-09-11 21:14 647manyzones
-rw-r--r-- 1 root root 10591 2009-09-11 21:14 648manyzones
-rw-r--r-- 1 root root 10588 2009-09-11 21:15 649manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:15 650manyzones
-rw-r--r-- 1 root root 10591 2009-09-11 21:16 651manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:17 652manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:17 653manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:18 654manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:19 655manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:19 656manyzones
-rw-r--r-- 1 root root 10617 2009-09-11 21:20 657manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:21 658manyzones
-rw-r--r-- 1 root root 10591 2009-09-11 21:21 659manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:22 660manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:23 661manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:23 662manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:24 663manyzones
-rw-r--r-- 1 root root 10617 2009-09-11 21:24 664manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:25 665manyzones
-rw-r--r-- 1 root root 10591 2009-09-11 21:26 666manyzones
-rw-r--r-- 1 root root 10617 2009-09-11 21:26 667manyzones
-rw-r--r-- 1 root root 10617 2009-09-11 21:27 668manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:28 669manyzones
-rw-r--r-- 1 root root 10618 2009-09-11 21:28 670manyzones
-rw-r--r-- 1 root root 10591 2009-09-11 21:29 671manyzones

1.5 domains per minute is not very good.

-- 
Patrik Wallström
Project Manager, R&D
.SE (Stiftelsen för Internetinfrastruktur)
E-mail: patrik.wallstrom at iis.se
Web: http://www.iis.se/