Subject: port-i386/26365: on x86, delay()/DELAY() is off by a very large amount
To: None <gnats-bugs@gnats.NetBSD.org>
From: Paul Shupak <paul@Plectere.com>
List: netbsd-bugs
Date: 07/19/2004 04:38:14
>Number:         26365
>Category:       port-i386
>Synopsis:       on x86, delay()/DELAY() is off by a very large amount
>Confidential:   no
>Severity:       critical
>Priority:       high
>Responsible:    port-i386-maintainer
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Mon Jul 19 11:39:01 UTC 2004
>Closed-Date:
>Last-Modified:
>Originator:     Paul Shupak
>Release:        NetBSD 2.0G
>Organization:
	
>Environment:
	
	
System: NetBSD svcs 2.0G NetBSD 2.0G (SVCS) #239: Mon Jul 19 03:54:18 PDT 2004 root@svcs:/sys/arch/i386/compile/SVCS i386
Architecture: i386
Machine: i386
>Description:
	
	On at least some x86's, the actual time "delay"'d by delay(n)
	or DELAY(n) is (5 + n) usecs rounded UP to the nearest 5 usecs.
	ex. DELAY(0) is 5 usecs, DELAY(1) is 10 usecs, DELAY(6) is 15 usecs,
	    etc.

		Why?  On a machine which impliments actual ISA bus timings,
	no transaction (except string instructions) can complete in less
	than two (and usually three) bus cycles (still usually run at 8MHz
	for most super-IO/"south bridge" chips); One iteration through the
	loop in i8254_delay(), uses enough transactions to require 5 usecs
	( ~20 reads or writes at 2 cycles each, or ~13 ISA bus transactions
	at three cycles, some of each type in actuality).  Basically, the
	loop to test for termination of DELAY()/delay() should execute in no
	more than 1/2 a usec - The x86 code is TEN TIMES TOO SLOW to function
	properly.

	NOTE: Fixing this will speed up the common (not DMA or ECP) case of
	      printing ten fold (and reduce CPU usage equally).

>How-To-Repeat:
		The hacked-in instrumentation (added to i386/isa/clock.c to
	execute at the start of the kernel boot sequence) demonstrates the
	problem.  For a 850MHz P3, one microsecond is approximately 850 cycles.

		The instrumented code diffs are below with a "dmesg" output
	following:

--------------------------------------------------------------------------------
Index: clock.c
===================================================================
RCS file: /cvsroot/src/sys/arch/i386/isa/clock.c,v
retrieving revision 1.84
diff -c -r1.84 clock.c
*** clock.c	3 Jul 2004 18:24:37 -0000	1.84
--- clock.c	19 Jul 2004 11:25:06 -0000
***************
*** 296,301 ****
--- 296,326 ----
  	return (v3);
  }
  
+ static void testDelayTimes(void) ;
+ 
+ static void
+ testDelayTimes()
+ {
+ 	unsigned int trial ;
+ 	unsigned int delay_time ;
+ 	unsigned long long int res[9] ;
+ 
+ 	for ( delay_time = 0 ; delay_time <= 20 ; delay_time++ ) {
+ 		res[ 0 ] = rdtsc() ;
+ 		for ( trial = 0 ; trial < 8 ; ) {
+ 			DELAY( delay_time ) ;
+ 			res[ ++trial ] = rdtsc() ;
+ 		}
+ 		printf( "Tested delay(%u):\nCycles =", delay_time ) ;
+ 		for ( trial = 0 ; trial < 7 ; trial++ )
+ 			printf( " %qu,", res[trial + 1] - res[trial] ) ;
+ 		printf( " %qu\n", res[8] - res[7] ) ;
+ 		for ( trial = 0 ; trial <= 8 ; trial++ )
+ 			printf( "res[%d] =  %qu\n", trial, res[trial] ) ;
+ 	}
+ 	return ;
+ }
+ 
  /* minimal initialization, enough for delay() */
  void
  initrtclock()
***************
*** 418,423 ****
--- 443,449 ----
  		printf("RTC BIOS diagnostic error %s\n",
  		    bitmask_snprintf(s, NVRAM_DIAG_BITS, bits, sizeof(bits)));
  	}
+ testDelayTimes() ;
  }
  
  int
--------------------------------------------------------------------------------
NetBSD 2.0G (SVCS) #239: Mon Jul 19 03:54:18 PDT 2004
	root@svcs:/sys/arch/i386/compile/SVCS
