Long delays during bootup in -current

I'm seeing long delays during bootup of the INSTALL kernel
in - 
current. This is on a PowerPC Mac mini.

timecounter: Timecounter "clockinterrupt"
frequency 100 Hz quality 0
timecounter: selected timecounter "clockinterrupt"
frequency 100 Hz  
quality 0
timecounter: Timecounter "mftb" frequency 41600661
Hz quality 0
timecounter: selected timecounter "mftb" frequency
41600661 Hz quality 0
md0: internal 2048 KB image area
Kernelized RAIDframe activated

<<<<<<<<<LONG
DELAY>>>>>>>>>>>>>>
;>>>

atapibus0 at atabus1: 2 targets
cd0 at atapibus0 drive 1: <MATSHITACD-RW  CW-8124, ,
DACD> cdrom  
removable
cd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 2
(Ultra/33)
wd0 at atabus1 drive 0: <Hitachi HTS541080G9AT00>

Has anyone else seen this?

Thanks
Sanjay

On Sun, Oct 08, 2006 at 08:12:20AM -0700, Sanjay Lal wrote:
> I'm seeing long delays during bootup of the INSTALL
kernel in - 
> current. This is on a PowerPC Mac mini.
> 
> timecounter: Timecounter "clockinterrupt"
frequency 100 Hz quality 0
> timecounter: selected timecounter
"clockinterrupt" frequency 100 Hz  
> quality 0
> timecounter: Timecounter "mftb" frequency
41600661 Hz quality 0
> timecounter: selected timecounter "mftb"
frequency 41600661 Hz quality 0
> md0: internal 2048 KB image area
> Kernelized RAIDframe activated
> 
> <<<<<<<<<LONG
DELAY>>>>>>>>>>>>>>
;>>>

How much long ? maybe 30s ?

> 
> atapibus0 at atabus1: 2 targets

Is there an atabus0 ? To what is it attached ? Is there any
drive attached
to atabus0 ?

-- 
Manuel Bouyer <bouyerantioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la
difference
--

Please see my comments inline...

On Oct 8, 2006, at 3:33 PM, Manuel Bouyer wrote:

> On Sun, Oct 08, 2006 at 08:12:20AM -0700, Sanjay Lal
wrote:
>> I'm seeing long delays during bootup of the INSTALL
kernel in -
>> current. This is on a PowerPC Mac mini.
>>
>> timecounter: Timecounter "clockinterrupt"
frequency 100 Hz quality 0
>> timecounter: selected timecounter
"clockinterrupt" frequency 100 Hz
>> quality 0
>> timecounter: Timecounter "mftb" frequency
41600661 Hz quality 0
>> timecounter: selected timecounter "mftb"
frequency 41600661 Hz  
>> quality 0
>> md0: internal 2048 KB image area
>> Kernelized RAIDframe activated
>>
>> <<<<<<<<<LONG
DELAY>>>>>>>>>>>>>>
;>>>
>
> How much long ? maybe 30s ?

More like ~90 secs.

>
>>
>> atapibus0 at atabus1: 2 targets
>
> Is there an atabus0 ? To what is it attached ? Is there
any drive  
> attached
> to atabus0 ?

Yep, there is a atabus0, it is attached to wdc0 which is
attached to  
obio0. Here is the entire dmesg:

Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002,
2003, 2004,  
2005, 2006
     The NetBSD Foundation, Inc.  All rights reserved.
Copyright (c) 1982, 1986, 1989, 1991, 1993
     The Regents of the University of California.  All
rights reserved.

NetBSD 4.99.3 (INSTALL) #0: Sun Oct  8 07:31:08 PDT 2006
	sanjaylkyma-serv1.kymasys.com:/home/sanjayl/WORKSPACE/kyma/n
etbsd- 
current/src/sys/arch/macppc/compile/INSTALL
total memory = 512 MB
avail memory = 490 MB
timecounter: Timecounters tick every 10.000 msec
init_interrupt: found OpenPIC  pa 0x80040000, 0x80040000
mainbus0 (root)
cpu0 at mainbus0: 7447A (Revision 1.5), ID 0 (primary)
cpu0: HID0  
8450c0bc<EMCP,EICE,NAP,DPM,ICE,DCE,SGE,BTIC,FBIOB,ABE,BHT
>, powersave: 1
cpu0: 1500.01 MHz, 512KB L2 cache
uninorth0 at mainbus0
pci0 at uninorth0 bus 0
pci0: i/o space, memory space enabled
pchb0 at pci0 dev 11 function 0
pchb0: vendor 0x106b product 0x0034 (rev. 0x00)
ofb0 at pci0 dev 16 function 0: vendor 0x1002 product 0x5962
ofb0: 1280 x 1024, 8bpp
wsdisplay0 at ofb0 kbdmux 1: console (std, vt100 emulation)
wsmux1: connecting to wsdisplay0
uninorth1 at mainbus0
pci1 at uninorth1 bus 0
pci1: i/o space, memory space enabled
pchb1 at pci1 dev 11 function 0
pchb1: vendor 0x106b product 0x0035 (rev. 0x00)
vendor 0x14e4 product 0x4318 (miscellaneous network,
revision 0x02)  
at pci1 dev 18 function 0 not configured
obio0 at pci1 dev 23 function 0: addr 0x80000000
zsc0 at obio0: irq 22,23
zstty0 at zsc0 channel 0
zstty1 at zsc0 channel 1
i2s at obio0 offset 0x10000 not configured
adb0 at obio0 offset 0x16000 irq 47: pm_adb_op: timeout.
command = 0x0
pmu: failed to read prim-info
0 targets
wdc0 at obio0 offset 0x20000 irq 24: DMA transfer
atabus0 at wdc0 channel 0
ohci0 at pci1 dev 24 function 0: vendor 0x106b product
0x003f (rev.  
0x00)
ohci0: can't map mem space
ohci1 at pci1 dev 25 function 0: vendor 0x106b product
0x003f (rev.  
0x00)
ohci1: can't map mem space
ohci2 at pci1 dev 26 function 0: vendor 0x106b product
0x003f (rev.  
0x00)
ohci2: interrupting at irq 29
ohci2: OHCI version 1.0, legacy support
usb0 at ohci2: USB revision 1.0
uhub0 at usb0
uhub0: vendor 0x106b OHCI root hub, class 9/0, rev
1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
ohci3 at pci1 dev 27 function 0: vendor 0x1033 product
0x0035 (rev.  
0x43)
ohci3: interrupting at irq 63
ohci3: OHCI version 1.0
usb1 at ohci3: USB revision 1.0
uhub1 at usb1
uhub1: vendor 0x1033 OHCI root hub, class 9/0, rev
1.00/1.00, addr 1
uhub1: 3 ports with 3 removable, self powered
ohci4 at pci1 dev 27 function 1: vendor 0x1033 product
0x0035 (rev.  
0x43)
ohci4: interrupting at irq 63
ohci4: OHCI version 1.0
usb2 at ohci4: USB revision 1.0
uhub2 at usb2
uhub2: vendor 0x1033 OHCI root hub, class 9/0, rev
1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
vendor 0x1033 product 0x00e0 (USB serial bus, interface
0x20,  
revision 0x04) at pci1 dev 27 function 2 not configured
uninorth2 at mainbus0
pci2 at uninorth2 bus 0
pci2: i/o space, memory space enabled
pchb2 at pci2 dev 11 function 0
pchb2: vendor 0x106b product 0x0036 (rev. 0x00)
wdc1 at pci2 dev 13 function 0: interrupting at irq 39
atabus1 at wdc1 channel 0
vendor 0x106b product 0x0031 (Firewire serial bus, interface
0x10,  
revision 0x81) at pci2 dev 14 function 0 not configured
gem0 at pci2 dev 15 function 0: vendor 0x106b product 0x0032
(rev. 0x80)
gem0: interrupting at irq 41
gem0: Ethernet address 00:11:24:d1:c7:b8, 10KB RX fifo, 4KB
TX fifo
bmtphy0 at gem0 phy 0: BCM5221 10/100 media interface, rev.
4
bmtphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX,
auto
timecounter: Timecounter "clockinterrupt"
frequency 100 Hz quality 0
timecounter: selected timecounter "clockinterrupt"
frequency 100 Hz  
quality 0
timecounter: Timecounter "mftb" frequency 41600661
Hz quality 0
timecounter: selected timecounter "mftb" frequency
41600661 Hz quality 0
md0: internal 2048 KB image area
Kernelized RAIDframe activated
atapibus0 at atabus1: 2 targets
cd0 at atapibus0 drive 1: <MATSHITACD-RW  CW-8124, ,
DACD> cdrom  
removable
cd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 2
(Ultra/33)
wd0 at atabus1 drive 0: <Hitachi HTS541080G9AT00>
wd0: drive supports 16-sector PIO transfers, LBA48
addressing
wd0: 76319 MB, 155061 cyl, 16 head, 63 sec, 512 bytes/sect x
 
