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

Reply via email to