total memory = 2047 MB
avail memory = 1996 MB
Tested delay(0):
Cycles = 5339, 4103, 4284, 4284, 4284, 4284, 4284, 4284
res[0] =  27658970945
res[1] =  27658976284
res[2] =  27658980387
res[3] =  27658984671
res[4] =  27658988955
res[5] =  27658993239
res[6] =  27658997523
res[7] =  27659001807
res[8] =  27659006091
Tested delay(1):
Cycles = 8214, 8548, 8568, 8568, 8568, 8670, 8568, 8670
res[0] =  27669801738
res[1] =  27669809952
res[2] =  27669818500
res[3] =  27669827068
res[4] =  27669835636
res[5] =  27669844204
res[6] =  27669852874
res[7] =  27669861442
res[8] =  27669870112
Tested delay(2):
Cycles = 8453, 8568, 8670, 8568, 8568, 8670, 8568, 8568
res[0] =  27680549423
res[1] =  27680557876
res[2] =  27680566444
res[3] =  27680575114
res[4] =  27680583682
res[5] =  27680592250
res[6] =  27680600920
res[7] =  27680609488
res[8] =  27680618056
Tested delay(3):
Cycles = 8274, 8568, 8568, 8568, 8568, 8568, 8568, 8568
res[0] =  27691203502
res[1] =  27691211776
res[2] =  27691220344
res[3] =  27691228912
res[4] =  27691237480
res[5] =  27691246048
res[6] =  27691254616
res[7] =  27691263184
res[8] =  27691271752
Tested delay(4):
Cycles = 8198, 8568, 8568, 8568, 8568, 8568, 8568, 8568
res[0] =  27702043832
res[1] =  27702052030
res[2] =  27702060598
res[3] =  27702069166
res[4] =  27702077734
res[5] =  27702086302
res[6] =  27702094870
res[7] =  27702103438
res[8] =  27702112006
Tested delay(5):
Cycles = 8198, 8568, 8568, 8568, 8568, 8568, 8568, 8670
res[0] =  27712722416
res[1] =  27712730614
res[2] =  27712739182
res[3] =  27712747750
res[4] =  27712756318
res[5] =  27712764886
res[6] =  27712773454
res[7] =  27712782022
res[8] =  27712790692
Tested delay(6):
Cycles = 12481, 12852, 12844, 12852, 12852, 12852, 12954, 12954
res[0] =  27723380201
res[1] =  27723392682
res[2] =  27723405534
res[3] =  27723418378
res[4] =  27723431230
res[5] =  27723444082
res[6] =  27723456934
res[7] =  27723469888
res[8] =  27723482842
Tested delay(7):
Cycles = 12541, 12852, 12852, 12954, 12852, 12954, 12954, 12852
res[0] =  27734135217
res[1] =  27734147758
res[2] =  27734160610
res[3] =  27734173462
res[4] =  27734186416
res[5] =  27734199268
res[6] =  27734212222
res[7] =  27734225176
res[8] =  27734238028
Tested delay(8):
Cycles = 12516, 12852, 12852, 12852, 12852, 12852, 12852, 12852
res[0] =  27744866764
res[1] =  27744879280
res[2] =  27744892132
res[3] =  27744904984
res[4] =  27744917836
res[5] =  27744930688
res[6] =  27744943540
res[7] =  27744956392
res[8] =  27744969244
Tested delay(9):
Cycles = 12524, 12954, 12954, 12852, 12954, 12954, 12852, 12954
res[0] =  27755624084
res[1] =  27755636608
res[2] =  27755649562
res[3] =  27755662516
res[4] =  27755675368
res[5] =  27755688322
res[6] =  27755701276
res[7] =  27755714128
res[8] =  27755727082
Tested delay(10):
Cycles = 12541, 12852, 12852, 12852, 12852, 12852, 12852, 12852
res[0] =  27766387209
res[1] =  27766399750
res[2] =  27766412602
res[3] =  27766425454
res[4] =  27766438306
res[5] =  27766451158
res[6] =  27766464010
res[7] =  27766476862
res[8] =  27766489714
Tested delay(11):
Cycles = 16842, 17136, 17128, 17136, 17136, 17136, 17238, 12962
res[0] =  27777132186
res[1] =  27777149028
res[2] =  27777166164
res[3] =  27777183292
res[4] =  27777200428
res[5] =  27777217564
res[6] =  27777234700
res[7] =  27777251938
res[8] =  27777264900
Tested delay(12):
Cycles = 16791, 17136, 17136, 17136, 17238, 17238, 17136, 17238
res[0] =  27788012161
res[1] =  27788028952
res[2] =  27788046088
res[3] =  27788063224
res[4] =  27788080360
res[5] =  27788097598
res[6] =  27788114836
res[7] =  27788131972
res[8] =  27788149210
Tested delay(13):
Cycles = 17344, 17238, 17238, 17136, 17238, 17238, 17238, 17136
res[0] =  27798865632
res[1] =  27798882976
res[2] =  27798900214
res[3] =  27798917452
res[4] =  27798934588
res[5] =  27798951826
res[6] =  27798969064
res[7] =  27798986302
res[8] =  27799003438
Tested delay(14):
Cycles = 16893, 17238, 17238, 17136, 17238, 17238, 17238, 17238
res[0] =  27809677267
res[1] =  27809694160
res[2] =  27809711398
res[3] =  27809728636
res[4] =  27809745772
res[5] =  27809763010
res[6] =  27809780248
res[7] =  27809797486
res[8] =  27809814724
Tested delay(15):
Cycles = 16774, 21428, 17128, 17136, 17136, 17136, 17136, 17213
res[0] =  27820457868
res[1] =  27820474642
res[2] =  27820496070
res[3] =  27820513198
res[4] =  27820530334
res[5] =  27820547470
res[6] =  27820564606
res[7] =  27820581742
res[8] =  27820598955
Tested delay(16):
Cycles = 21151, 21514, 21522, 17246, 21514, 21522, 17246, 21514
res[0] =  27831232349
res[1] =  27831253500
res[2] =  27831275014
res[3] =  27831296536
res[4] =  27831313782
res[5] =  27831335296
res[6] =  27831356818
res[7] =  27831374064
res[8] =  27831395578
Tested delay(17):
Cycles = 21092, 21420, 21420, 21420, 21420, 21522, 21522, 21522
res[0] =  27842036852
res[1] =  27842057944
res[2] =  27842079364
res[3] =  27842100784
res[4] =  27842122204
res[5] =  27842143624
res[6] =  27842165146
res[7] =  27842186668
res[8] =  27842208190
Tested delay(18):
Cycles = 21075, 21420, 21420, 21420, 21420, 21420, 21522, 21624
res[0] =  27852828061
res[1] =  27852849136
res[2] =  27852870556
res[3] =  27852891976
res[4] =  27852913396
res[5] =  27852934816
res[6] =  27852956236
res[7] =  27852977758
res[8] =  27852999382
Tested delay(19):
Cycles = 21101, 21420, 21420, 21420, 21522, 21522, 21522, 21522
res[0] =  27863643401
res[1] =  27863664502
res[2] =  27863685922
res[3] =  27863707342
res[4] =  27863728762
res[5] =  27863750284
res[6] =  27863771806
res[7] =  27863793328
res[8] =  27863814850
Tested delay(20):
Cycles = 21058, 21420, 21420, 25712, 25806, 21624, 21514, 21420
res[0] =  27874433106
res[1] =  27874454164
res[2] =  27874475584
res[3] =  27874497004
res[4] =  27874522716
res[5] =  27874548522
res[6] =  27874570146
res[7] =  27874591660
res[8] =  27874613080
BIOS32 rev. 0 found at 0xf0ad0
PCI BIOS rev. 2.1 found at 0xf0cd0
pcibios: config mechanism [1][x], special cycles [1][x], last bus 1
PCI IRQ Routing Table rev. 1.0 found at 0xf1280, size 160 bytes (8 entries)
PCI Interrupt Router at 000:04:0 (VIA Technologies VT82C586 (Apollo VP) PCI-ISA Bridge compatible)
[System BIOS Setting]-----------------------
  device vendor product
  register space address    size
