Summary: bind9 uses very high CPU after an upgrade from Lucid to Precise. I have traced this to a directory permissions problem as /var/cache/bind is not writeable by the bind group after an upgrade, but is writeable after a clean install.
Ubuntu release: root@dev1-kvm-cluster:~# lsb_release -rd Description: Ubuntu 12.04.1 LTS Release: 12.04
Package version: root@dev1-kvm-cluster:~# apt-cache policy bind9 bind9: Installed: 1:9.8.1.dfsg.P1-4ubuntu0.4 Candidate: 1:9.8.1.dfsg.P1-4ubuntu0.4 Version table: *** 1:9.8.1.dfsg.P1-4ubuntu0.4 0 500 http://gb.archive.ubuntu.com/ubuntu/ precise-updates/main amd64 Packages 500 http://security.ubuntu.com/ubuntu/ precise-security/main amd64 Packages 100 /var/lib/dpkg/status 1:9.8.1.dfsg.P1-4 0 500 http://gb.archive.ubuntu.com/ubuntu/ precise/main amd64 Packages
Expected behaviour: Upgrading Lucid->Precise when bind9 is installed does not use >100% CPU
Observed behaviour: Upgrading Lucid->Precise when bind9 is installed does not use >100% CPU
Root cause:
On an upgraded machine:
root@dev1-kvm-cluster:~# ls -la /var/cache/bind total 8 drwxr-xr-x 2 root bind 4096 Jun 5 2012 . drwxr-xr-x 14 root root 4096 Dec 5 10:18 ..
On a clean install of Precise:
amb@adamant:~$ ls -la /var/cache/bind total 16 drwxrwxr-x 2 root bind 4096 Dec 4 21:00 . drwxr-xr-x 8 root root 4096 Dec 3 20:54 .. -rw-r--r-- 1 bind bind 698 Dec 4 21:00 managed-keys.bind -rw-r--r-- 1 bind bind 512 Dec 4 21:00 managed-keys.bind.jnl
Workaround:
# chmod 775 /var/cache/bind # service bind9 restart
Logs from the upgraded machine (see 'working directory not writeable' and 'permission denied')
05-Dec-2012 12:23:35.719 found 2 CPUs, using 2 worker threads 05-Dec-2012 12:23:35.720 using up to 4096 sockets 05-Dec-2012 12:23:35.726 loading configuration from '/etc/bind/named.conf' 05-Dec-2012 12:23:35.727 reading built-in trusted keys from file '/etc/bind/bind.keys' 05-Dec-2012 12:23:35.727 using default UDP/IPv4 port range: [1024, 65535] 05-Dec-2012 12:23:35.728 using default UDP/IPv6 port range: [1024, 65535] 05-Dec-2012 12:23:35.729 listening on IPv6 interfaces, port 53 05-Dec-2012 12:23:35.731 listening on IPv4 interface lo, 127.0.0.1#53 05-Dec-2012 12:23:35.732 listening on IPv4 interface eth0, 10.40.0.5#53 05-Dec-2012 12:23:35.734 listening on IPv4 interface eth1, 10.157.128.1#53 05-Dec-2012 12:23:35.735 listening on IPv4 interface eth1, 10.161.208.1#53 05-Dec-2012 12:23:35.736 listening on IPv4 interface eth0.60, 10.157.16.12#53 05-Dec-2012 12:23:35.738 generating session key for dynamic DNS 05-Dec-2012 12:23:35.738 sizing zone task pool based on 7 zones 05-Dec-2012 12:23:35.744 using built-in root key for view _default 05-Dec-2012 12:23:35.744 set up managed keys zone for view _default, file 'managed-keys.bind' 05-Dec-2012 12:23:35.744 Warning: 'empty-zones-enable/disable-empty-zone' not set: disabling RFC 1918 empty zones 05-Dec-2012 12:23:35.744 automatic empty zone: 254.169.IN-ADDR.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: 2.0.192.IN-ADDR.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: 100.51.198.IN-ADDR.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: 113.0.203.IN-ADDR.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: 255.255.255.255.IN-ADDR.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: 0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: D.F.IP6.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: 8.E.F.IP6.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: 9.E.F.IP6.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: A.E.F.IP6.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: B.E.F.IP6.ARPA 05-Dec-2012 12:23:35.744 automatic empty zone: 8.B.D.0.1.0.0.2.IP6.ARPA 05-Dec-2012 12:23:35.749 command channel listening on 127.0.0.1#953 05-Dec-2012 12:23:35.749 command channel listening on ::1#953 05-Dec-2012 12:23:35.749 the working directory is not writable 05-Dec-2012 12:23:35.749 ignoring config file logging statement due to -g option 05-Dec-2012 12:23:35.750 zone 0.in-addr.arpa/IN: loaded serial 1 05-Dec-2012 12:23:35.750 zone 157.10.in-addr.arpa/IN: loaded serial 1 05-Dec-2012 12:23:35.751 zone 127.in-addr.arpa/IN: loaded serial 1 05-Dec-2012 12:23:35.752 zone 255.in-addr.arpa/IN: loaded serial 1 05-Dec-2012 12:23:35.753 zone extility.install/IN: loaded serial 1300877104 05-Dec-2012 12:23:35.754 zone localhost/IN: loaded serial 2 05-Dec-2012 12:23:35.754 managed-keys-zone ./IN: loading from master file managed-keys.bind failed: file not found 05-Dec-2012 12:23:35.754 managed-keys.bind.jnl: create: permission denied 05-Dec-2012 12:23:35.754 managed-keys-zone ./IN: sync_keyzone:dns_journal_open -> unexpected error
Summary: bind9 uses very high CPU after an upgrade from Lucid to Precise. I have traced this to a directory permissions problem as /var/cache/bind is not writeable by the bind group after an upgrade, but is writeable after a clean install.
Ubuntu release: kvm-cluster: ~# lsb_release -rd
root@dev1-
Description: Ubuntu 12.04.1 LTS
Release: 12.04
Package version: kvm-cluster: ~# apt-cache policy bind9 dfsg.P1- 4ubuntu0. 4 dfsg.P1- 4ubuntu0. 4 dfsg.P1- 4ubuntu0. 4 0 gb.archive. ubuntu. com/ubuntu/ precise- updates/ main amd64 Packages security. ubuntu. com/ubuntu/ precise- security/ main amd64 Packages dpkg/status 9.8.1.dfsg. P1-4 0 gb.archive. ubuntu. com/ubuntu/ precise/main amd64 Packages
root@dev1-
bind9:
Installed: 1:9.8.1.
Candidate: 1:9.8.1.
Version table:
*** 1:9.8.1.
500 http://
500 http://
100 /var/lib/
1:
500 http://
Expected behaviour: Upgrading Lucid->Precise when bind9 is installed does not use >100% CPU
Observed behaviour: Upgrading Lucid->Precise when bind9 is installed does not use >100% CPU
Root cause:
On an upgraded machine:
root@dev1- kvm-cluster: ~# ls -la /var/cache/bind
total 8
drwxr-xr-x 2 root bind 4096 Jun 5 2012 .
drwxr-xr-x 14 root root 4096 Dec 5 10:18 ..
On a clean install of Precise:
amb@adamant:~$ ls -la /var/cache/bind keys.bind. jnl
total 16
drwxrwxr-x 2 root bind 4096 Dec 4 21:00 .
drwxr-xr-x 8 root root 4096 Dec 3 20:54 ..
-rw-r--r-- 1 bind bind 698 Dec 4 21:00 managed-keys.bind
-rw-r--r-- 1 bind bind 512 Dec 4 21:00 managed-
Workaround:
# chmod 775 /var/cache/bind
# service bind9 restart
Logs from the upgraded machine (see 'working directory not writeable' and 'permission denied')
05-Dec-2012 12:23:35.719 found 2 CPUs, using 2 worker threads named.conf' bind.keys' zones-enable/ disable- empty-zone' not set: disabling RFC 1918 empty zones IN-ADDR. ARPA IN-ADDR. ARPA 198.IN- ADDR.ARPA IN-ADDR. ARPA 255.255. IN-ADDR. ARPA 0.0.0.0. 0.0.0.0. 0.0.0.0. 0.0.0.0. 0.0.0.0. 0.0.0.0. 0.0.0.0. IP6.ARPA 0.0.0.0. 0.0.0.0. 0.0.0.0. 0.0.0.0. 0.0.0.0. 0.0.0.0. 0.0.0.0. IP6.ARPA 1.0.0.2. IP6.ARPA in-addr. arpa/IN: loaded serial 1 addr.arpa/ IN: loaded serial 1 addr.arpa/ IN: loaded serial 1 install/ IN: loaded serial 1300877104 keys.bind. jnl: create: permission denied dns_journal_ open -> unexpected error
05-Dec-2012 12:23:35.720 using up to 4096 sockets
05-Dec-2012 12:23:35.726 loading configuration from '/etc/bind/
05-Dec-2012 12:23:35.727 reading built-in trusted keys from file '/etc/bind/
05-Dec-2012 12:23:35.727 using default UDP/IPv4 port range: [1024, 65535]
05-Dec-2012 12:23:35.728 using default UDP/IPv6 port range: [1024, 65535]
05-Dec-2012 12:23:35.729 listening on IPv6 interfaces, port 53
05-Dec-2012 12:23:35.731 listening on IPv4 interface lo, 127.0.0.1#53
05-Dec-2012 12:23:35.732 listening on IPv4 interface eth0, 10.40.0.5#53
05-Dec-2012 12:23:35.734 listening on IPv4 interface eth1, 10.157.128.1#53
05-Dec-2012 12:23:35.735 listening on IPv4 interface eth1, 10.161.208.1#53
05-Dec-2012 12:23:35.736 listening on IPv4 interface eth0.60, 10.157.16.12#53
05-Dec-2012 12:23:35.738 generating session key for dynamic DNS
05-Dec-2012 12:23:35.738 sizing zone task pool based on 7 zones
05-Dec-2012 12:23:35.744 using built-in root key for view _default
05-Dec-2012 12:23:35.744 set up managed keys zone for view _default, file 'managed-keys.bind'
05-Dec-2012 12:23:35.744 Warning: 'empty-
05-Dec-2012 12:23:35.744 automatic empty zone: 254.169.
05-Dec-2012 12:23:35.744 automatic empty zone: 2.0.192.
05-Dec-2012 12:23:35.744 automatic empty zone: 100.51.
05-Dec-2012 12:23:35.744 automatic empty zone: 113.0.203.
05-Dec-2012 12:23:35.744 automatic empty zone: 255.255.
05-Dec-2012 12:23:35.744 automatic empty zone: 0.0.0.0.
05-Dec-2012 12:23:35.744 automatic empty zone: 1.0.0.0.
05-Dec-2012 12:23:35.744 automatic empty zone: D.F.IP6.ARPA
05-Dec-2012 12:23:35.744 automatic empty zone: 8.E.F.IP6.ARPA
05-Dec-2012 12:23:35.744 automatic empty zone: 9.E.F.IP6.ARPA
05-Dec-2012 12:23:35.744 automatic empty zone: A.E.F.IP6.ARPA
05-Dec-2012 12:23:35.744 automatic empty zone: B.E.F.IP6.ARPA
05-Dec-2012 12:23:35.744 automatic empty zone: 8.B.D.0.
05-Dec-2012 12:23:35.749 command channel listening on 127.0.0.1#953
05-Dec-2012 12:23:35.749 command channel listening on ::1#953
05-Dec-2012 12:23:35.749 the working directory is not writable
05-Dec-2012 12:23:35.749 ignoring config file logging statement due to -g option
05-Dec-2012 12:23:35.750 zone 0.in-addr.arpa/IN: loaded serial 1
05-Dec-2012 12:23:35.750 zone 157.10.
05-Dec-2012 12:23:35.751 zone 127.in-
05-Dec-2012 12:23:35.752 zone 255.in-
05-Dec-2012 12:23:35.753 zone extility.
05-Dec-2012 12:23:35.754 zone localhost/IN: loaded serial 2
05-Dec-2012 12:23:35.754 managed-keys-zone ./IN: loading from master file managed-keys.bind failed: file not found
05-Dec-2012 12:23:35.754 managed-
05-Dec-2012 12:23:35.754 managed-keys-zone ./IN: sync_keyzone: