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:
Aug 18 19:48:40 gw /bsd: OpenBSD 4.4-beta (GENERIC) #1004: Thu Jul 31 00:42:16
MDT 2008
Aug 18 19:48:42 gw /bsd: [EMAIL
PROTECTED]:/usr/src/sys/arch/i386/compile/GENERIC
Aug 18 19:48:43 gw /bsd: cpu0: Geode(TM) Integrated Processor by AMD PCS
("AuthenticAMD" 586-class) 432 MHz
Aug 18 19:48:45 gw /bsd: cpu0: FPU,DE,PSE,TSC,MSR,CX8,SEP,PGE,CMOV,CFLUSH,MMX
Aug 18 19:48:48 gw /bsd: real mem = 133791744 (127MB)
Aug 18 19:48:48 gw /bsd: avail mem = 120950784 (115MB)
Aug 18 19:48:55 gw /bsd: mainbus0 at root
Aug 18 19:48:55 gw /bsd: bios0 at mainbus0: AT/286+ BIOS, date 12/10/07, BIOS32
rev. 0 @ 0xfceb2
Aug 18 19:48:56 gw /bsd: pcibios0 at bios0: rev 2.1 @ 0xf0000/0x10000
Aug 18 19:48:57 gw /bsd: pcibios0: pcibios_get_intr_routing - function not
supported
Aug 18 19:48:57 gw /bsd: pcibios0: PCI IRQ Routing information unavailable.
Aug 18 19:48:58 gw /bsd: pcibios0: PCI bus #0 is the last bus
Aug 18 19:48:58 gw /bsd: bios0: ROM list: 0xe0000/0xa800
Aug 18 19:48:59 gw /bsd: cpu0 at mainbus0
Aug 18 19:48:59 gw /bsd: pci0 at mainbus0 bus 0: configuration mode 1 (bios)
Aug 18 19:49:00 gw /bsd: pchb0 at pci0 dev 1 function 0 "AMD Geode LX" rev 0x31
Aug 18 19:49:00 gw /bsd: glxsb0 at pci0 dev 1 function 2 "AMD Geode LX Crypto"
rev 0x00: RNG AES
Aug 18 19:49:01 gw /bsd: vr0 at pci0 dev 9 function 0 "VIA VT6105M RhineIII"
rev 0x96: irq 10, address 00:0d:b9:12:9f:2c
Aug 18 19:49:01 gw /bsd: ukphy0 at vr0 phy 1: Generic IEEE 802.3u media
interface, rev. 3: OUI 0x004063, model 0x0034
Aug 18 19:49:02 gw /bsd: vr1 at pci0 dev 10 function 0 "VIA VT6105M RhineIII"
rev 0x96: irq 11, address 00:0d:b9:12:9f:2d
Aug 18 19:49:02 gw /bsd: ukphy1 at vr1 phy 1: Generic IEEE 802.3u media
interface, rev. 3: OUI 0x004063, model 0x0034
Aug 18 19:49:03 gw /bsd: vr2 at pci0 dev 11 function 0 "VIA VT6105M RhineIII"
rev 0x96: irq 12, address 00:0d:b9:12:9f:2e
Aug 18 19:49:03 gw /bsd: ukphy2 at vr2 phy 1: Generic IEEE 802.3u media
interface, rev. 3: OUI 0x004063, model 0x0034
Aug 18 19:49:04 gw /bsd: glxpcib0 at pci0 dev 15 function 0 "AMD CS5536 ISA"
rev 0x03: rev 0, 32-bit 3579545Hz timer, watchdog, gpio
Aug 18 19:49:04 gw /bsd: gpio0 at glxpcib0: 32 pins
Aug 18 19:49:05 gw /bsd: pciide0 at pci0 dev 15 function 2 "AMD CS5536 IDE" rev
0x01: DMA, channel 0 wired to compatibility, channel 1 wired to compatibility
Aug 18 19:49:05 gw /bsd: wd0 at pciide0 channel 0 drive 0: <CF CARD 4GB>
Aug 18 19:49:05 gw /bsd: wd0: 1-sector PIO, LBA, 3871MB, 7928928 sectors
Aug 18 19:49:06 gw /bsd: wd0(pciide0:0:0): using PIO mode 4, DMA mode 2
Aug 18 19:49:06 gw /bsd: pciide0: channel 1 ignored (disabled)
Aug 18 19:49:07 gw /bsd: ohci0 at pci0 dev 15 function 4 "AMD CS5536 USB" rev
0x02: irq 15, version 1.0, legacy support
Aug 18 19:49:08 gw /bsd: ehci0 at pci0 dev 15 function 5 "AMD CS5536 USB" rev
0x02: irq 15
Aug 18 19:49:09 gw /bsd: usb0 at ehci0: USB revision 2.0
Aug 18 19:49:09 gw /bsd: uhub0 at usb0 "AMD EHCI root hub" rev 2.00/1.00 addr 1
Aug 18 19:49:10 gw /bsd: isa0 at glxpcib0
Aug 18 19:49:10 gw /bsd: isadma0 at isa0
Aug 18 19:49:14 gw /bsd: com0 at isa0 port 0x3f8/8 irq 4: ns16550a, 16 byte fifo
Aug 18 19:49:15 gw /bsd: com0: console
Aug 18 19:49:15 gw /bsd: pcppi0 at isa0 port 0x61
Aug 18 19:49:16 gw /bsd: midi0 at pcppi0: <PC speaker>
Aug 18 19:49:17 gw /bsd: spkr0 at pcppi0
Aug 18 19:49:20 gw /bsd: npx0 at isa0 port 0xf0/16: reported by CPUID; using
exception 16
Aug 18 19:49:23 gw /bsd: usb1 at ohci0: USB revision 1.0
Aug 18 19:49:24 gw /bsd: uhub1 at usb1 "AMD OHCI root hub" rev 1.00/1.00 addr 1
Aug 18 19:49:25 gw /bsd: biomask e3ef netmask ffef ttymask ffff
Aug 18 19:49:25 gw /bsd: mtrr: K6-family MTRR support (2 registers)
Aug 18 19:49:26 gw /bsd: nvram: invalid checksum
Aug 18 19:49:28 gw /bsd: softraid0 at root
Aug 18 19:49:30 gw /bsd: root on wd0a swap on wd0b dump on wd0b
Aug 18 19:49:31 gw /bsd: clock: unknown CMOS layout
Aug 18 19:48:48 gw pflogd[15005]: [priv]: msg PRIV_OPEN_LOG received
# named staring here
Aug 18 19:48:58 gw named[15560]: starting BIND 9.4.2-P1
Aug 18 19:49:03 gw named[15560]: loading configuration from '/etc/named.conf'
Aug 18 19:49:03 gw named[15560]: listening on IPv6 interfaces, port 53
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface lo0, 127.0.0.1#53
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface vr0,
192.167.167.1#53
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface vr1,
192.168.111.1#53
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface vr2,
192.168.222.1#53
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:04 gw named[15560]: Binding privsep
Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:05 gw named[15560]: Binding locally
Aug 18 19:49:05 gw named[15560]: Binding locally
Aug 18 19:49:06 gw named[15560]: automatic empty zone: view internal:
254.169.IN-ADDR.ARPA
Aug 18 19:49:06 gw named[15560]: automatic empty zone: view internal:
2.0.192.IN-ADDR.ARPA
Aug 18 19:49:06 gw named[15560]: automatic empty zone: view internal:
255.255.255.255.IN-ADDR.ARPA
# took about 8 seconds up to here; but then
Aug 18 19:49:31 gw named[15560]: 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
# what could possibly take 25 seconds when loading an automatic empty zone?
Aug 18 19:49:31 gw named[15560]: 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 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
D.F.IP6.ARPA
Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
8.E.F.IP6.ARPA
Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
9.E.F.IP6.ARPA
Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
A.E.F.IP6.ARPA
Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
B.E.F.IP6.ARPA
Aug 18 19:49:31 gw named[15560]: Binding privsep
Aug 18 19:49:31 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:31 gw named[15560]: command channel listening on 127.0.0.1#953
Aug 18 19:49:31 gw named[15560]: Binding privsep
Aug 18 19:49:31 gw named[29233]: [priv]: msg PRIV_BIND received
Aug 18 19:49:31 gw named[15560]: command channel listening on ::1#953
Aug 18 19:49:31 gw named[15560]: zone 127.in-addr.arpa/IN/internal: loaded
serial 1
Aug 18 19:49:31 gw named[15560]: zone 111.168.192.in-addr.arpa/IN/internal:
loaded serial 1
Aug 18 19:49:31 gw named[15560]: zone 222.168.192.in-addr.arpa/IN/internal:
loaded serial 1
Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/internal: loaded serial
2008060101
Aug 18 19:49:31 gw named[15560]: zone localhost/IN/internal: loaded serial 1
Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/external: loaded serial
2008052901
Aug 18 19:49:31 gw named[15560]: running
Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/internal: sending notifies
(serial 2008060101)
Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/external: sending notifies
(serial 2008052901)
Aug 18 19:49:31 gw named[15560]: client 79.98.73.150#7375: view external:
received notify for zone 'stare.cz'
Aug 18 19:49:31 gw ntpd[26108]: ntp engine ready
Aug 18 19:49:31 gw named[15560]: Binding locally
# This message keeps appearing in the log even after bootup.
Aug 18 19:49:32 gw last message repeated 3 times
Aug 18 19:49:33 gw ntpd[13902]: set local clock to Mon Aug 18 19:49:33 CEST
2008 (offset 1.270602s)
Aug 18 19:49:34 gw savecore: /dev/wd0b: Device not configured
Aug 18 19:49:37 gw sshd[9870]: Server listening on 192.167.167.1 port 2222.
Aug 18 19:49:37 gw sshd[9870]: Server listening on 192.168.222.1 port 22.
Aug 18 19:49:37 gw sshd[9870]: Server listening on 192.168.111.1 port 22.
Aug 18 19:49:37 gw cron[26797]: (CRON) STARTUP (V5.0)
Aug 18 19:49:39 gw postfix/postfix-script[31730]: starting the Postfix mail
system
Aug 18 19:49:39 gw postfix/master[29430]: daemon started -- version 2.5.1,
configuration /etc/postfix
Aug 18 19:49:49 gw login: ROOT LOGIN (root) ON tty00
Aug 18 19:49:52 gw ntpd[26108]: peer 147.251.48.140 now valid
Aug 18 19:49:54 gw ntpd[26108]: peer 84.242.87.238 now valid
Aug 18 19:49:57 gw ntpd[26108]: peer 212.71.128.157 now valid
Aug 18 19:50:08 gw named[15560]: Binding locally
Aug 18 19:50:09 gw last message repeated 2 times
Aug 18 19:52:28 gw last message repeated 3 times
Aug 18 19:54:28 gw last message repeated 4 times
Aug 18 19:55:05 gw ntpd[26108]: clock is now synced
Aug 18 19:56:31 gw named[15560]: Binding locally
Aug 18 19:56:54 gw last message repeated 10 times
So, my questions are:
1. What could possibly cause the 25s gap when loading an automatic empty zone?
The BIND configuration is not complicated - two views (internal, external)
of one zone.
2. Why does BIND keep 'binding locally'?
Thanks
Jan