--------------------------------------------
000:00:0 0x1106 0x0691 
	10h mem  0xf8000000 0x04000000
		[OK]
000:01:0 0x1106 0x8598 
		[OK]
000:04:0 0x1106 0x0686 
		[OK]
000:04:1 0x1106 0x0571 
	20h port 0x0000d800 0x00000010
		[OK]
000:04:2 0x1106 0x3038 
	20h port 0x0000d400 0x00000020
		[OK]
000:04:3 0x1106 0x3038 
	20h port 0x0000d000 0x00000020
		[OK]
000:04:4 0x1106 0x3057 
		[OK]
000:07:0 0x131f 0x2081 
	10h port 0x0000b800 0x00000008
	14h port 0x0000b400 0x00000008
	18h port 0x0000b000 0x00000008
	1ch port 0x0000a800 0x00000008
	20h port 0x0000a400 0x00000020
		[OK]
000:08:0 0x8086 0x1229 
	10h mem  0xee800000 0x00001000
	14h port 0x0000a000 0x00000040
	18h mem  0xee000000 0x00020000
		[OK]
000:09:0 0x105a 0x4d38 
	10h port 0x00009800 0x00000008
	14h port 0x00009400 0x00000004
	18h port 0x00009000 0x00000008
	1ch port 0x00008800 0x00000004
	20h port 0x00008400 0x00000040
	24h mem  0xed800000 0x00020000
		[OK]
