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
