Replying to myself, On Aug 18 20:51:26, Jan Stary wrote: > This is -current as of a few weeks back, running on ALIX2C3. > Works smoothly as my home router/fw/dns, but when booting > gets to starting named, there is a strange slowdown: <snip> > Aug 18 19:48:58 gw named[15560]: starting BIND 9.4.2-P1 > Aug 18 19:49:03 gw named[15560]: loading configuration from '/etc/named.conf' > Aug 18 19:49:03 gw named[15560]: listening on IPv6 interfaces, port 53 > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface lo0, 127.0.0.1#53 > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface vr0, > 192.167.167.1#53 > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface vr1, > 192.168.111.1#53 > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface vr2, > 192.168.222.1#53 > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:04 gw named[15560]: Binding privsep > Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:05 gw named[15560]: Binding locally > Aug 18 19:49:05 gw named[15560]: Binding locally > Aug 18 19:49:06 gw named[15560]: automatic empty zone: view internal: > 254.169.IN-ADDR.ARPA > Aug 18 19:49:06 gw named[15560]: automatic empty zone: view internal: > 2.0.192.IN-ADDR.ARPA > Aug 18 19:49:06 gw named[15560]: automatic empty zone: view internal: > 255.255.255.255.IN-ADDR.ARPA > > # took about 8 seconds up to here; but then > > Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal: > 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 > > # what could possibly take 25 seconds when loading an automatic empty zone?
Could we possibly be waiting for 'ntpd -s'? See: > Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal: > 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 > Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal: > D.F.IP6.ARPA > Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal: > 8.E.F.IP6.ARPA > Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal: > 9.E.F.IP6.ARPA > Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal: > A.E.F.IP6.ARPA > Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal: > B.E.F.IP6.ARPA > Aug 18 19:49:31 gw named[15560]: Binding privsep > Aug 18 19:49:31 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:31 gw named[15560]: command channel listening on 127.0.0.1#953 > Aug 18 19:49:31 gw named[15560]: Binding privsep > Aug 18 19:49:31 gw named[29233]: [priv]: msg PRIV_BIND received > Aug 18 19:49:31 gw named[15560]: command channel listening on ::1#953 > Aug 18 19:49:31 gw named[15560]: zone 127.in-addr.arpa/IN/internal: loaded > serial 1 > Aug 18 19:49:31 gw named[15560]: zone 111.168.192.in-addr.arpa/IN/internal: > loaded serial 1 > Aug 18 19:49:31 gw named[15560]: zone 222.168.192.in-addr.arpa/IN/internal: > loaded serial 1 > Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/internal: loaded serial > 2008060101 > Aug 18 19:49:31 gw named[15560]: zone localhost/IN/internal: loaded serial 1 > Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/external: loaded serial > 2008052901 > Aug 18 19:49:31 gw named[15560]: running > Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/internal: sending notifies > (serial 2008060101) > Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/external: sending notifies > (serial 2008052901) > Aug 18 19:49:31 gw named[15560]: client 79.98.73.150#7375: view external: > received notify for zone 'stare.cz' > Aug 18 19:49:31 gw ntpd[26108]: ntp engine ready The timestamp when named spoke again is the same time when ntpd said 'ntp engine ready'. It is started as 'ntpd -s'; is there any interaction between ntpd and named during startup, or is this just a coincidence? > Aug 18 19:49:31 gw named[15560]: Binding locally > # This message keeps appearing in the log even after bootup. > > Aug 18 19:49:32 gw last message repeated 3 times > Aug 18 19:49:33 gw ntpd[13902]: set local clock to Mon Aug 18 19:49:33 CEST > 2008 (offset 1.270602s) > Aug 18 19:49:34 gw savecore: /dev/wd0b: Device not configured > Aug 18 19:49:37 gw sshd[9870]: Server listening on 192.167.167.1 port 2222. > Aug 18 19:49:37 gw sshd[9870]: Server listening on 192.168.222.1 port 22. > Aug 18 19:49:37 gw sshd[9870]: Server listening on 192.168.111.1 port 22. > Aug 18 19:49:37 gw cron[26797]: (CRON) STARTUP (V5.0) > Aug 18 19:49:39 gw postfix/postfix-script[31730]: starting the Postfix mail > system > Aug 18 19:49:39 gw postfix/master[29430]: daemon started -- version 2.5.1, > configuration /etc/postfix > Aug 18 19:49:49 gw login: ROOT LOGIN (root) ON tty00 > Aug 18 19:49:52 gw ntpd[26108]: peer 147.251.48.140 now valid > Aug 18 19:49:54 gw ntpd[26108]: peer 84.242.87.238 now valid > Aug 18 19:49:57 gw ntpd[26108]: peer 212.71.128.157 now valid > Aug 18 19:50:08 gw named[15560]: Binding locally > Aug 18 19:50:09 gw last message repeated 2 times > Aug 18 19:52:28 gw last message repeated 3 times > Aug 18 19:54:28 gw last message repeated 4 times > Aug 18 19:55:05 gw ntpd[26108]: clock is now synced > Aug 18 19:56:31 gw named[15560]: Binding locally > Aug 18 19:56:54 gw last message repeated 10 times > 2. Why does BIND keep 'binding locally'? Thanks Jan