On Wed, Aug 20, 2008 at 05:36:36PM +0200, Jan Stary wrote: > On Aug 20 15:36:36, Otto Moerbeek wrote: > > > 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: > > > > I expect it to be the extra randomization that named does. Since some > > time, at startup, it builds a table that is used to randomize id's. > > This is computationally a bit expensive, and you could notice it on a > > slow host. > > Sounds very probable. > > > The extra binding messages could very well be caused by the source > > port randomizations done now. You seem to use a pretty high debug log > > level. > > Indeed, > > logging { > channel syslog_channel { > syslog local0; > severity info; > print-category no; > print-severity no; > print-time no; > }; > > I just bumped severity to even debug, and restarted named > (pkill named, sleep, named) while looking at the log to > confirm your explanation; named now starts in one second: > > Aug 20 17:22:23 gw named[32687]: exiting > Aug 20 17:22:31 gw named[29116]: starting BIND 9.4.2-P1 > Aug 20 17:22:31 gw named[29116]: loading configuration from '/etc/named.conf' > Aug 20 17:22:31 gw named[29116]: listening on IPv6 interfaces, port 53 > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: listening on IPv4 interface lo0, 127.0.0.1#53 > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: listening on IPv4 interface vr0, > 192.167.167.1#53 > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: listening on IPv4 interface vr1, > 192.168.111.1#53 > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: listening on IPv4 interface vr2, > 192.168.222.1#53 > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: Binding locally > Aug 20 17:22:31 gw named[29116]: Binding locally > Aug 20 17:22:31 gw named[29116]: automatic empty zone: view internal: > 254.169.IN-ADDR.ARPA > Aug 20 17:22:31 gw named[29116]: automatic empty zone: view internal: > 2.0.192.IN-ADDR.ARPA > Aug 20 17:22:31 gw named[29116]: automatic empty zone: view internal: > 255.255.255.255.IN-ADDR.ARPA > Aug 20 17:22:31 gw named[29116]: 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 > Aug 20 17:22:31 gw named[29116]: 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 20 17:22:31 gw named[29116]: automatic empty zone: view internal: > D.F.IP6.ARPA > Aug 20 17:22:31 gw named[29116]: automatic empty zone: view internal: > 8.E.F.IP6.ARPA > Aug 20 17:22:31 gw named[29116]: automatic empty zone: view internal: > 9.E.F.IP6.ARPA > Aug 20 17:22:31 gw named[29116]: automatic empty zone: view internal: > A.E.F.IP6.ARPA > Aug 20 17:22:31 gw named[29116]: automatic empty zone: view internal: > B.E.F.IP6.ARPA > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: command channel listening on 127.0.0.1#953 > Aug 20 17:22:31 gw named[29116]: Binding privsep > Aug 20 17:22:31 gw named[3931]: [priv]: msg PRIV_BIND received > Aug 20 17:22:31 gw named[29116]: command channel listening on ::1#953 > Aug 20 17:22:31 gw named[29116]: now using logging configuration from config > file > Aug 20 17:22:31 gw named[29116]: load_configuration: success > Aug 20 17:22:31 gw named[29116]: zone 127.in-addr.arpa/IN/internal: starting > load > Aug 20 17:22:31 gw named[29116]: zone 127.in-addr.arpa/IN/internal: journal > rollforward completed successfully: no journal > Aug 20 17:22:31 gw named[29116]: zone 127.in-addr.arpa/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone 127.in-addr.arpa/IN/internal: loaded > serial 1 > Aug 20 17:22:31 gw named[29116]: zone 254.169.IN-ADDR.ARPA/IN/internal: > starting load > Aug 20 17:22:31 gw named[29116]: zone 254.169.IN-ADDR.ARPA/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone 2.0.192.IN-ADDR.ARPA/IN/internal: > starting load > Aug 20 17:22:31 gw named[29116]: zone 2.0.192.IN-ADDR.ARPA/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone 111.168.192.in-addr.arpa/IN/internal: > starting load > Aug 20 17:22:31 gw named[29116]: zone 111.168.192.in-addr.arpa/IN/internal: > journal rollforward completed successfully: no journal > Aug 20 17:22:31 gw named[29116]: zone 111.168.192.in-addr.arpa/IN/internal: > loaded > Aug 20 17:22:31 gw named[29116]: zone 111.168.192.in-addr.arpa/IN/internal: > loaded serial 1 > Aug 20 17:22:31 gw named[29116]: zone 222.168.192.in-addr.arpa/IN/internal: > starting load > Aug 20 17:22:31 gw named[29116]: zone 222.168.192.in-addr.arpa/IN/internal: > journal rollforward completed successfully: no journal > Aug 20 17:22:31 gw named[29116]: zone 222.168.192.in-addr.arpa/IN/internal: > loaded > Aug 20 17:22:31 gw named[29116]: zone 222.168.192.in-addr.arpa/IN/internal: > loaded serial 1 > Aug 20 17:22:31 gw named[29116]: zone > 255.255.255.255.IN-ADDR.ARPA/IN/internal: starting load > Aug 20 17:22:31 gw named[29116]: zone > 255.255.255.255.IN-ADDR.ARPA/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: 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/IN/internal: > starting load > Aug 20 17:22:31 gw named[29116]: 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/IN/internal: > loaded > Aug 20 17:22:31 gw named[29116]: 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/IN/internal: > starting load > Aug 20 17:22:31 gw named[29116]: 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/IN/internal: > loaded > Aug 20 17:22:31 gw named[29116]: zone D.F.IP6.ARPA/IN/internal: starting load > Aug 20 17:22:31 gw named[29116]: zone D.F.IP6.ARPA/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone 8.E.F.IP6.ARPA/IN/internal: starting > load > Aug 20 17:22:31 gw named[29116]: zone 8.E.F.IP6.ARPA/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone 9.E.F.IP6.ARPA/IN/internal: starting > load > Aug 20 17:22:31 gw named[29116]: zone 9.E.F.IP6.ARPA/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone A.E.F.IP6.ARPA/IN/internal: starting > load > Aug 20 17:22:31 gw named[29116]: zone A.E.F.IP6.ARPA/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone B.E.F.IP6.ARPA/IN/internal: starting > load > Aug 20 17:22:31 gw named[29116]: zone B.E.F.IP6.ARPA/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone stare.cz/IN/internal: starting load > Aug 20 17:22:31 gw named[29116]: zone stare.cz/IN/internal: journal > rollforward completed successfully: no journal > Aug 20 17:22:31 gw named[29116]: zone stare.cz/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone stare.cz/IN/internal: loaded serial > 2008060101 > Aug 20 17:22:31 gw named[29116]: zone localhost/IN/internal: starting load > Aug 20 17:22:31 gw named[29116]: zone localhost/IN/internal: journal > rollforward completed successfully: no journal > Aug 20 17:22:31 gw named[29116]: zone localhost/IN/internal: loaded > Aug 20 17:22:31 gw named[29116]: zone localhost/IN/internal: loaded serial 1 > Aug 20 17:22:31 gw named[29116]: zone stare.cz/IN/external: starting load > Aug 20 17:22:31 gw named[29116]: zone stare.cz/IN/external: journal > rollforward completed successfully: no journal > Aug 20 17:22:31 gw named[29116]: zone stare.cz/IN/external: loaded > Aug 20 17:22:31 gw named[29116]: zone stare.cz/IN/external: loaded serial > 2008052901 > Aug 20 17:22:31 gw named[29116]: zone authors.bind/CH: starting load > Aug 20 17:22:31 gw named[29116]: zone authors.bind/CH: loaded > Aug 20 17:22:31 gw named[29116]: zone hostname.bind/CH: starting load > Aug 20 17:22:31 gw named[29116]: zone hostname.bind/CH: loaded > Aug 20 17:22:31 gw named[29116]: zone version.bind/CH: starting load > Aug 20 17:22:31 gw named[29116]: zone version.bind/CH: loaded > Aug 20 17:22:31 gw named[29116]: zone id.server/CH: starting load > Aug 20 17:22:31 gw named[29116]: zone id.server/CH: loaded > Aug 20 17:22:31 gw named[29116]: dns_zone_maintenance: zone > localhost/IN/internal: enter > [ ... lots of these ... ] > Aug 20 17:22:31 gw named[29116]: running > > There is none of that slowdown I experienced when the whole > machine was booting up. What could be the difference?
It could be blocking on reading the random device. At booting, not much entropy has been collected yet. -Otto > > A log of a regular query seems to confirm > your explanation of the binding messages: > > Aug 20 17:31:02 gw named[29116]: createfetch: microsoft.com A > Aug 20 17:31:02 gw named[29116]: Binding locally > Aug 20 17:31:02 gw named[29116]: createfetch: microsoft.com AAAA > Aug 20 17:31:02 gw named[29116]: Binding locally > Aug 20 17:31:02 gw named[29116]: createfetch: microsoft.com MX > Aug 20 17:31:02 gw named[29116]: Binding locally > > Thanks a lot for the insight > > Jan