6.0_BETA: Extreamly slow newfs_ext2fs on 60Gb USB stick

To: tech-kern%NetBSD.org@localhost
Subject: 6.0_BETA: Extreamly slow newfs_ext2fs on 60Gb USB stick
From: Aleksey Cheusov <cheusov%tut.by@localhost>
Date: Thu, 01 Mar 2012 20:11:24 +0300

For a number of reasons I decided to use ext2 filesystem on 60Gb memory
stick.

    umass0 at uhub7 port 1 configuration 1 interface 0
    umass0: JetFlash Mass Storage Device, rev 2.00/1.00, addr 2
    umass0: using SCSI over Bulk-Only
    scsibus0 at umass0: 2 targets, 1 lun per target
    sd0 at scsibus0 target 0 lun 0: <JetFlash, Transcend 64GB, 8.07> disk 
removable
    sd0: fabricating a geometry
    sd0: 61280 MB, 61280 cyl, 64 head, 32 sec, 512 bytes/sect x 125501440 
sectors
    sd0: fabricating a geometry

Unfortunately newfs_ext2fs works extreamly slowly

    work# time -p newfs_ext2fs -V4 /dev/rsd0e
    /dev/rsd0e: 61276.0MB (125493248 sectors) block size 4096, fragment size 
4096
    using 479 block groups of 128.0MB, 32768 blks, 16384 inodes.
    super-block backups (for fsck_ext2fs -b #) at:
    32768,    65536,    98304,   131072,   163840,   196608,   229376,   
262144,   294912,
    ...
    real  4944.92
    user     0.56
    sys      4.59
    work#

that is it worked almost an hour and a half.

ktruss(1) says most of the time newfs_ext2fs(8) does the following

    ...
    29777      1 newfs_ext2fs pwrite(0x5, 0xbbaa0000, 0x400, 0, 0x400, 0x1) = 
1024
    
"\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\0\0\0\0\0\0\0"
    29777      1 newfs_ext2fs pwrite(0x5, 0xbbaa0000, 0x400, 0, 0x800400, 0x1) 
= 1024
    
"\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\0\0\0\0\0\0\0"
    29777      1 newfs_ext2fs pwrite(0x5, 0xbbaa0000, 0x400, 0, 0x1000400, 0x1) 
= 1024
    
"\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\0\0\0\0\0\0\0"
    29777      1 newfs_ext2fs pwrite(0x5, 0xbbaa0000, 0x400, 0, 0x1800400, 0x1) 
= 1024
    
"\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\0\0\0\0\0\0\0"
    ...

It executes approximately 5 pwrite(2) syscalls per second.

On file image (newfs_ext2fs -F) creating fs takes about 40 seconds.
Raw write speed (dd of=/dev/rsd0e) on this memstick is about 15Mb/sec.

To me this looks like kernel bug in USB subsystem. Any clue?

dmesg output is in attachement

Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
    2006, 2007, 2008, 2009, 2010, 2011, 2012
    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 6.0_BETA (GENERIC) #0: Thu Feb 23 16:52:34 FET 2012
        
cheusov%work.imb.invention.com@localhost:/srv/obj-current/sys/arch/i386/compile/GENERIC
total memory = 2039 MB
avail memory = 1992 MB
timecounter: Timecounters tick every 10.000 msec
timecounter: Timecounter "i8254" frequency 1193182 Hz quality 100
    ( )
mainbus0 (root)
cpu0 at mainbus0 apid 0: Intel(R) Pentium(R) 4 CPU 3.00GHz, id 0xf43
cpu1 at mainbus0 apid 1: Intel(R) Pentium(R) 4 CPU 3.00GHz, id 0xf43
ioapic0 at mainbus0 apid 2: pa 0xfec00000, version 20, 24 pins
acpi0 at mainbus0: Intel ACPICA 20110623
acpi0: X/RSDT: OemId <GBT   ,AWRDACPI,42302e31>, AslId <AWRD,01010101>
acpi0: SCI interrupting at int 9
timecounter: Timecounter "ACPI-Fast" frequency 3579545 Hz quality 1000
acpibut0 at acpi0 (PWRB, PNP0C0C): ACPI Power Button
SYSR (PNP0C02) at acpi0 not configured
attimer1 at acpi0 (TMR, PNP0100): io 0x40-0x43 irq 0
pcppi1 at acpi0 (SPKR, PNP0800): io 0x61
midi0 at pcppi1: PC speaker
sysbeep0 at pcppi1
npx1 at acpi0 (COPR, PNP0C04): io 0xf0-0xff irq 13
npx1: reported by CPUID; using exception 16
pckbc1 at acpi0 (PS2K, PNP0303) (kbd port): io 0x60,0x64 irq 1
PMIO (PNP0C02) at acpi0 not configured
EXPL (PNP0C02) at acpi0 not configured
MEM (PNP0C01) at acpi0 not configured
FWH (INT0800) at acpi0 not configured
apm0 at acpi0: Power Management spec V1.2
attimer1: attached to pcppi1
pckbd0 at pckbc1 (kbd slot)
pckbc1: using irq 1 for kbd slot
wskbd0 at pckbd0: console keyboard
pms0 at pckbc1 (aux slot)
pckbc1: unable to establish interrupt 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: vendor 0x8086 product 0x2770 (rev. 0x02)
agp0 at pchb0: detected 7932k stolen memory
agp0: aperture at 0xd0000000, size 0x10000000
vga1 at pci0 dev 2 function 0: vendor 0x8086 product 0x2772 (rev. 0x02)
wsdisplay0 at vga1 kbdmux 1: console (80x25, vt100 emulation), using wskbd0
wsmux1: connecting to wsdisplay0
i915drm0 at vga1: Intel i945G
i915drm0: AGP at 0xd0000000 256MB
i915drm0: Initialized i915 1.6.0 20080730
hdaudio0 at pci0 dev 27 function 0: HD Audio Controller
hdaudio0: interrupting at ioapic0 pin 16
hdafg0 at hdaudio0: Realtek ALC882
hdafg0: DAC00 10ch: Speaker [Jack], SPDIF Out [Jack]
hdafg0: DAC01 2ch: HP Out [Jack]
hdafg0: ADC02 2ch: CD [Built-In], Line In [Jack], Mic In [Jack]
hdafg0: DIG-In03 2ch: SPDIF In [Jack]
hdafg0: 10ch/2ch 44100Hz 48000Hz 96000Hz 192000Hz PCM16 PCM20 PCM24 AC3
audio0 at hdafg0: full duplex, playback, capture, independent
ppb0 at pci0 dev 28 function 0: vendor 0x8086 product 0x27d0 (rev. 0x01)
ppb0: PCI Express 1.0 <Root Port of PCI-E Root Complex>
pci1 at ppb0 bus 1
pci1: i/o space, memory space enabled, rd/line, wr/inv ok
uhci0 at pci0 dev 29 function 0: vendor 0x8086 product 0x27c8 (rev. 0x01)
uhci0: interrupting at ioapic0 pin 23
usb0 at uhci0: USB revision 1.0
uhci1 at pci0 dev 29 function 1: vendor 0x8086 product 0x27c9 (rev. 0x01)
uhci1: interrupting at ioapic0 pin 19
usb1 at uhci1: USB revision 1.0
uhci2 at pci0 dev 29 function 2: vendor 0x8086 product 0x27ca (rev. 0x01)
uhci2: interrupting at ioapic0 pin 18
usb2 at uhci2: USB revision 1.0
uhci3 at pci0 dev 29 function 3: vendor 0x8086 product 0x27cb (rev. 0x01)
uhci3: interrupting at ioapic0 pin 16
usb3 at uhci3: USB revision 1.0
ehci0 at pci0 dev 29 function 7: vendor 0x8086 product 0x27cc (rev. 0x01)
ehci0: interrupting at ioapic0 pin 23
ehci0: EHCI version 1.0
ehci0: companion controllers, 2 ports each: uhci0 uhci1 uhci2 uhci3
usb4 at ehci0: USB revision 2.0
ppb1 at pci0 dev 30 function 0: vendor 0x8086 product 0x244e (rev. 0xe1)
pci2 at ppb1 bus 2
pci2: i/o space, memory space enabled
uhci4 at pci2 dev 0 function 0: vendor 0x1106 product 0x3038 (rev. 0x62)
uhci4: interrupting at ioapic0 pin 20
usb5 at uhci4: USB revision 1.0
uhci5 at pci2 dev 0 function 1: vendor 0x1106 product 0x3038 (rev. 0x62)
uhci5: interrupting at ioapic0 pin 19
usb6 at uhci5: USB revision 1.0
ehci1 at pci2 dev 0 function 2: vendor 0x1106 product 0x3104 (rev. 0x65)
ehci1: interrupting at ioapic0 pin 18
ehci1: dropped intr workaround enabled
ehci1: EHCI version 1.0
ehci1: companion controllers, 2 ports each: uhci4 uhci5
usb7 at ehci1: USB revision 2.0
fxp0 at pci2 dev 1 function 0: i82559 Ethernet (rev. 0x08)
fxp0: interrupting at ioapic0 pin 19
fxp0: Ethernet address 00:90:27:a2:f2:9e
inphy0 at fxp0 phy 1: i82555 10/100 media interface, rev. 4
inphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
ichlpcib0 at pci0 dev 31 function 0: vendor 0x8086 product 0x27b8 (rev. 0x01)
timecounter: Timecounter "ichlpcib0" frequency 3579545 Hz quality 1000
ichlpcib0: 24-bit timer
ichlpcib0: TCO (watchdog) timer configured.
gpio0 at ichlpcib0: 64 pins
piixide0 at pci0 dev 31 function 2: Intel 82801GB/GR Serial ATA/Raid Controller 
(ICH7) (rev. 0x01)
piixide0: bus-master DMA support present
piixide0: primary channel configured to compatibility mode
piixide0: primary channel interrupting at ioapic0 pin 14
atabus0 at piixide0 channel 0
piixide0: secondary channel configured to compatibility mode
piixide0: secondary channel interrupting at ioapic0 pin 15
atabus1 at piixide0 channel 1
ichsmb0 at pci0 dev 31 function 3: vendor 0x8086 product 0x27da (rev. 0x01)
ichsmb0: interrupting at ioapic0 pin 19
iic0 at ichsmb0: I2C bus
isa0 at ichlpcib0
acpicpu0 at cpu0: ACPI CPU
acpicpu0: C1: HLT, lat   0 us, pow     0 mW
acpicpu0: P0: I/O, lat 160 us, pow 22464 mW, 3000 MHz
acpicpu0: P1: I/O, lat 160 us, pow 22464 mW, 2800 MHz
acpicpu0: T0: I/O, lat   1 us, pow     0 mW, 100 %
acpicpu0: T1: I/O, lat   1 us, pow     0 mW,  50 %
acpicpu1 at cpu1: ACPI CPU
timecounter: Timecounter "clockinterrupt" frequency 100 Hz quality 0
timecounter: Timecounter "TSC" frequency 2992886850 Hz quality 3000
uhub0 at usb0: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhub1 at usb1: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
uhub2 at usb2: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
uhub3 at usb3: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub3: 2 ports with 2 removable, self powered
uhub4 at usb4: vendor 0x8086 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub4: 8 ports with 8 removable, self powered
uhub5 at usb5: vendor 0x1106 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub5: 2 ports with 2 removable, self powered
uhub6 at usb6: vendor 0x1106 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub6: 2 ports with 2 removable, self powered
uhub7 at usb7: vendor 0x1106 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub7: 4 ports with 4 removable, self powered
ehci0: handing over low speed device on port 5 to uhci2
wd0 at atabus0 drive 0
wd0: <SAMSUNG HD200HJ>
wd0: drive supports 16-sector PIO transfers, LBA48 addressing
wd0: 186 GB, 387618 cyl, 16 head, 63 sec, 512 bytes/sect x 390719855 sectors
uhidev0 at uhub2 port 1 configuration 1 interface 0
uhidev0: Logitech USB-PS/2 Optical Mouse, rev 2.00/11.10, addr 2, iclass 3/1
ums0 at uhidev0: 3 buttons and Z dir
wsmouse1 at ums0 mux 0
wd0: 32-bit data port
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 7
wd0(piixide0:0:0): using PIO mode 4, Ultra-DMA mode 6 (Ultra/133) (using DMA)
wd1 at atabus1 drive 0
wd1: <ST3320620AS>
wd1: drive supports 16-sector PIO transfers, LBA48 addressing
wd1: 298 GB, 620178 cyl, 16 head, 63 sec, 512 bytes/sect x 625140335 sectors
wd1: 32-bit data port
wd1: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133)
wd2 at atabus1 drive 1
wd2: <SAMSUNG SP2504C>
wd2: drive supports 16-sector PIO transfers, LBA48 addressing
wd2: 232 GB, 484518 cyl, 16 head, 63 sec, 512 bytes/sect x 488395055 sectors
wd2: 32-bit data port
wd2: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 7
wd1(piixide0:1:0): using PIO mode 4, Ultra-DMA mode 6 (Ultra/133) (using DMA)
wd2(piixide0:1:1): using PIO mode 4, Ultra-DMA mode 6 (Ultra/133) (using DMA)
Kernelized RAIDframe activated
boot device: wd0
root on wd0a dumps on wd0b
/: replaying log to memory
root file system type: ffs
/: replaying log to disk
tap0: Ethernet address f2:0b:a4:c3:b9:08
tap1: Ethernet address f2:0b:a4:c3:b9:08
tap2: Ethernet address f2:0b:a4:c3:b9:08
tap3: Ethernet address f2:0b:a4:ee:e0:08
tap4: Ethernet address f2:0b:a4:ee:e0:08
tap5: Ethernet address f2:0b:a4:ee:e0:08
tap6: Ethernet address f2:0b:a4:ee:e0:08
tap7: Ethernet address f2:0b:a4:ee:e0:08
tap8: Ethernet address f2:0b:a4:fd:07:09
tap9: Ethernet address f2:0b:a4:fd:07:09
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)
/dev/wd1g: file system not clean; please fsck(8)
i915drm0: interrupting at ioapic0 pin 16
pckbport: command timeout
pms_enable: command error 35
pckbport: command timeout
pckbport: command timeout
pms_disable: command error
pckbport: command timeout
pms_enable: command error 35
pckbport: command timeout
pms_disable: command error
pckbport: command timeout
pms_enable: command error 35
arp info overwritten for 172.17.12.17 by 00:21:91:0c:60:1d
arp info overwritten for 172.17.12.17 by 24:ab:81:9a:d1:95
arp info overwritten for 172.17.12.17 by 00:21:91:0c:60:1d
syn-proc4:/shared/syntagma4: inaccurate wcc data (ctime) detected, disabling 
wcc (ctime 1330501445.000000000 1330501445.000000000, mtime 
1330501445.000000000 1330501445.000000000)
syn-proc:/home: inaccurate wcc data (ctime) detected, disabling wcc (ctime 
1330513371.804572920 1330513371.804572920, mtime 1330513371.804572920 
1330513371.804572920)
arp info overwritten for 172.17.10.82 by 00:21:91:0c:60:1d
nfs server syn-proc:/home: not responding
nfs server syn-proc:/home: is alive again
arp info overwritten for 172.17.0.13 by 02:4c:8e:3e:04:ef
arp info overwritten for 172.17.0.13 by 1a:8d:72:e4:5a:e2
nfs server syn-proc7:/shared/syntagma2: not responding
nfs server syn-proc7:/shared/syntagma2: is alive again
pckbport: command timeout
pms_disable: command error
i915drm0: interrupting at ioapic0 pin 16
pckbport: command timeout
pms_enable: command error 35
nfs server syn-proc4:/shared/syntagma4: not responding
nfs server syn-proc4:/shared/syntagma4: is alive again
nfs server syn-proc7:/shared/syntagma2: not responding
nfs server syn-proc7:/shared/syntagma2: is alive again
pckbport: command timeout
pms_disable: command error
usl_detachtimeout
usl_detachack: not detaching
agpclose: mem 0 is bound
agpclose: mem 1 is bound
agpclose: mem 2 is bound
agpclose: mem 3 is bound
agpclose: mem 4 is bound
agpclose: mem 5 is bound
error: [drm:pid10692:i915_initialize] *ERROR* can not ioremap virtual address 
for ring buffer
pckbport: command timeout
pms_enable: command error 35
pckbport: command timeout
pms_disable: command error
pckbport: command timeout
pms_enable: command error 35
pckbport: command timeout
pms_disable: command error
pckbport: command timeout
pms_enable: command error 35
pckbport: command timeout
pms_disable: command error
usl_detachtimeout
usl_detachack: not detaching
pckbport: command timeout
pms_enable: command error 35
arp info overwritten for 172.17.10.82 by 7c:11:be:97:f6:d4
arp info overwritten for 172.17.10.82 by 00:21:91:0c:60:1d
arp info overwritten for 172.17.10.82 by 00:21:91:0c:60:1d
umass0 at uhub7 port 1 configuration 1 interface 0
umass0: JetFlash Mass Storage Device, rev 2.00/1.00, addr 2
umass0: using SCSI over Bulk-Only
scsibus0 at umass0: 2 targets, 1 lun per target
sd0 at scsibus0 target 0 lun 0: <JetFlash, Transcend 64GB, 8.07> disk removable
sd0: fabricating a geometry
sd0: 61280 MB, 61280 cyl, 64 head, 32 sec, 512 bytes/sect x 125501440 sectors
sd0: fabricating a geometry

Follow-Ups:
- Re: 6.0_BETA: Extreamly slow newfs_ext2fs on 60Gb USB stick
  - From: Izumi Tsutsui
- Re: 6.0_BETA: Extreamly slow newfs_ext2fs on 60Gb USB stick
  - From: Paul Fleischer

Prev by Date: Re: making kmem more efficient
Next by Date: Re: making kmem more efficient
Previous by Thread: making kmem more efficient
Next by Thread: Re: 6.0_BETA: Extreamly slow newfs_ext2fs on 60Gb USB stick
Indexes:

Home | Main Index | Thread Index | Old Index