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? 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