[SOLVED] Major performance issue - 300 kBs on SMB transfers

[VJ8h8bwgHziT]

This is a new problem that had cropped up and I have no idea why. I did a lot of CIPF and FTP tuning and this is better than it was. Two days ago, I found I should scrub the ZFS so I started that process and it is still only at the beginning, indicating to me that the issue has nothing to do with SMB/CIPF

Here is the information screen:


Pool information and status

pool: RAIDZ-bpr
state: ONLINE
scan: scrub in progress since Thu May 29 21:35:40 2014
569G scanned out of 5.30T at 4.78M/s, 288h59m to go
0 repaired, 10.49% done
config:

NAME STATE READ WRITE CKSUM
RAIDZ-bpr ONLINE 0 0 0
raidz1-0 ONLINE 0 0 0
ada1 ONLINE 0 0 0
ada2 ONLINE 0 0 0
ada3 ONLINE 0 0 0
ada4 ONLINE 0 0 0
ada5 ONLINE 0 0 0

errors: No known data errors


I notice that when I shutdown, it is trying to write to a swap file that does not exist. It has 32 GB RAM and about 2% is used, along with about 0% of the quad core CPU.

Any suggestions for next steps?


Here are the last lines of the Diagnostic file in reverse order (newest at the top):

Date & Time User Event
May 31 14:50:47 nas4free login: login on ttyv0 as root
May 31 14:50:47 nas4free lighttpd[2518]: (log.c.164) server started
May 31 14:50:45 nas4free msmtp: host=mail.xxx.com tls=on auth=on user=xxx@xxx.com from=xxx@xxx.com recipients=xxx@xxx.xxx mailsize=9622 smtpstatus=250 smtpmsg='250 OK id=1WqoMe-0003QB-Uc' exitcode=EX_OK
May 31 14:50:41 nas4free smartd[2269]: Device: /dev/ada1, 686 Offline uncorrectable sectors
May 31 14:50:41 nas4free msmtp: host=mail.xxx.com tls=on auth=on user=xxx@xxx.com from=xxx@xxx.com recipients=xxx@xxx.xxx mailsize=9625 smtpstatus=250 smtpmsg='250 OK id=1WqoMb-0003P0-2f' exitcode=EX_OK
May 31 14:50:38 nas4free smartd[2269]: Device: /dev/ada1, 687 Currently unreadable (pending) sectors
May 31 14:50:35 nas4free proftpd[2077]: 192.168.1.250 - ProFTPD 1.3.4d (maint) (built Sun Apr 27 2014 14:58:28 CEST) standalone mode STARTUP
May 31 14:50:35 nas4free kernel: ada1 ada2 ada3 ada4 ada5
May 31 14:50:30 nas4free kernel: Trying to mount root from ufs:/dev/ufsid/5352ed2d5917550d [rw]...
May 31 14:50:30 nas4free kernel: Timecounter "TSC-low" frequency 1549582072 Hz quality 1000
May 31 14:50:30 nas4free kernel: SMP: AP CPU #1 Launched!
May 31 14:50:30 nas4free kernel: SMP: AP CPU #2 Launched!
May 31 14:50:30 nas4free kernel: SMP: AP CPU #3 Launched!
May 31 14:50:30 nas4free kernel: ada5: Previously was known as ad20
May 31 14:50:30 nas4free kernel: ada5: 3815447MB (7814037168 512 byte sectors: 16H 63S/T 16383C)
May 31 14:50:30 nas4free kernel: ada5: Command Queueing enabled
May 31 14:50:30 nas4free kernel: ada5: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
May 31 14:50:30 nas4free kernel: ada5: <WDC WD4000F9YZ-09N20L0 01.01A01> ATA-8 SATA 3.x device
May 31 14:50:30 nas4free kernel: ada5 at ahcich8 bus 0 scbus8 target 0 lun 0
May 31 14:50:30 nas4free kernel: ada4: Previously was known as ad18
May 31 14:50:30 nas4free kernel: ada4: 3815447MB (7814037168 512 byte sectors: 16H 63S/T 16383C)
May 31 14:50:30 nas4free kernel: ada4: Command Queueing enabled
May 31 14:50:30 nas4free kernel: ada4: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
May 31 14:50:30 nas4free kernel: ada4: <WDC WD4000F9YZ-09N20L0 01.01A01> ATA-8 SATA 3.x device
May 31 14:50:30 nas4free kernel: ada4 at ahcich7 bus 0 scbus7 target 0 lun 0
May 31 14:50:30 nas4free kernel: ada3: Previously was known as ad16
May 31 14:50:30 nas4free kernel: ada3: 3815447MB (7814037168 512 byte sectors: 16H 63S/T 16383C)
May 31 14:50:30 nas4free kernel: ada3: Command Queueing enabled
May 31 14:50:30 nas4free kernel: ada3: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
May 31 14:50:30 nas4free kernel: ada3: <WDC WD4000F9YZ-09N20L0 01.01A01> ATA-8 SATA 3.x device
May 31 14:50:30 nas4free kernel: ada3 at ahcich6 bus 0 scbus6 target 0 lun 0
May 31 14:50:30 nas4free kernel: ada2: Previously was known as ad14
May 31 14:50:30 nas4free kernel: ada2: 3815447MB (7814037168 512 byte sectors: 16H 63S/T 16383C)
May 31 14:50:30 nas4free kernel: ada2: Command Queueing enabled
May 31 14:50:30 nas4free kernel: ada2: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
May 31 14:50:30 nas4free kernel: ada2: <WDC WD4000F9YZ-09N20L0 01.01A01> ATA-8 SATA 3.x device
May 31 14:50:30 nas4free kernel: ada2 at ahcich5 bus 0 scbus5 target 0 lun 0
May 31 14:50:30 nas4free kernel: ada1: Previously was known as ad12
May 31 14:50:30 nas4free kernel: ada1: 3815447MB (7814037168 512 byte sectors: 16H 63S/T 16383C)
May 31 14:50:30 nas4free kernel: ada1: Command Queueing enabled
May 31 14:50:30 nas4free kernel: ada1: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
May 31 14:50:30 nas4free kernel: cd0: Attempt to query device size failed: NOT READY, Medium not present - tray closed
May 31 14:50:30 nas4free kernel: cd0: 150.000MB/s transfers (SATA 1.x, UDMA5, ATAPI 12bytes, PIO 8192bytes)
May 31 14:50:30 nas4free kernel: cd0: <ATAPI iHAS124 W HL0F> Removable CD-ROM SCSI-0 device
May 31 14:50:30 nas4free kernel: cd0 at ahcich1 bus 0 scbus1 target 0 lun 0
May 31 14:50:30 nas4free kernel: ada1: <WDC WD4000F9YZ-09N20L0 01.01A01> ATA-8 SATA 3.x device
May 31 14:50:30 nas4free kernel: ada1 at ahcich4 bus 0 scbus4 target 0 lun 0
May 31 14:50:30 nas4free kernel: ada0: Previously was known as ad4
May 31 14:50:30 nas4free kernel: ada0: 30533MB (62533296 512 byte sectors: 16H 63S/T 16383C)
May 31 14:50:30 nas4free kernel: ada0: Command Queueing enabled
May 31 14:50:30 nas4free kernel: ada0: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 512bytes)
May 31 14:50:30 nas4free kernel: ada0: <SanDisk SDSSDRC032G 3.0.0> ATA-9 SATA 3.x device
May 31 14:50:30 nas4free kernel: ada0 at ahcich0 bus 0 scbus0 target 0 lun 0
May 31 14:50:30 nas4free kernel: uhub3: 8 ports with 8 removable, self powered
May 31 14:50:30 nas4free kernel: uhub2: 6 ports with 6 removable, self powered
May 31 14:50:30 nas4free kernel: uhub3: <vendor 0x8087 product 0x8000, class 9/0, rev 2.00/0.04, addr 2> on usbus1
May 31 14:50:30 nas4free kernel: ugen1.2: <vendor 0x8087> at usbus1
May 31 14:50:30 nas4free kernel: uhub2: <vendor 0x8087 product 0x8008, class 9/0, rev 2.00/0.04, addr 2> on usbus0
May 31 14:50:30 nas4free kernel: ugen0.2: <vendor 0x8087> at usbus0
May 31 14:50:30 nas4free kernel: uhub1: 2 ports with 2 removable, self powered
May 31 14:50:30 nas4free kernel: uhub0: 2 ports with 2 removable, self powered
May 31 14:50:30 nas4free kernel: uhub1: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus1
May 31 14:50:30 nas4free kernel: ugen1.1: <Intel> at usbus1
May 31 14:50:30 nas4free kernel: uhub0: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus0
May 31 14:50:30 nas4free kernel: ugen0.1: <Intel> at usbus0
May 31 14:50:30 nas4free kernel: usbus1: 480Mbps High Speed USB v2.0
May 31 14:50:30 nas4free kernel: usbus0: 480Mbps High Speed USB v2.0
May 31 14:50:30 nas4free kernel: pcm2: <Realtek (0x0900) (Rear Digital)> at nid 30 on hdaa0
May 31 14:50:30 nas4free kernel: pcm1: <Realtek (0x0900) (Front Analog)> at nid 27 and 25 on hdaa0
May 31 14:50:30 nas4free kernel: pcm0: <Realtek (0x0900) (Rear Analog 5.1/2.0)> at nid 20,22,21 and 24,26 on hdaa0
May 31 14:50:30 nas4free kernel: hdaa0: <Realtek (0x0900) Audio Function Group> at nid 1 on hdacc0
May 31 14:50:30 nas4free kernel: hdacc0: <Realtek (0x0900) HDA CODEC> at cad 0 on hdac0
May 31 14:50:30 nas4free kernel: iSCSI boot driver version 0.2.6
May 31 14:50:30 nas4free kernel: ipfw2 (+ipv6) initialized, divert loadable, nat loadable, default to accept, logging disabled
May 31 14:50:30 nas4free kernel: Timecounters tick every 10.000 msec
May 31 14:50:30 nas4free kernel: ZFS storage pool version: features support (5000)
May 31 14:50:30 nas4free kernel: ZFS filesystem version: 5
May 31 14:50:30 nas4free kernel: p4tcc3: <CPU Frequency Thermal Control> on cpu3
May 31 14:50:30 nas4free kernel: est3: <Enhanced SpeedStep Frequency Control> on cpu3
May 31 14:50:30 nas4free kernel: coretemp3: <CPU On-Die Thermal Sensors> on cpu3
May 31 14:50:30 nas4free kernel: p4tcc2: <CPU Frequency Thermal Control> on cpu2
May 31 14:50:30 nas4free kernel: est2: <Enhanced SpeedStep Frequency Control> on cpu2
May 31 14:50:30 nas4free kernel: coretemp2: <CPU On-Die Thermal Sensors> on cpu2
May 31 14:50:30 nas4free kernel: p4tcc1: <CPU Frequency Thermal Control> on cpu1
May 31 14:50:30 nas4free kernel: est1: <Enhanced SpeedStep Frequency Control> on cpu1
May 31 14:50:30 nas4free kernel: coretemp1: <CPU On-Die Thermal Sensors> on cpu1
May 31 14:50:30 nas4free kernel: p4tcc0: <CPU Frequency Thermal Control> on cpu0
May 31 14:50:30 nas4free kernel: est0: <Enhanced SpeedStep Frequency Control> on cpu0
May 31 14:50:30 nas4free kernel: coretemp0: <CPU On-Die Thermal Sensors> on cpu0
May 31 14:50:30 nas4free kernel: ctl: CAM Target Layer loaded
May 31 14:50:30 nas4free kernel: ppc0: cannot reserve I/O port range
May 31 14:50:30 nas4free kernel: vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
May 31 14:50:30 nas4free kernel: sc0: VGA <16 virtual consoles, flags=0x300>
May 31 14:50:30 nas4free kernel: sc0: <System console> at flags 0x100 on isa0
May 31 14:50:30 nas4free kernel: orm0: <ISA Option ROMs> at iomem 0xc0000-0xccfff,0xcd000-0xcffff on isa0
May 31 14:50:30 nas4free kernel: atkbd0: [GIANT-LOCKED]
May 31 14:50:30 nas4free kernel: kbd0 at atkbd0
May 31 14:50:30 nas4free kernel: atkbd0: <AT Keyboard> irq 1 on atkbdc0
May 31 14:50:30 nas4free kernel: atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
May 31 14:50:30 nas4free kernel: acpi_button0: <Power Button> on acpi0
May 31 14:50:30 nas4free kernel: pci0: <serial bus, SMBus> at device 31.3 (no driver attached)
May 31 14:50:30 nas4free kernel: ahcich8: <AHCI channel> at channel 4 on ahci2
May 31 14:50:30 nas4free kernel: ahcich7: <AHCI channel> at channel 3 on ahci2
May 31 14:50:30 nas4free kernel: ahcich6: <AHCI channel> at channel 2 on ahci2
May 31 14:50:30 nas4free kernel: ahcich5: <AHCI channel> at channel 1 on ahci2
May 31 14:50:30 nas4free kernel: ahcich4: <AHCI channel> at channel 0 on ahci2
May 31 14:50:30 nas4free kernel: ahci2: AHCI v1.30 with 6 6Gbps ports, Port Multiplier not supported
May 31 14:50:30 nas4free kernel: ahci2: <Intel Lynx Point AHCI SATA controller> port 0xf070-0xf077,0xf060-0xf063,0xf050-0xf057,0xf040-0xf043,0xf020-0xf03f mem 0xf6706000-0xf67067ff irq 19 at device 31.2 on pci0
May 31 14:50:30 nas4free kernel: isa0: <ISA bus> on isab0
May 31 14:50:30 nas4free kernel: isab0: <PCI-ISA bridge> at device 31.0 on pci0
May 31 14:50:30 nas4free kernel: usbus1 on ehci1
May 31 14:50:30 nas4free kernel: usbus1: EHCI version 1.0
May 31 14:50:30 nas4free kernel: ehci1: <EHCI (generic) USB 2.0 controller> mem 0xf6707000-0xf67073ff irq 23 at device 29.0 on pci0
May 31 14:50:30 nas4free kernel: pci14: <ACPI PCI bus> on pcib14
May 31 14:50:30 nas4free kernel: pcib14: <ACPI PCI-PCI bridge> irq 16 at device 9.0 on pci6
May 31 14:50:30 nas4free kernel: pci13: <ACPI PCI bus> on pcib13
May 31 14:50:30 nas4free kernel: pcib13: <ACPI PCI-PCI bridge> irq 19 at device 0.0 on pci12
May 31 14:50:30 nas4free kernel: pci12: <ACPI PCI bus> on pcib12
May 31 14:50:30 nas4free kernel: pcib12: <ACPI PCI-PCI bridge> irq 19 at device 8.0 on pci6
May 31 14:50:30 nas4free kernel: pci11: <ACPI PCI bus> on pcib11
May 31 14:50:30 nas4free kernel: pcib11: <ACPI PCI-PCI bridge> irq 18 at device 7.0 on pci6
May 31 14:50:30 nas4free kernel: pci10: <ACPI PCI bus> on pcib10
May 31 14:50:30 nas4free kernel: pcib10: <ACPI PCI-PCI bridge> irq 17 at device 6.0 on pci6
May 31 14:50:30 nas4free kernel: pci9: <ACPI PCI bus> on pcib9
May 31 14:50:30 nas4free kernel: pcib9: <ACPI PCI-PCI bridge> irq 16 at device 5.0 on pci6
May 31 14:50:30 nas4free kernel: igb1: Bound queue 3 to cpu 3
May 31 14:50:30 nas4free kernel: igb1: Bound queue 2 to cpu 2
May 31 14:50:30 nas4free kernel: igb1: Bound queue 1 to cpu 1
May 31 14:50:30 nas4free kernel: igb1: Bound queue 0 to cpu 0
May 31 14:50:30 nas4free kernel: igb1: Ethernet address: bc:5f:f4:cb:2d:27
May 31 14:50:30 nas4free kernel: igb1: Using MSIX interrupts with 5 vectors
May 31 14:50:30 nas4free kernel: igb1: <Intel(R) PRO/1000 Network Connection version - 2.3.10> port 0x9000-0x901f mem 0xf6100000-0xf617ffff,0xf6180000-0xf6183fff irq 19 at device 0.0 on pci8
May 31 14:50:30 nas4free kernel: pci8: <ACPI PCI bus> on pcib8
May 31 14:50:30 nas4free kernel: pcib8: <ACPI PCI-PCI bridge> irq 19 at device 4.0 on pci6
May 31 14:50:30 nas4free kernel: pci7: <serial bus, FireWire> at device 0.0 (no driver attached)
May 31 14:50:30 nas4free kernel: pci7: <ACPI PCI bus> on pcib7
May 31 14:50:30 nas4free kernel: pcib7: <ACPI PCI-PCI bridge> irq 16 at device 1.0 on pci6
May 31 14:50:30 nas4free kernel: pci6: <ACPI PCI bus> on pcib6
May 31 14:50:30 nas4free kernel: pcib6: <ACPI PCI-PCI bridge> mem 0xf6300000-0xf631ffff irq 19 at device 0.0 on pci5
May 31 14:50:30 nas4free kernel: pci5: <ACPI PCI bus> on pcib5
May 31 14:50:30 nas4free kernel: pcib5: <ACPI PCI-PCI bridge> irq 19 at device 28.3 on pci0
May 31 14:50:30 nas4free kernel: igb0: Bound queue 3 to cpu 3
May 31 14:50:30 nas4free kernel: igb0: Bound queue 2 to cpu 2
May 31 14:50:30 nas4free kernel: igb0: Bound queue 1 to cpu 1
May 31 14:50:30 nas4free kernel: igb0: Bound queue 0 to cpu 0
May 31 14:50:30 nas4free kernel: igb0: Ethernet address: bc:5f:f4:cb:2d:25
May 31 14:50:30 nas4free kernel: igb0: Using MSIX interrupts with 5 vectors
May 31 14:50:30 nas4free kernel: igb0: <Intel(R) PRO/1000 Network Connection version - 2.3.10> port 0xb000-0xb01f mem 0xf6400000-0xf647ffff,0xf6480000-0xf6483fff irq 18 at device 0.0 on pci4
May 31 14:50:30 nas4free kernel: pci4: <ACPI PCI bus> on pcib4
May 31 14:50:30 nas4free kernel: pcib4: <ACPI PCI-PCI bridge> irq 18 at device 28.2 on pci0
May 31 14:50:30 nas4free kernel: ahcich3: <AHCI channel> at channel 1 on ahci1
May 31 14:50:30 nas4free kernel: ahcich2: <AHCI channel> at channel 0 on ahci1
May 31 14:50:30 nas4free kernel: ahci1: quirks=0x100<NOBSYRES>
May 31 14:50:30 nas4free kernel: ahci1: AHCI v1.00 with 2 6Gbps ports, Port Multiplier supported with FBS
May 31 14:50:30 nas4free kernel: ahci1: <Marvell 88SE9172 AHCI SATA controller> port 0xc040-0xc047,0xc030-0xc033,0xc020-0xc027,0xc010-0xc013,0xc000-0xc00f mem 0xf6510000-0xf65101ff irq 17 at device 0.0 on pci3
May 31 14:50:30 nas4free kernel: pci3: <ACPI PCI bus> on pcib3
May 31 14:50:30 nas4free kernel: pcib3: <ACPI PCI-PCI bridge> irq 17 at device 28.1 on pci0
May 31 14:50:30 nas4free kernel: ahcich1: <AHCI channel> at channel 1 on ahci0
May 31 14:50:30 nas4free kernel: ahcich0: <AHCI channel> at channel 0 on ahci0
May 31 14:50:30 nas4free kernel: ahci0: quirks=0x100<NOBSYRES>
May 31 14:50:30 nas4free kernel: ahci0: AHCI v1.00 with 2 6Gbps ports, Port Multiplier supported with FBS
May 31 14:50:30 nas4free kernel: ahci0: <Marvell 88SE9172 AHCI SATA controller> port 0xd040-0xd047,0xd030-0xd033,0xd020-0xd027,0xd010-0xd013,0xd000-0xd00f mem 0xf6610000-0xf66101ff irq 16 at device 0.0 on pci2
May 31 14:50:30 nas4free kernel: pci2: <ACPI PCI bus> on pcib2
May 31 14:50:30 nas4free kernel: pcib2: <ACPI PCI-PCI bridge> irq 16 at device 28.0 on pci0
May 31 14:50:30 nas4free kernel: hdac0: <Intel Lynx Point HDA Controller> mem 0xf6700000-0xf6703fff irq 22 at device 27.0 on pci0
May 31 14:50:30 nas4free kernel: usbus0 on ehci0
May 31 14:50:30 nas4free kernel: usbus0: EHCI version 1.0
May 31 14:50:30 nas4free kernel: ehci0: <EHCI (generic) USB 2.0 controller> mem 0xf6708000-0xf67083ff irq 16 at device 26.0 on pci0
May 31 14:50:30 nas4free kernel: pci0: <simple comms> at device 22.0 (no driver attached)
May 31 14:50:30 nas4free kernel: vgapci1: <VGA-compatible display> mem 0xf6020000-0xf602ffff at device 0.1 on pci1
May 31 14:50:30 nas4free kernel: vgapci0: <VGA-compatible display> port 0xe000-0xe0ff mem 0xf4000000-0xf5ffffff,0xf6030000-0xf603ffff irq 16 at device 0.0 on pci1
May 31 14:50:30 nas4free kernel: pci1: <ACPI PCI bus> on pcib1
May 31 14:50:30 nas4free kernel: pcib1: <ACPI PCI-PCI bridge> irq 16 at device 1.0 on pci0
May 31 14:50:30 nas4free kernel: pci0: <ACPI PCI bus> on pcib0
May 31 14:50:30 nas4free kernel: pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
May 31 14:50:30 nas4free kernel: acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1808-0x180b on acpi0
May 31 14:50:30 nas4free kernel: Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
May 31 14:50:30 nas4free kernel: Event timer "i8254" frequency 1193182 Hz quality 100
May 31 14:50:30 nas4free kernel: Timecounter "i8254" frequency 1193182 Hz quality 0
May 31 14:50:30 nas4free kernel: attimer0: <AT timer> port 0x40-0x43,0x50-0x53 irq 0 on acpi0
May 31 14:50:30 nas4free kernel: Event timer "RTC" frequency 32768 Hz quality 0
May 31 14:50:30 nas4free kernel: atrtc0: Warning: Couldn't map I/O.
May 31 14:50:30 nas4free kernel: atrtc0: <AT realtime clock> port 0x70-0x77 irq 8 on acpi0
May 31 14:50:30 nas4free kernel: Event timer "HPET4" frequency 14318180 Hz quality 440
May 31 14:50:30 nas4free kernel: Event timer "HPET3" frequency 14318180 Hz quality 440
May 31 14:50:30 nas4free kernel: Event timer "HPET2" frequency 14318180 Hz quality 440
May 31 14:50:30 nas4free kernel: Event timer "HPET1" frequency 14318180 Hz quality 440
May 31 14:50:30 nas4free kernel: Event timer "HPET" frequency 14318180 Hz quality 550
May 31 14:50:30 nas4free kernel: Timecounter "HPET" frequency 14318180 Hz quality 950
May 31 14:50:30 nas4free kernel: hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff on acpi0
May 31 14:50:30 nas4free kernel: cpu3: <ACPI CPU> on acpi0
May 31 14:50:30 nas4free kernel: cpu2: <ACPI CPU> on acpi0
May 31 14:50:30 nas4free kernel: cpu1: <ACPI CPU> on acpi0
May 31 14:50:30 nas4free kernel: cpu0: <ACPI CPU> on acpi0
May 31 14:50:30 nas4free kernel: acpi0: reservation of 67, 1 (4) failed
May 31 14:50:30 nas4free kernel: acpi0: Power Button (fixed)
May 31 14:50:30 nas4free kernel: acpi0: <ALASKA A M I> on motherboard
May 31 14:50:30 nas4free kernel: cryptosoft0: <software crypto> on motherboard
May 31 14:50:30 nas4free kernel: kbd1 at kbdmux0
May 31 14:50:30 nas4free kernel: ioapic0 <Version 2.0> irqs 0-23 on motherboard
May 31 14:50:30 nas4free kernel: ACPI Warning: FADT (revision 5) is longer than ACPI 2.0 version, truncating length 268 to 244 (20110527/tbfadt-320)
May 31 14:50:30 nas4free kernel: cpu3 (AP): APIC ID: 6
May 31 14:50:30 nas4free kernel: cpu2 (AP): APIC ID: 4
May 31 14:50:30 nas4free kernel: cpu1 (AP): APIC ID: 2
May 31 14:50:30 nas4free kernel: cpu0 (BSP): APIC ID: 0
May 31 14:50:30 nas4free kernel: FreeBSD/SMP: 1 package(s) x 4 core(s)
May 31 14:50:30 nas4free kernel: FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
May 31 14:50:30 nas4free kernel: ACPI APIC Table: <ALASKA A M I>
May 31 14:50:30 nas4free kernel: Event timer "LAPIC" quality 600
May 31 14:50:30 nas4free kernel: avail memory = 16455208960 (15692 MB)
May 31 14:50:30 nas4free kernel: real memory = 17179869184 (16384 MB)
May 31 14:50:30 nas4free kernel: TSC: P-state invariant, performance statistics
May 31 14:50:30 nas4free kernel: Standard Extended Features=0x2fbb<GSFSBASE,TSCADJ,SMEP,ENHMOVSB,INVPCID>
May 31 14:50:30 nas4free kernel: AMD Features2=0x21<LAHF,ABM>
May 31 14:50:30 nas4free kernel: AMD Features=0x2c100800<SYSCALL,NX,Page1GB,RDTSCP,LM>
May 31 14:50:30 nas4free kernel: Features2=0x7ffafbff<SSE3,PCLMULQDQ,DTES64,MON,DS_CPL,VMX,SMX,EST,TM2,SSSE3,<b11>,FMA,CX16,xTPR,PDCM,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,TSCDLT,AESNI,XSAVE,OSXSAVE,AVX,F16C,RDRAND>
May 31 14:50:30 nas4free kernel: Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
May 31 14:50:30 nas4free kernel: Origin = "GenuineIntel" Id = 0x306c3 Family = 0x6 Model = 0x3c Stepping = 3
May 31 14:50:30 nas4free kernel: CPU: Intel(R) Xeon(R) CPU E3-1220 v3 @ 3.10GHz (3099.16-MHz K8-class CPU)
May 31 14:50:30 nas4free kernel: gcc version 4.2.1 20070831 patched [FreeBSD]
May 31 14:50:30 nas4free kernel: root@dev.nas4free.org:/usr/obj/nas4free/usr/src/sys/NAS4FREE-amd64 amd64
May 31 14:50:30 nas4free kernel: FreeBSD 9.2-RELEASE-p4 #0 r264973M: Sun Apr 27 13:37:49 CEST 2014
May 31 14:50:30 nas4free kernel: FreeBSD is a registered trademark of The FreeBSD Foundation.
May 31 14:50:30 nas4free kernel: The Regents of the University of California. All rights reserved.
May 31 14:50:30 nas4free kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
May 31 14:50:30 nas4free kernel: Copyright (c) 1992-2013 The FreeBSD Project.
May 31 14:50:30 nas4free syslogd: kernel boot file is /boot/kernel/kernel