000:10:0 0x1106 0x3044 
	10h mem  0xed000000 0x00000800
	14h port 0x00008000 0x00000080
		[OK]
000:11:0 0x1415 0x9521 
	10h port 0x00007800 0x00000008
	14h port 0x00007400 0x00000008
	18h port 0x00007000 0x00000020
	1ch mem  0xec800000 0x00001000
	20h mem  0xec000000 0x00001000
		[OK]
000:11:1 0x1415 0x9523 
	10h port 0x00006800 0x00000008
	14h port 0x00006400 0x00000004
	18h port 0x00006000 0x00000020
	1ch mem  0xeb800000 0x00001000
		[OK]
001:00:0 0x5333 0x8a22 
	10h mem  0xef000000 0x00080000
	14h mem  0xf0000000 0x08000000
		[OK]
--------------------------[  0 devices bogus]
 Physical memory end: 0x7ffdc000
 PCI memory mapped I/O space start: 0x80000000
mainbus0 (root)
 tbxface-0198 [01] AcpiLoadTables        : ACPI Tables successfully acquired
Parsing all Control Methods:................................................................................................
Table [DSDT](id F004) - 355 Objects with 40 Devices 96 Methods 32 Regions
ACPI Namespace successfully loaded at root 0xc087c420
cpu0 at mainbus0: (uniprocessor)
cpu0: Intel Pentium III (686-class), 856.07 MHz, id 0x683
cpu0: features 383f9ff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,SEP,MTRR>
cpu0: features 383f9ff<PGE,MCA,CMOV,PAT,PSE36,MMX>
cpu0: features 383f9ff<FXSR,SSE>
cpu0: I-cache 16 KB 32B/line 4-way, D-cache 16 KB 32B/line 4-way
cpu0: L2 cache 256 KB 32B/line 8-way
cpu0: ITLB 32 4 KB entries 4-way, 2 4 MB entries fully associative
cpu0: DTLB 64 4 KB entries 4-way, 8 4 MB entries 4-way
cpu0: 8 page colors
acpi0 at mainbus0
acpi0: using Intel ACPI CA subsystem version 20040211
acpi0: X/RSDT: OemId <ASUS  ,CUV4X_E ,30303031>, AslId <MSFT,31313031>
evxfevnt-0175 [02] AcpiEnable            : Transition to ACPI mode successful
evgpeblk-0869 [08] EvCreateGpeBlock      : GPE 00 to 15 [_GPE] 2 regs at 000000000000E420 on int 9
Completing Region/Field/Buffer/Package initialization:.......................................................................
Initialized 32/32 Regions 9/9 Fields 19/19 Buffers 11/11 Packages (363 nodes)
Executing all Device _STA and_INI methods:..........................................
42 Devices found containing: 42 _STA, 0 _INI methods
acpi0: SCI interrupting at int 9
acpi0: fixed-feature power button present
acpi_pci_fixup starts:
acpi0: fixing up PCI bus 0 at level 1
acpi0: fixing up PCI bus 1 at level 2
ACPI Object Type 'Processor' (0x0c) at acpi0 not configured
acpibut0 at acpi0 (PNP0C0C): ACPI Power Button
PNP0C01 [System Board] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
PNP0A03 [PCI Bus] at acpi0 not configured
PNP0C02 [Plug and Play motherboard register resources] at acpi0 not configured
PNP0C02 [Plug and Play motherboard register resources] at acpi0 not configured
PNP0000 [AT Interrupt Controller] at acpi0 not configured
PNP0200 [AT DMA Controller] at acpi0 not configured
PNP0100 [AT Timer] at acpi0 not configured
PNP0B00 [AT Real-Time Clock] at acpi0 not configured
PNP0800 [AT-style speaker sound] at acpi0 not configured
npx0 at acpi0 (PNP0C04)
npx0: io 0xf0-0xff irq 13
npx0: using exception 16
fdc0 at acpi0 (PNP0700)
fdc0: io 0x3f2-0x3f5,0x3f7 irq 6 drq 2
atppc0 at acpi0 (PNP0401): AT Parallel Port
atppc0: io 0x378-0x37f,0x778-0x77b irq 7 drq 3
atppc0: dtr = 0x0, str = 0xf8, ctr = 0x0
atppc0: ecr = 0x15, cnfgA = 0x10, cnfgB = 0x0
atppc0: FIFO <depth,wthr,rthr>=<16,8,8>
atppc0: capabilities=3f<INTR,DMA,FIFO,PS2,ECP,EPP>
ppbus0 at atppc0
ppbus0: IEEE1284 negotiation: modes NIBBLE/ECP
ppbus0: IEEE1284 device found.
ppbus0: Probing for PnP devices.
ppbus0: <HEWLETT-PACKARD PHOTOSMART P1100> MLC,PCL,PML
lpt0 at ppbus0: port mode = 1<COMPATIBLE>
com0 at acpi0 (PNP0501-1)
com0: io 0x3f8-0x3ff irq 4
com0: ns16550a, working fifo
com1 at acpi0 (PNP0501-2)
com1: io 0x2f8-0x2ff irq 3
com1: ns16550a, working fifo
pckbc0 at acpi0 (PNP0303): kbd port
pckbc0: io 0x60,0x64 irq 1
pckbc1 at acpi0 (PNP0F13): aux port
pckbc1: irq 12
pckbd0 at pckbc0 (kbd slot)
pckbc0: using irq 1 for kbd slot
wskbd0 at pckbd0: console keyboard
pms0 at pckbc0 (aux slot)
pckbc0: using irq 12 for aux slot
wsmouse0 at pms0 mux 0
pci0 at mainbus0 bus 0: configuration mode 1
pci0: i/o space, memory space enabled, rd/line, rd/mult, wr/inv ok
pchb0 at pci0 dev 0 function 0
pchb0: VIA Technologies VT82C691 (Apollo Pro) Host-PCI (rev. 0xc4)
agp0 at pchb0: aperture at 0xf8000000, size 0x10000000
ppb0 at pci0 dev 1 function 0: VIA Technologies VT82C598 (Apollo MVP3) CPU-AGP Bridge (rev. 0x00)
pci1 at ppb0 bus 1
pci1: i/o space, memory space enabled
vga0 at pci1 dev 0 function 0: S3 Savage4 (rev. 0x02)
wsdisplay0 at vga0 kbdmux 1: console (80x25, vt100 emulation), using wskbd0
wsmux1: connecting to wsdisplay0
pcib0 at pci0 dev 4 function 0
pcib0: VIA Technologies VT82C686A (Apollo KX133) PCI-ISA Bridge (rev. 0x40)
viaide0 at pci0 dev 4 function 1
viaide0: VIA Technologies VT82C686A (Apollo KX133) ATA100 controller
viaide0: bus-master DMA support present
viaide0: primary channel configured to compatibility mode
viaide0: primary channel interrupting at irq 14
atabus0 at viaide0 channel 0
viaide0: secondary channel configured to compatibility mode
viaide0: secondary channel interrupting at irq 15
atabus1 at viaide0 channel 1
uhci0 at pci0 dev 4 function 2: VIA Technologies VT83C572 USB Controller (rev. 0x16)
uhci0: interrupting at irq 11
usb0 at uhci0: USB revision 1.0
uhub0 at usb0
uhub0: VIA Technologies UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhci1 at pci0 dev 4 function 3: VIA Technologies VT83C572 USB Controller (rev. 0x16)
uhci1: interrupting at irq 11
usb1 at uhci1: USB revision 1.0
uhub1 at usb1
uhub1: VIA Technologies UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
viapm0 at pci0 dev 4 function 4
viaenv0 at viapm0: disabled
puc0 at pci0 dev 7 function 0: SIIG PS8000 8S PCI 16C650 (20x family) (com, com, com, com, com, com, com, com)
com2 at puc0 port 0: interrupting at irq 10
com2: st16650a, working fifo
com3 at puc0 port 1: interrupting at irq 10
com3: st16650a, working fifo
com4 at puc0 port 2: interrupting at irq 10
com4: st16650a, working fifo
com5 at puc0 port 3: interrupting at irq 10
com5: st16650a, working fifo
com6 at puc0 port 4: interrupting at irq 10
com6: st16650a, working fifo
com7 at puc0 port 5: interrupting at irq 10
com7: st16650a, working fifo
com8 at puc0 port 6: interrupting at irq 10
com8: st16650a, working fifo
com9 at puc0 port 7: interrupting at irq 10
com9: st16650a, working fifo
fxp0 at pci0 dev 8 function 0: i82550 Ethernet, rev 12
fxp0: interrupting at irq 9
fxp0: Ethernet address 00:02:b3:28:71:1d
inphy0 at fxp0 phy 1: i82555 10/100 media interface, rev. 4
inphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
pdcide0 at pci0 dev 9 function 0
pdcide0: Promise Ultra66/ATA Bus Master IDE Accelerator (rev. 0x01)
pdcide0: bus-master DMA support present
pdcide0: primary channel configured to native-PCI mode
pdcide0: using irq 5 for native-PCI interrupt
atabus2 at pdcide0 channel 0
pdcide0: secondary channel configured to native-PCI mode
atabus3 at pdcide0 channel 1
fwohci0 at pci0 dev 10 function 0: VIA Technologies VT3606 OHCI IEEE 1394 Controller (rev. 0x43)
fwohci0: interrupting at irq 11
fwohci0: OHCI 1.0, 00:01:08:00:30:00:0b:78, 400Mb/s, 2048 max_rec, 8 ir_ctx, 8 it_ctx
puc1 at pci0 dev 11 function 0: Oxford Semiconductor OX16PCI952 UARTs (com, com)
com10 at puc1 port 0: interrupting at irq 10
com10: st16650a, working fifo
com11 at puc1 port 1: interrupting at irq 10
com11: st16650a, working fifo
puc2 at pci0 dev 11 function 1: Oxford Semiconductor OX16PCI952 Parallel port (lpt)
atppc1 at puc2 port 0: AT Parallel Port
atppc1: interrupting at irq 10
atppc1: dtr = 0x0, str = 0xdf, ctr = 0x0
atppc1: ecr = 0x15, cnfgA = 0x90, cnfgB = 0x40
atppc1: FIFO <depth,wthr,rthr>=<16,8,8>
atppc1: capabilities=3d<INTR,FIFO,PS2,ECP,EPP>
ppbus1 at atppc1
ppbus1: IEEE1284 negotiation: modes NIBBLE/ECP
ppbus1: IEEE1284 device found.
ppbus1: Probing for PnP devices.
ppbus1: <Hewlett-Packard HP LaserJet 6MP> PJL,MLC,PCLXL,PCL,POSTSCRIPT
lpt1 at ppbus1: port mode = 1<COMPATIBLE>
isa0 at pcib0
pcppi0 at isa0 port 0x61
midi0 at pcppi0: PC speaker
spkr0 at pcppi0
sysbeep0 at pcppi0
fd0 at fdc0 drive 0: 1.44MB, 80 cyl, 2 head, 18 sec
Kernelized RAIDframe activated
IPsec: Initialized Security Association Processing.
wd0 at atabus0 drive 0fw0 at fwohci0: 00:01:08:00:30:00:0b:78:0a:02:ff:ff:f0:01:00:00
: <WDC WD400AB-00CMB0>
wd0: drive supports 16-sector PIO transfers, LBA addressing
wd0: 38166 MB, 77545 cyl, 16 head, 63 sec, 512 bytes/sect x 78165360 sectors
wd0: 32-bit data port
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd1 at atabus0 drive 1: <WDC WD400EB-11CPF0>
wd1: drive supports 16-sector PIO transfers, LBA addressing
wd1: 38166 MB, 77545 cyl, 16 head, 63 sec, 512 bytes/sect x 78165360 sectors
wd1: 32-bit data port
wd1: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd0(viaide0:0:0): using PIO mode 4, Ultra-DMA mode 5 (Ultra/100) (using DMA data transfers)
wd1(viaide0:0:1): using PIO mode 4, Ultra-DMA mode 5 (Ultra/100) (using DMA data transfers)
wd2 at atabus1 drive 0: <WDC WD400AB-00BVA0>
wd2: drive supports 16-sector PIO transfers, LBA addressing
wd2: 38166 MB, 77545 cyl, 16 head, 63 sec, 512 bytes/sect x 78165360 sectors
wd2: 32-bit data port
wd2: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd3 at atabus1 drive 1: <WDC WD400AB-00BVA0>
wd3: drive supports 16-sector PIO transfers, LBA addressing
wd3: 38166 MB, 77545 cyl, 16 head, 63 sec, 512 bytes/sect x 78165360 sectors
wd3: 32-bit data port
wd3: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd2(viaide0:1:0): using PIO mode 4, Ultra-DMA mode 5 (Ultra/100) (using DMA data transfers)
wd3(viaide0:1:1): using PIO mode 4, Ultra-DMA mode 5 (Ultra/100) (using DMA data transfers)
wd4 at atabus2 drive 0: <WDC WD400AB-00BVA0>
wd4: drive supports 16-sector PIO transfers, LBA addressing
wd4: 38166 MB, 77545 cyl, 16 head, 63 sec, 512 bytes/sect x 78165360 sectors
wd4: 32-bit data port
wd4: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd4(pdcide0:0:0): using PIO mode 4, Ultra-DMA mode 4 (Ultra/66) (using DMA data transfers)
wd6 at atabus3 drive 0: <WDC WD400AB-00CMB0>
wd6: drive supports 16-sector PIO transfers, LBA addressing
wd6: 38166 MB, 77545 cyl, 16 head, 63 sec, 512 bytes/sect x 78165360 sectors
wd6: 32-bit data port
wd6: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd6(pdcide0:1:0): using PIO mode 4, Ultra-DMA mode 4 (Ultra/66) (using DMA data transfers)
raid0: RAID Level 5
raid0: Components: /dev/wd0b /dev/wd2b /dev/wd4b /dev/wd1b /dev/wd3b /dev/wd6b
raid0: Total Sectors: 20769200 (10141 MB)
boot device: raid0
root on raid0a dumps on wd4a
raid0: Device already configured!
raid1: Component /dev/wd0e being configured at col: 0
         Column: 0 Num Columns: 6
         Version: 2 Serial Number: 12011 Mod Counter: 6943
         Clean: Yes Status: 0
