[Opendnssec-develop] performance

Mon Sep 14 08:46:24 UTC 2009

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Another guess is that the signer engine is file based. More files in a
directory slows down the engine, see the story in the icebox (story id
846640)

Matthijs

Patrik Wallström wrote:
> 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.
> 

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iQEcBAEBAgAGBQJKrgLdAAoJEA8yVCPsQCW51KkIAMJ9i8U0h30dKxjR1iZqlXZU
Q99yrr83dIsdfHOnDh5jyz4MDr0dk/o8eZDTv/NuF0CZ2TwlqqtGq3/sHPioFHVG
C3iRGJAgKtttS9n5qAmVr/qGO3AEZCi2kwMBw+U12PoZQX4cnoJNpusHoPRCCHJ2
a4O8HUklDstsQ05fcEiEOVlFw8tIfKcXAVEAZlYeAhJAY8mqTPZ4DLMdSeEXodfE
ToME2BW2Cilb7I+exRQLqGsD8w7dmz/3p6cq5BZdOZ5QhGAdHhWR02y0FQXAGBWS
qdAugwgTjO8g6PS8QPhTzFWRpqqqW1Z7PXrc1oN95Rp/7o/yZlsjHuSt/6iETk8=
=d05V
-----END PGP SIGNATURE-----