[crowi]

one of your drives has a major probelm:

May 31 14:50:41 nas4free smartd[2269]: Device: /dev/ada1, 686 Offline uncorrectable sectors

[VJ8h8bwgHziT]

I did see that, but did some research and did not think that it would lead to this kind of performance issue. That number has been a constant since I first noticed it (after I noticed the performance issue.)

I agree that the drive has an issue, but are you saying it is causing the performance problem?

Anything I can do short of buying a new drive?

FWIW - that drive has 7,814,037,168 sectors per http://www.wdc.com/wdproducts/library/S ... 771475.pdf
And the total disk array is only 20% full, 80% unused

[crowi]

the fill level doesn't matter. You should urgently exchange this drive.
And yes it can lead to performance issues when the system tries to read from corrupted sectors.
Did scrub report any repairs?

[VJ8h8bwgHziT]

Thank you so much for your help and advice. I will replace the drive with urgency!

I started the scrup on Thursday, as you can see from my original post on Saturday afternoon 10 hours ago. Here is it's up-to-the minute status:

pool: RAIDZ-bpr
state: ONLINE
scan: scrub in progress since Thu May 29 21:35:40 2014
755G scanned out of 5.30T at 5.37M/s, 247h30m to go
0 repaired, 13.90% done
config:

NAME STATE READ WRITE CKSUM
RAIDZ-bpr ONLINE 0 0 0
raidz1-0 ONLINE 0 0 0
ada1 ONLINE 0 0 0
ada2 ONLINE 0 0 0
ada3 ONLINE 0 0 0
ada4 ONLINE 0 0 0
ada5 ONLINE 0 0 0