156301488 sectors
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5
(Ultra/100)
wd0(wdc1:0:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode
5 (Ultra/ 
100) (using DMA)
cd0(wdc1:0:1): using PIO mode 4, DMA mode 2, Ultra-DMA mode
2 (Ultra/ 
33) (using DMA)
uhidev0 at uhub1 port 1 configuration 1 interface 0
uhidev0: Logitech USB Receiver, rev 1.10/17.00, addr 2,
iclass 3/1
uhidev1 at uhub0 port 1 configuration 1 interface 0
uhidev1: vendor 0x05ac product 0x1000, rev 2.00/19.65, addr
2, iclass  
3/1
ukbd0 at uhidev0
wskbd1 at ukbd0 mux 1
wskbd1: connecting to wsdisplay0
uhidev2 at uhub1 port 1 configuration 1 interface 1ukbd1 at
uhidev1
wskbd2 at ukbd1 mux 1
wskbd2: connecting to wsdisplay0
uhidev3 at uhub0 port 1 configuration 1 interface 1
uhidev3: vendor 0x05ac product 0x1000, rev 2.00/19.65, addr
2, iclass  
3/1

uhidev2: Logitech USB Receiver, rev 1.10/17.00, addr 2,
iclass 3/1
uhid at uhidev3 not configured
uhidev2: 4 report ids
uhid at uhidev2 reportid 1 not configured
uhid at uhidev2 reportid 2 not configured
uhid at uhidev2 reportid 3 not configured
uhid at uhidev2 reportid 4 not configured



Thanks,
Sanjay

>
> -- 
> Manuel Bouyer <bouyerantioche.eu.org>
>      NetBSD: 26 ans d'experience feront toujours la
difference
> --
>

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hello,

On Oct 8, 2006, at 19:28, Sanjay Lal wrote:

> Please see my comments inline...
>
> On Oct 8, 2006, at 3:33 PM, Manuel Bouyer wrote:
>
>> On Sun, Oct 08, 2006 at 08:12:20AM -0700, Sanjay
Lal wrote:
>>> I'm seeing long delays during bootup of the
INSTALL kernel in -
>>> current. This is on a PowerPC Mac mini.
>>>
>>> timecounter: Timecounter
"clockinterrupt" frequency 100 Hz quality 0
>>> timecounter: selected timecounter
"clockinterrupt" frequency 100 Hz
>>> quality 0
>>> timecounter: Timecounter "mftb"
frequency 41600661 Hz quality 0
>>> timecounter: selected timecounter
"mftb" frequency 41600661 Hz 
>>> quality 0
>>> md0: internal 2048 KB image area
>>> Kernelized RAIDframe activated
>>>
>>> <<<<<<<<<LONG
DELAY>>>>>>>>>>>>>>
;>>>
>>
>> How much long ? maybe 30s ?
>
> More like ~90 secs.

When the machine finally comes up - does the clock run at
the right 
speed? Maybe the timebase is wrong.

have fun
Michael
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.4 (Darwin)

iQEVAwUBRSmRg8pnzkX8Yg2nAQIIxgf+NcQBsUqIL6PZDDcl1qyKknr+bzYC
BW/P
ztKJubRu2aRdCJPm+dM6jqCKy+CXefa34WgE2fciOt9cask0EgGryN++Q63K
fIJX
ADX4kVP7Mlw9pWS80VoyabL4kJR6bIxlJd20+9vBhmtzpAKmXl5epNkkSL/2
uERI
qwcW677ESaGEMElZHVyr5XPkwe3a5iZJgL7jIbq8bfrncanYDYgc/5kxSjre
0yZU
QRM2Ia7I/fZpQzvBOVFehPVBFNF63zE94VJsnFhUjHMpiEPu4XQuxI7FxJY4
aKym
YIaWU5ZWzKU7m92Xpmny2qkruVDiSs7B4mvRhs4Xh1xOvEEhssM8Nw==
=rjjg
-----END PGP SIGNATURE-----

sanjaylkymasys.com wrote:

> I'm seeing long delays during bootup of the INSTALL
kernel in - 
> current. This is on a PowerPC Mac mini.
> 
> timecounter: Timecounter "clockinterrupt"
frequency 100 Hz quality 0
> timecounter: selected timecounter
"clockinterrupt" frequency 100 Hz  
> quality 0
> timecounter: Timecounter "mftb" frequency
41600661 Hz quality 0
> timecounter: selected timecounter "mftb"
frequency 41600661 Hz quality 0
> md0: internal 2048 KB image area
> Kernelized RAIDframe activated
> 
> <<<<<<<<<LONG
DELAY>>>>>>>>>>>>>>
;>>>
> 
> atapibus0 at atabus1: 2 targets
> cd0 at atapibus0 drive 1: <MATSHITACD-RW  CW-8124, ,
DACD> cdrom  
> removable
> cd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA
mode 2 (Ultra/33)
> wd0 at atabus1 drive 0: <Hitachi HTS541080G9AT00>
> 
> Has anyone else seen this?

How about the attached patch?

I'm not sure where PSL_EE is set in that case, but I think
hardclock(9) shouldn't be enabled until cpu_initclocks(9) is
called.
---
Izumi Tsutsui


Index: autoconf.c
============================================================
=======
RCS file: /cvsroot/src/sys/arch/macppc/macppc/autoconf.c,v
retrieving revision 1.48
diff -u -r1.48 autoconf.c
--- autoconf.c	29 Sep 2006 22:20:08 -0000	1.48
+++ autoconf.c	14 Oct 2006 13:30:46 -0000
 -69,7
+69,9 
 void
 cpu_configure()
 {
+#if 0
 	int msr;
+#endif
 
 	init_interrupt();
 	canonicalize_bootpath();
 -79,11
+81,13 
 
 	(void)spl0();
 
+#if 0
 	/*
 	 * Now allow hardware interrupts.
 	 */
 	__asm volatile ("mfmsr %0; ori %0,%0,%1; mtmsr
%0"
 		      : "=r"(msr) :
"K"(PSL_EE|PSL_RI));
+#endif
 }
 
 void

That fixed it!

Regards and thanks
Sanjay

On Oct 14, 2006, at 6:31 AM, Izumi Tsutsui wrote:

> sanjaylkymasys.com wrote:
>
>> I'm seeing long delays during bootup of the INSTALL
kernel in -
>> current. This is on a PowerPC Mac mini.
>>
>> timecounter: Timecounter "clockinterrupt"
frequency 100 Hz quality 0
>> timecounter: selected timecounter
"clockinterrupt" frequency 100 Hz
>> quality 0
>> timecounter: Timecounter "mftb" frequency
41600661 Hz quality 0
>> timecounter: selected timecounter "mftb"
frequency 41600661 Hz  
>> quality 0
>> md0: internal 2048 KB image area
>> Kernelized RAIDframe activated
>>
>> <<<<<<<<<LONG
DELAY>>>>>>>>>>>>>>
;>>>
>>
>> atapibus0 at atabus1: 2 targets
>> cd0 at atapibus0 drive 1: <MATSHITACD-RW 
CW-8124, , DACD> cdrom
>> removable
>> cd0: drive supports PIO mode 4, DMA mode 2,
Ultra-DMA mode 2  
>> (Ultra/33)
>> wd0 at atabus1 drive 0: <Hitachi
HTS541080G9AT00>
>>
>> Has anyone else seen this?
>
> How about the attached patch?
>
> I'm not sure where PSL_EE is set in that case, but I
think
> hardclock(9) shouldn't be enabled until
cpu_initclocks(9) is called.
> ---
> Izumi Tsutsui
>
>
> Index: autoconf.c
>
============================================================
=======
> RCS file:
/cvsroot/src/sys/arch/macppc/macppc/autoconf.c,v
> retrieving revision 1.48
> diff -u -r1.48 autoconf.c
> --- autoconf.c	29 Sep 2006 22:20:08 -0000	1.48
> +++ autoconf.c	14 Oct 2006 13:30:46 -0000
>  -69,7 +69,9 
>  void
>  cpu_configure()
>  {
> +#if 0
>  	int msr;
> +#endif
>
>  	init_interrupt();
>  	canonicalize_bootpath();
>  -79,11 +81,13 
>
>  	(void)spl0();
>
> +#if 0
>  	/*
>  	 * Now allow hardware interrupts.
>  	 */
>  	__asm volatile ("mfmsr %0; ori %0,%0,%1; mtmsr
%0"
>  		      : "=r"(msr) :
"K"(PSL_EE|PSL_RI));
> +#endif
>  }
>
>  void
>

sanjaylkymasys.com wrote:

> That fixed it!

Is it okay to commit the attached patch?

(though some other powerpc ports set PSL_EE in cpu_startup()
 after splraise(-1))
---
Izumi Tsutsui


Index: macppc/autoconf.c
============================================================
=======
RCS file: /cvsroot/src/sys/arch/macppc/macppc/autoconf.c,v
retrieving revision 1.48
diff -u -r1.48 autoconf.c
--- macppc/autoconf.c	29 Sep 2006 22:20:08 -0000	1.48
+++ macppc/autoconf.c	17 Oct 2006 15:06:14 -0000
 -69,7
+69,6 
 void
 cpu_configure()
 {
-	int msr;
 
 	init_interrupt();
 	canonicalize_bootpath();
 -78,12
+77,6 
 		panic("configure: mainbus not configured");
 
 	(void)spl0();
-
-	/*
-	 * Now allow hardware interrupts.
-	 */
-	__asm volatile ("mfmsr %0; ori %0,%0,%1; mtmsr
%0"
-		      : "=r"(msr) :
"K"(PSL_EE|PSL_RI));
 }
 
 void
Index: macppc/clock.c
============================================================
=======
RCS file: /cvsroot/src/sys/arch/macppc/macppc/clock.c,v
retrieving revision 1.32
diff -u -r1.32 clock.c
--- macppc/clock.c	13 Oct 2006 14:17:37 -0000	1.32
+++ macppc/clock.c	17 Oct 2006 15:06:14 -0000
 -70,6
+70,7 
 cpu_initclocks(void)
 {
 	struct cpu_info * const ci = curcpu();
+	uint32_t msr;
 
 	ticks_per_intr = ticks_per_sec / hz;
 	cpu_timebase = ticks_per_sec;
 -80,6
+81,12 
 		__asm volatile ("mftb %0" :
"=r"(ci->ci_lasttb));
 	__asm volatile ("mtdec %0" ::
"r"(ticks_per_intr));
 	init_macppc_tc();
+
+	/*
+	 * Now allow hardware interrupts.
+	 */
+	__asm volatile ("mfmsr %0; ori %0,%0,%1; mtmsr
%0"
+	    : "=r"(msr) : "K"(PSL_EE|PSL_RI));
 }
 
 /*
 -105,12
+112,6 
 	int nticks;
 
 	/*
-	 * Check whether we are initialized.
-	 */
-	if (cold)
-		return;
-		
-	/*
 	 * Based on the actual time delay since the last
decrementer reload,
 	 * we arrange for earlier interrupt next time.
 	 */

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hello,

On Oct 17, 2006, at 11:12, Izumi Tsutsui wrote:

> sanjaylkymasys.com wrote:
>
>> That fixed it!
>
> Is it okay to commit the attached patch?

Please commit. The if (cold) was just a workaround anyway,
if it's no 
longer needed all the better.

have fun]Michael
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.4 (Darwin)