raid1: Component /dev/wd2e being configured at col: 1
         Column: 1 Num Columns: 6
         Version: 2 Serial Number: 12011 Mod Counter: 6943
         Clean: Yes Status: 0
raid1: Component /dev/wd4e being configured at col: 2
         Column: 2 Num Columns: 6
         Version: 2 Serial Number: 12011 Mod Counter: 6943
         Clean: Yes Status: 0
raid1: Component /dev/wd1e being configured at col: 3
         Column: 3 Num Columns: 6
         Version: 2 Serial Number: 12011 Mod Counter: 6943
         Clean: Yes Status: 0
raid1: Component /dev/wd3e being configured at col: 4
         Column: 4 Num Columns: 6
         Version: 2 Serial Number: 12011 Mod Counter: 6943
         Clean: Yes Status: 0
raid1: Component /dev/wd6e being configured at col: 5
         Column: 5 Num Columns: 6
         Version: 2 Serial Number: 12011 Mod Counter: 6943
         Clean: Yes Status: 0
raid1: RAID Level 5
raid1: Components: /dev/wd0e /dev/wd2e /dev/wd4e /dev/wd1e /dev/wd3e /dev/wd6e
raid1: Total Sectors: 20562880 (10040 MB)
raid2: Component /dev/wd0f being configured at col: 0
         Column: 0 Num Columns: 6
         Version: 2 Serial Number: 12022 Mod Counter: 8721
         Clean: No Status: 0