errors: No known data errors



So as you can see, it is now 13.90% complete with an estimated 247hours 30 minutes remaining. About 10 hours ago as you can see above, it was 10.49% complete with 288 hours and 59 minutes to go. The good news is still no known data errors.

[VJ8h8bwgHziT]

Related performance question - this system has no swap file but has 16 GB RAM and only a few percent seem to be used at any point in time.

Would a swap file be advised? The system boots off of an SSD that is not part of the array - would it make sense to put a swap file there, or on the array as a separate volume or dataset?

Thank you for helping out a beginner!

[crowi]

No swap won't be needed. Use ZFSkerneltune to optimize RAM:
viewtopic.php?f=71&t=1278

[VJ8h8bwgHziT]

Thank you. I have a contacted the vendor, Western Digital, and they are sending a new disk as an exchange - no questions asked once they learned that it has bad sectors and was less than 5 years old.
Why is the system so slow? The CPU usage is an average of 0% for all cores, with an occasional peak of 1% on a single core.... and the disk I/O is only about 6 MB/s - I would expect the CPU to be working this scrub as fast as the disks can read the data - that is why I had not expected that the bad sectors were the root cause of the exceedingly poor performance. Below is the status of the scrub and the status of the processes:

pool: RAIDZ-bpr
state: ONLINE
scan: scrub in progress since Thu May 29 21:35:40 2014
1.76T scanned out of 5.30T at 5.72M/s, 180h15m to go
288K repaired, 33.28% done
config:

