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