/dev/wd0f is not clean!
raid2: Component /dev/wd2f being configured at col: 1
         Column: 1 Num Columns: 6
         Version: 2 Serial Number: 12022 Mod Counter: 8721
         Clean: No Status: 0
/dev/wd2f is not clean!
raid2: Component /dev/wd4f being configured at col: 2
         Column: 2 Num Columns: 6
         Version: 2 Serial Number: 12022 Mod Counter: 8721
         Clean: No Status: 0
/dev/wd4f is not clean!
raid2: Component /dev/wd1f being configured at col: 3
         Column: 3 Num Columns: 6
         Version: 2 Serial Number: 12022 Mod Counter: 8721
         Clean: No Status: 0
/dev/wd1f is not clean!
raid2: Component /dev/wd3f being configured at col: 4
         Column: 4 Num Columns: 6
         Version: 2 Serial Number: 12022 Mod Counter: 8721
         Clean: No Status: 0
/dev/wd3f is not clean!
raid2: Component /dev/wd6f being configured at col: 5
         Column: 5 Num Columns: 6
         Version: 2 Serial Number: 12022 Mod Counter: 8721
         Clean: No Status: 0
/dev/wd6f is not clean!
raid2: RAID Level 5
raid2: Components: /dev/wd0f /dev/wd2f /dev/wd4f /dev/wd1f /dev/wd3f /dev/wd6f
raid2: Total Sectors: 41126080 (20081 MB)
raid3: Component /dev/wd0g being configured at col: 0
         Column: 0 Num Columns: 6
         Version: 2 Serial Number: 12033 Mod Counter: 5003
         Clean: No Status: 0