iQEVAwUBRTUXrcpnzkX8Yg2nAQK41gf5AdyGL4TyORt9tl3uvkh1u5XtpQGf
Xq4b
5a2xcbBuxZIyKsJiZXiCraclGPoa+i2rpI6YPhLHCewrntEhBu5KnlvCdajX
5AYW
z/hxi5VmMEY6TxdI1qGW9dLjroo/EzVmpXm4MlbDQl9vlMnP9E1CuuhqfS5y
26sK
jtvSr8MFhZuUpILRPGDHDjpA07OKW4L4uSW49MgbKSIXUxtKTT3FxUHQ9x9o
Ja3L
1ue1XhS0F3cylX5Fa/zuQOuPwpRJ3GXoDg9zMU6lBi/obO0jC5U1MaQNhrgu
vh0Y
6YuI9vn8x8wnSp5LEXgO5oxa9EVA/dJwJtopsMg8bd4A9K4RjQx2rQ==
=vC0G
-----END PGP SIGNATURE-----

macallanNetBSD.org wrote:

> > Is it okay to commit the attached patch?
> 
> Please commit. The if (cold) was just a workaround
anyway, if it's no 
> longer needed all the better.

Done.

(BTW, doesn't prep have ths same problem? I can't test it
right now)
---
Izumi Tsutsui

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hello,