NAME STATE READ WRITE CKSUM
RAIDZ-bpr ONLINE 0 0 0
raidz1-0 ONLINE 0 0 0
ada1 ONLINE 0 0 0 (repairing)
ada2 ONLINE 0 0 0
ada3 ONLINE 0 0 0
ada4 ONLINE 0 0 0
ada5 ONLINE 0 0 0

errors: No known data errors

capacity operations bandwidth
pool alloc free read write read write
---------- ----- ----- ----- ----- ----- -----
RAIDZ-bpr 5.32T 12.8T 43 15 4.56M 136K
raidz1 5.32T 12.8T 43 15 4.56M 136K
ada1 - - 15 5 1.16M 44.2K
ada2 - - 31 5 1.15M 44.2K
ada3 - - 31 5 1.15M 44.2K
ada4 - - 31 5 1.15M 44.2K
ada5 - - 31 5 1.15M 44.3K
---------- ----- ----- ----- ----- ----- -----





Here are the processes:

last pid: 34034; load averages: 0.09, 0.04, 0.01 up 2+13:21:16 04:10:42
20 processes: 1 running, 19 sleeping

Mem: 20M Active, 30M Inact, 6348M Wired, 27M Buf, 9384M Free
ARC: 5925M Total, 414M MFU, 5420M MRU, 16K Anon, 85M Header, 5835K Other
Swap:


PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
2518 root 1 20 0 35320K 5340K kqread 2 0:15 0.00% lighttpd
2211 root 1 20 0 76212K 10944K select 2 0:09 0.00% smbd
2077 root 1 20 0 29760K 5140K select 1 0:01 0.00% proftpd
2208 root 1 20 0 67596K 7372K select 3 0:01 0.00% nmbd
98522 root 1 20 0 85176K 12560K select 3 0:01 0.00% smbd
2247 root 1 20 0 76212K 11104K select 3 0:00 0.00% smbd
1881 root 1 20 0 12112K 1772K select 3 0:00 0.00% syslogd
2405 root 1 20 0 14176K 1856K nanslp 3 0:00 0.00% cron
2322 root 1 20 0 25984K 3784K nanslp 3 0:00 0.00% smartd
1788 root 1 20 0 6280K 740K select 2 0:00 0.00% devd
34033 root 1 22 0 91660K 18148K piperd 0 0:00 0.00% php-cgi
2665 root 1 52 0 14508K 3140K pause 2 0:00 0.00% csh
2662 root 1 52 0 45332K 2332K wait 2 0:00 0.00% login
2673 root 1 20 0 14536K 2716K ttyin 1 0:00 0.00% sh
1430 _dhcp 1 20 0 12080K 1920K select 2 0:00 0.00% dhclient
1392 root 1 27 0 12080K 1884K select 1 0:00 0.00% dhclient
34034 root 1 21 0 16596K 2300K CPU1 1 0:00 0.00% top
2664 root 1 52 0 12084K 1676K ttyin 0 0:00 0.00% getty

[crowi]

Stop the current scrub and shutdown your server !

Wait until you get the replacement drive and resilver your pool with the new drive:

ada1 ONLINE 0 0 0 (repairing)

I strongly believe the slow performance comes from the bad drive.
Don't stress the system any further, in order not to loose a second drive and thus to shred your data.

[b0ssman]

your wd drives do not have tler (time limited error recovery)

if they encounter an error while reading they try again and again to read the sector until they get it right.
during this time the entire io stalls.
that could be one explanation for the bad performance.

[VJ8h8bwgHziT]

Documenting so that it may help others:

I stopped the scrub with this command: zpool scrub -s RAIDZ-brp

Here is the confirmation:

pool: RAIDZ-bpr
state: ONLINE
scan: scrub canceled on Tue Jun 3 05:49:53 2014
config:

NAME STATE READ WRITE CKSUM
RAIDZ-bpr ONLINE 0 0 0
raidz1-0 ONLINE 0 0 0
ada1 ONLINE 0 0 0
ada2 ONLINE 0 0 0
ada3 ONLINE 0 0 0
ada4 ONLINE 0 0 0
ada5 ONLINE 0 0 0

errors: No known data errors


Then I powered down the system and am waiting for the replacement drive.

Thanks for your help on this - I am technical but very new to storage. Your advice makes sense - once the scrub found errors it began repairing only the defective drive.

[00Roush]

Could you possibly post up a little more info about your setup? There is a good chance that the HDD with errors is your performance problem but It always help to have the full picture of the setup when helping folks track down performance problems. CPU, RAM, motherboard, NIC, NAS4Free version and are you running in a VM? In some cases hardware is not supported or not well supported in FreeBSD (base OS for NAS4Free) which can also cause low performance. So I figured we could check that too.

Let us know.

00Roush

[VJ8h8bwgHziT]

I had upgraded to the new 9.2.0.1.959. Config is below. I will post an update after I change drives. My plan is to physically replace that drive in the same slot with the same cabling while the machine is off, then power on the machine per viewtopic.php?f=66&t=1366#p5619 Any issues?


Custom Built NAS Server
Processor Intel Quad-Core Xeon E3-1220V3 Haswell 3.1GHz 8MB L3 Cache LGA 1150
Fan for CPU Cooler Thermaltake NiC C5
Motherboard ASRock C226 WS ATX Server Motherboard LGA 1150
Memory Crucial 16GB (2 x 8GB) ECC Unbuffered DDR3 1600 (PC3 12800)
Hard Drive (OS) SanDisk SSD 32GB SATA III
Hard Drive (Data) (5) Western Digital SE WD4000F9YZ 4TB 7200 RPM 64MB Cache SATA 6.0Gb/s
Hot-Swap Cage (2) Xigmatek COA-UGOCBS-U01 Universal 3 in 3 SATA HDD w/120mm Fan
Optical Drive 24X DVD RW
Computer Case Antec Twelve Hundred V3
Power Supply EVGA SuperNOVA 650W (80 Plus GOLD Certified) (Full Modular) 10Year Warranty
Video - old PCI card circa 2005