/dev/wd0g is not clean!
raid3: Component /dev/wd2g being configured at col: 1
         Column: 1 Num Columns: 6
         Version: 2 Serial Number: 12033 Mod Counter: 5003
         Clean: No Status: 0
/dev/wd2g is not clean!
raid3: Component /dev/wd4g being configured at col: 2
         Column: 2 Num Columns: 6
         Version: 2 Serial Number: 12033 Mod Counter: 5003
         Clean: No Status: 0
/dev/wd4g is not clean!
raid3: Component /dev/wd1g being configured at col: 3
         Column: 3 Num Columns: 6
         Version: 2 Serial Number: 12033 Mod Counter: 5003
         Clean: No Status: 0
/dev/wd1g is not clean!
raid3: Component /dev/wd3g being configured at col: 4
         Column: 4 Num Columns: 6
         Version: 2 Serial Number: 12033 Mod Counter: 5003
         Clean: No Status: 0
/dev/wd3g is not clean!
raid3: Component /dev/wd6g being configured at col: 5
         Column: 5 Num Columns: 6
         Version: 2 Serial Number: 12033 Mod Counter: 5003
         Clean: No Status: 0
/dev/wd6g is not clean!
raid3: RAID Level 5
raid3: Components: /dev/wd0g /dev/wd2g /dev/wd4g /dev/wd1g /dev/wd3g /dev/wd6g
raid3: Total Sectors: 82252480 (40162 MB)
raid4: Component /dev/wd0h being configured at col: 0
         Column: 0 Num Columns: 6
         Version: 2 Serial Number: 12044 Mod Counter: 268440709
         Clean: No Status: 0