On Oct 19, 2006, at 10:36, Izumi Tsutsui wrote:

> macallanNetBSD.org wrote:
>
>>> Is it okay to commit the attached patch?
>>
>> Please commit. The if (cold) was just a workaround
anyway, if it's no
>> longer needed all the better.
>
> Done.
>
> (BTW, doesn't prep have ths same problem? I can't test
it right now)

I guess it does - otherwise the test in decr_intr() ( which
is present 
in prep's clock.c ) wouldn't make much sense. I'll bug Tim
about that.

have fun
Michael
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.4 (Darwin)

iQEVAwUBRTekbMpnzkX8Yg2nAQLD6Af/ZKcX92EitRxJZbX9Ix0vJ/Pl5crq
0SOJ
9rkTaUNT/fhHs3KtLNYGE6N92JRezps3G3tvTL/PqtHzrRtrteb/BQpDprqz
GWo5
I5evIsUSzdFgjKn4ckuxcspDSw6cqxV0qN91BJR17jOXJ6/BPcYL17K58DDB
qtPL
UAlFLdWR6OGdeYobFjfrgIfdAkmmJxcktz5pQAOSaJ5Py5rEG3MZAmv90aOH
Ryq2
ffe52PgIdPDz32eC6DAVNQbVV67BI9YUY607qRdA/iSSUFn/wBjkRF++Ba2z
Xxil
PYefLsNQussQKCI0lQK4M2CLg864imLJEwW5Xb4FmJkq1q6FGPyPoQ==
=Qs4y
-----END PGP SIGNATURE-----