[VJ8h8bwgHziT]

Replacement disk is here and the resilvering process is underway. LOOK AT THOSE DISK I/O SPEEDS! Although it is not finished, it seems certain that the replacement disk will fix the issue. With the resilvering process, I am seeing 10-20% CPU usage and 5% RAM usage (of 16 GB RAM). Hope this information helps someone in the future with similar problem.

pool: RAIDZ-bpr
state: DEGRADED
status: One or more devices is currently being resilvered. The pool will
continue to function, possibly in a degraded state.
action: Wait for the resilver to complete.
scan: resilver in progress since Thu Jun 5 19:12:07 2014
194G scanned out of 5.32T at 325M/s, 4h36m to go
38.8G resilvered, 3.56% done
config:

NAME STATE READ WRITE CKSUM
RAIDZ-bpr DEGRADED 0 0 0
raidz1-0 DEGRADED 0 0 0
replacing-0 UNAVAIL 0 0 0
10541922745487076773 UNAVAIL 0 0 0 was /dev/ada1/old
ada1 ONLINE 0 0 0 (resilvering)
ada2 ONLINE 0 0 0
ada3 ONLINE 0 0 0
ada4 ONLINE 0 0 0
ada5 ONLINE 0 0 0

errors: No known data errors


capacity operations bandwidth
pool alloc free read write read write
-------------------------- ----- ----- ----- ----- ----- -----
RAIDZ-bpr 5.32T 12.8T 1.35K 134 143M 597K
raidz1 5.32T 12.8T 1.35K 134 143M 597K
replacing - - 0 2.05K 0 58.7M
10541922745487076773 - - 0 0 0 0
ada1 - - 0 1.41K 55 58.7M
ada2 - - 781 5 36.1M 33.5K
ada3 - - 813 5 36.1M 33.6K
ada4 - - 801 5 36.1M 33.9K
ada5 - - 792 5 36.1M 34.0K
-------------------------- ----- ----- ----- ----- ----- -----

[crowi]

at 325M/s,

nice! That's how it should behave.

Thanks for the feedback.

[b0ssman]

you should set up smart monitoring with email messaging to catch these errors in the future.

[VJ8h8bwgHziT]

The system is back and running at full speed again. I did set up the SMART monitoring and email notifications.

b0ssman and crowi - THANK YOU SO MUCH!

[VJ8h8bwgHziT]

Everything seems to be working perfectly... but when I go to the DISK management page, I see this error:

"The device(s) in config are different to actual device(s). Please remove the device(s) and re-add it or use 'Clear config and Import disks'. "

I deleted the disk with the red "X" next to it, then clicked on the button "Clear config and import disks" and the error went away and everything seems fine with no errors now.

[raulfg3]

Everything seems to be working perfectly... but when I go to the DISK management page, I see this error:

"The device(s) in config are different to actual device(s). Please remove the device(s) and re-add it or use 'Clear config and Import disks'. "

I deleted the disk with the red "X" next to it, then clicked on the button "Clear config and import disks" and the error went away and everything seems fine with no errors now.

This is normal, and as you see is safe to use "Clear config & Import Disk", only remember that this import reset your SMART values to webGUI default, so probably you need to edit each HD by Hand to re-enable SMART monitoring if you need this feature.

[VJ8h8bwgHziT]

Thank you, raulfg3.

After reading your reply, I did check each drive to ensure that SMART was still enabled with the setting before the defective drive was replace - each was. There was nothing that I needed to do that I can see regarding the SMART settings.

Related question regarding desilvering in ZFS - The replacement drive I used was right from the factory - never been used - not formatting and no data. I bought a spare drive of the same model that I intend to use in a different PC and have on standby should another ZFS drive fail. In that scenario, the drive will have been used and formatted NTFS in Windows 8.1. Would the desilvering work the same way in NAS4FREE with a pre-formatted drive? If not, how should I prepare that drive for insertion into the array for desilvering?

[b0ssman]

yes resilvering works the same. just make sure that the existing parition on the drive is not mounted before you start the resilvering process.

before i use a factory new disk i generally run a burn in test on the drive using
badblocks -wvsb 4096 /dev/<disk>
and check the smart values afterwards.

[VJ8h8bwgHziT]

"yes resilvering works the same. just make sure that the existing parition on the drive is not mounted before you start the resilvering process."

Yes. I would indend to do exactly what I did above - power off the ZFS array, remove the old drive and replace it with the pre-formatted Windows NTFS drive that had been used in a different PC - using the same slot/cables. Then I would power on the ZFS array and use the GUI as I did above with the new (never used, never formatted drive.)

(I am documenting this not just for my future reference, but to have a complete step-by-step procedure for others.)