/dev/wd0h is not clean!
raid4: Component /dev/wd2h being configured at col: 1
         Column: 1 Num Columns: 6
         Version: 2 Serial Number: 12044 Mod Counter: 268440709
         Clean: No Status: 0
/dev/wd2h is not clean!
raid4: Component /dev/wd4h being configured at col: 2
         Column: 2 Num Columns: 6
         Version: 2 Serial Number: 12044 Mod Counter: 268440709
         Clean: No Status: 0
/dev/wd4h is not clean!
raid4: Component /dev/wd1h being configured at col: 3
         Column: 3 Num Columns: 6
         Version: 2 Serial Number: 12044 Mod Counter: 268440709
         Clean: No Status: 0
/dev/wd1h is not clean!
raid4: Component /dev/wd3h being configured at col: 4
         Column: 4 Num Columns: 6
         Version: 2 Serial Number: 12044 Mod Counter: 268440709
         Clean: No Status: 0
/dev/wd3h is not clean!
raid4: Component /dev/wd6h being configured at col: 5
         Column: 5 Num Columns: 6
         Version: 2 Serial Number: 12044 Mod Counter: 268440709
         Clean: No Status: 0
/dev/wd6h is not clean!
raid4: RAID Level 5
raid4: Components: /dev/wd0h /dev/wd2h /dev/wd4h /dev/wd1h /dev/wd3h /dev/wd6h
raid4: Total Sectors: 164505280 (80324 MB)
raid5: Component /dev/wd0i being configured at col: 0
         Column: 0 Num Columns: 6
         Version: 2 Serial Number: 12055 Mod Counter: 1074420184
         Clean: No Status: 0
/dev/wd0i is not clean!
raid5: Component /dev/wd2i being configured at col: 1
         Column: 1 Num Columns: 6
         Version: 2 Serial Number: 12055 Mod Counter: 1074420184
         Clean: No Status: 0
/dev/wd2i is not clean!
raid5: Component /dev/wd4i being configured at col: 2
         Column: 2 Num Columns: 6
         Version: 2 Serial Number: 12055 Mod Counter: 1074420184
         Clean: No Status: 0
/dev/wd4i is not clean!
raid5: Component /dev/wd1i being configured at col: 3
         Column: 3 Num Columns: 6
         Version: 2 Serial Number: 12055 Mod Counter: 1074420184
         Clean: No Status: 0
/dev/wd1i is not clean!
raid5: Component /dev/wd3i being configured at col: 4
         Column: 4 Num Columns: 6
         Version: 2 Serial Number: 12055 Mod Counter: 1074420184
         Clean: No Status: 0
/dev/wd3i is not clean!
raid5: Component /dev/wd6i being configured at col: 5
         Column: 5 Num Columns: 6
         Version: 2 Serial Number: 12055 Mod Counter: 1074420184
         Clean: No Status: 0
/dev/wd6i is not clean!
raid5: RAID Level 5
raid5: Components: /dev/wd0i /dev/wd2i /dev/wd4i /dev/wd1i /dev/wd3i /dev/wd6i
raid5: Total Sectors: 41045680 (20041 MB)
fxp0: Microcode loaded: int delay: 1000 usec, max bundle: 6
wsdisplay0: screen 1 added (80x25, vt100 emulation)
wsdisplay0: screen 2 added (80x25, vt100 emulation)
wsdisplay0: screen 3 added (80x25, vt100 emulation)
wsdisplay0: screen 4 added (80x25, vt100 emulation)
Accounting started
lptopen(lpt0): initializing printer.
lptopen(lpt0): printer ready.
lptopen(lpt1): initializing printer.
lptopen(lpt1): printer ready.
	
>Fix:

	The delays under AND modulo ~15microseconds NEED to be performed
by a calibrated "nop" loop that checks at least every 1/2 microsecond for
completion.  I would recomend usings the existing i8254_delay() for (n-10)
when n>15, then waiting out the residual in a tight calibrated spin loop.
And yes, Speedstep and the K7/8 equivalent greatly complicate this!
>Release-Note:
>Audit-Trail:
>Unformatted: