Copying files from windows pauses entire NAS for 20 seconds

[AdrianW]

Often when I start copying a large file (200MB+) to my TS-859 from Windows 7 (to an UNC path - eg \\NasName\ShareName\FolderName) - I'll get the "discovering items..." message in the copy dialog. This lasts for around 20 seconds, and meanwhile ALL other access to the NAS is halted (eg. if my wife is streaming a video it just stops). (All the drives were already all spun-up).

While this is happening the lights for just drives 2, 4 & 7 are blinking (I have 8 drives in a single RAID 6 array).

Once the copy is underway, everything seems fine - I can often upload more files without any more pauses to the system. But, sometimes, even after waiting only 30 seconds, copying a second file will again pause the NAS.

Looking at the process list, smbd starts up and sits at around 4% cpu during those first 20 seconds and then when the copy actually gets underway it goes up to 80-90%.

I have a TS-859, with the latest firmware, 8 Samsung HD204UI drives (with the firmware update). I have virtually all services switched off (I just use windows networking and the web file manager).

Does anyone else have this issue?

And does anyone know what I can do to prevent it from happening?

Note: I've asked this question before without any answers - see: Copying files via samba slow to start

[AdrianW]

{bump}

So, am I the only one that has this issue?

The copy speed is fine, it's just that regularly the ** thing just sits there for twenty seconds thinking about it before the copy even starts.

[schumaku]

Disk-based recovery of write problems?

[QNAPDavidchang]

Hi AdrianW

how is NAS working through web file manager upload files?
is that also pause NAS again?

Regards
David.Chang

[AdrianW]

how is NAS working through web file manager upload files?
is that also pause NAS again?

Regards
David.Chang

I just tried uploading a 700MB file to my NAS via the Web File Manager and it did exactly the same thing: paused for around 20 seconds (the lights for drives 2, 4 & 7 were blinking during this time) and then the copy started.

[QNAPDavidchang]

hi AdrianW

it will helpful if you collect these message for me
# df

# demsg

# mount

# cat /proc/mdstat

Regards
David.Chang

[AdrianW]

OK - I'll do that as soon as I get home from work (in about 8 hours).

[AdrianW]

David - here's the info you asked for:

Code: Select all

[~] # df
Filesystem                Size      Used Available Use% Mounted on
/dev/ramdisk            139.5M    116.2M     23.2M  83% /
tmpfs                    32.0M    120.0k     31.9M   0% /tmp
/dev/sda4               310.0M    166.5M    143.4M  54% /mnt/ext
/dev/md9                509.5M     47.6M    461.9M   9% /mnt/HDA_ROOT
/dev/md0                 10.7T      4.9T      5.9T  45% /share/MD0_DATA
tmpfs                    32.0M         0     32.0M   0% /.eaccelerator.tmp

Code: Select all

[~] # dmesg
back data mode
[   43.342400] kjournald starting.  Commit interval 5 seconds
[   43.342419] EXT3-fs (sdh1): mounted filesystem with writeback data mode
[   43.807685] md: md9 stopped.
[   43.889647] md: bind<sdb1>
[   43.889919] md: bind<sdc1>
[   43.890181] md: bind<sdd1>
[   43.890497] md: bind<sdf1>
[   43.890814] md: bind<sde1>
[   43.891126] md: bind<sdg1>
[   43.891453] md: bind<sdh1>
[   43.891701] md: bind<sda1>
[   43.893560] raid1: raid set md9 active with 8 out of 8 mirrors
[   43.898200] md9: bitmap initialized from disk: read 5/5 pages, set 0 bits
[   43.898319] created bitmap (65 pages) for device md9
[   43.922480] md9: detected capacity change from 0 to 542769152
[   43.927046]  md9: unknown partition table
[   44.977659] kjournald starting.  Commit interval 5 seconds
[   45.121189] EXT3-fs (md9): using internal journal
[   45.121375] EXT3-fs (md9): mounted filesystem with writeback data mode
[   45.593030] md: md13 stopped.
[   45.884420] md: bind<sdb4>
[   45.884691] md: bind<sdc4>
[   45.884943] md: bind<sdd4>
[   45.885265] md: bind<sde4>
[   45.885588] md: bind<sdf4>
[   45.885900] md: bind<sdg4>
[   45.886207] md: bind<sdh4>
[   45.886471] md: bind<sda4>
[   45.888314] raid1: raid set md13 active with 8 out of 8 mirrors
[   45.892319] md13: bitmap initialized from disk: read 4/4 pages, set 0 bits
[   45.892440] created bitmap (57 pages) for device md13
[   45.932616] md13: detected capacity change from 0 to 469893120
[   45.937173]  md13: unknown partition table
[   47.395992] kjournald starting.  Commit interval 5 seconds
[   47.505669] EXT3-fs (md9): using internal journal
[   47.505853] EXT3-fs (md9): mounted filesystem with writeback data mode
[   65.560685] kjournald starting.  Commit interval 5 seconds
[   65.652236] EXT3-fs (md9): using internal journal
[   65.652436] EXT3-fs (md9): mounted filesystem with writeback data mode
[  116.408328] kjournald starting.  Commit interval 5 seconds
[  116.515013] EXT3-fs (md13): using internal journal
[  116.515223] EXT3-fs (md13): mounted filesystem with writeback data mode
[  125.023285] usbcore: registered new interface driver hiddev
[  125.513982] generic-usb 0003:051D:0002.0001: hiddev96: USB HID v1.10 Device [APC Back-UPS ES 700G FW:871.O2 .I USB FW:O2 ] on usb-0000:00:1d.2-1/input0
[  125.514623] usbcore: registered new interface driver usbhid
[  125.514769] usbhid: USB HID core driver
[  125.520403] Register ICH/PCH RTC driver.
[  125.529508] iTCO_vendor_support: vendor-support=0
[  125.536199] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.05
[  125.537103] iTCO_wdt: Found a ICH9R TCO device (Version=2, TCOBASE=0x0860)
[  125.542239] iTCO_wdt: initialized. heartbeat=120 sec (nowayout=0)
[  125.552516] usbcore: registered new interface driver usblp
[  125.563106] ufsd: module license 'Commercial product' taints kernel.
[  125.563230] Disabling lock debugging due to kernel taint
[  125.589499] ufsd: driver 8.3 (Mar 31 2011 01:50:57) with acl LBD=OFF with ioctl loaded at ffffffffa00ae000
[  125.589505] NTFS read/write support included
[  125.589507] Hfs+/HfsX read/write support included
[  125.613324] fnotify: Load file notify kernel module.
[  125.613799] fnotify:   Global_Private_Data_List_Init()
[  125.613981] fnotify:   Launch the fnotify thread: 1899
[  125.613999] fnotify:   The fnotify thread starts...
[  126.674449] usbcore: registered new interface driver snd-usb-audio
[  126.684087] usbcore: registered new interface driver snd-usb-caiaq
[  126.712074] 802.1Q VLAN Support v1.8 Ben Greear <greearb@candelatech.com>
[  126.712210] All bugs added by David S. Miller <davem@redhat.com>
[  127.255188] kjournald starting.  Commit interval 5 seconds
[  127.270502] EXT3-fs (md9): using internal journal
[  127.270687] EXT3-fs (md9): mounted filesystem with writeback data mode
[  129.975136] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
[  133.274325] md: bind<sda2>
[  133.276038] raid1: raid set md8 active with 1 out of 1 mirrors
[  133.276200] md8: detected capacity change from 0 to 542769152
[  134.281413]  md8: unknown partition table
[  136.333228] Adding 530040k swap on /dev/md8.  Priority:-1 extents:1 across:530040k
[  141.001794] md: bind<sdb2>
[  141.012625] RAID1 conf printout:
[  141.012750]  --- wd:1 rd:2
[  141.012869]  disk 0, wo:0, o:1, dev:sda2
[  141.012989]  disk 1, wo:1, o:1, dev:sdb2
[  141.013270] md: recovery of RAID array md8
[  141.013413] md: minimum _guaranteed_  speed: 5000 KB/sec/disk.
[  141.013535] md: using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for recovery.
[  141.013708] md: using 128k window, over a total of 530048 blocks.
[  143.111179] md: bind<sdc2>
[  145.306910] md: bind<sdd2>
[  147.404115] md: bind<sde2>
[  149.600198] md: bind<sdf2>
[  151.773916] md: bind<sdg2>
[  152.995541] md: md8: recovery done.
[  153.034176] RAID1 conf printout:
[  153.034288]  --- wd:2 rd:2
[  153.034388]  disk 0, wo:0, o:1, dev:sda2
[  153.034492]  disk 1, wo:0, o:1, dev:sdb2
[  153.874300] md: bind<sdh2>
[  156.567239] active port 0 :139
[  156.567359] active port 1 :445
[  156.567455] active port 2 :20
[  174.474737] md: md0 stopped.
[  174.485115] md: md0 stopped.
[  174.621339] md: bind<sdb3>
[  174.621623] md: bind<sdc3>
[  174.621875] md: bind<sdd3>
[  174.622206] md: bind<sde3>
[  174.622515] md: bind<sdf3>
[  174.622837] md: bind<sdg3>
[  174.623158] md: bind<sdh3>
[  174.623416] md: bind<sda3>
[  174.625032] raid5: device sda3 operational as raid disk 0
[  174.625144] raid5: device sdh3 operational as raid disk 7
[  174.625249] raid5: device sdg3 operational as raid disk 6
[  174.625359] raid5: device sdf3 operational as raid disk 5
[  174.625467] raid5: device sde3 operational as raid disk 4
[  174.625572] raid5: device sdd3 operational as raid disk 3
[  174.625677] raid5: device sdc3 operational as raid disk 2
[  174.625782] raid5: device sdb3 operational as raid disk 1
[  174.644088] raid5: allocated 135840kB for md0
[  174.644372] 0: w=1 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
[  174.644484] 7: w=2 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
[  174.644588] 6: w=3 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
[  174.644693] 5: w=4 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
[  174.644798] 4: w=5 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
[  174.644902] 3: w=6 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
[  174.645022] 2: w=7 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
[  174.645127] 1: w=8 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
[  174.645232] raid5: raid level 6 set md0 active with 8 out of 8 devices, algorithm 2
[  174.645398] RAID5 conf printout:
[  174.645493]  --- rd:8 wd:8
[  174.645588]  disk 0, o:1, dev:sda3
[  174.645686]  disk 1, o:1, dev:sdb3
[  174.645783]  disk 2, o:1, dev:sdc3
[  174.645881]  disk 3, o:1, dev:sdd3
[  174.645978]  disk 4, o:1, dev:sde3
[  174.646087]  disk 5, o:1, dev:sdf3
[  174.646189]  disk 6, o:1, dev:sdg3
[  174.646286]  disk 7, o:1, dev:sdh3
[  174.646482] md0: detected capacity change from 0 to 11992753766400
[  175.950519]  md0: unknown partition table
[  188.700631] EXT4-fs (md0): mounted filesystem with ordered data mode
[  214.723108] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
[  244.541144] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
[  268.993195] active port 0 :139
[  268.993307] active port 1 :445
[  268.993407] active port 2 :20
[  302.353179]  Set Adpater:port=0:0 standby to 242 (3600 secs).
[  302.357883]  Set Adpater:port=0:1 standby to 242 (3600 secs).
[  302.362604]  Set Adpater:port=0:2 standby to 242 (3600 secs).
[  302.367411]  Set Adpater:port=0:3 standby to 242 (3600 secs).
[  304.389297] rule type=1, num=2
[  304.684814] Loading iSCSI transport class v2.0-871.
[  304.732433] iscsi: registered transport (tcp)
[~] #

Code: Select all

[~] # mount
/proc on /proc type proc (rw)
none on /dev/pts type devpts (rw,gid=5,mode=620)
sysfs on /sys type sysfs (rw)
tmpfs on /tmp type tmpfs (rw,size=32M)
none on /proc/bus/usb type usbfs (rw)
/dev/sda4 on /mnt/ext type ext3 (rw)
/dev/md9 on /mnt/HDA_ROOT type ext3 (rw)
/dev/md0 on /share/MD0_DATA type ext4 (rw,usrjquota=aquota.user,jqfmt=vfsv0,user_xattr,data=ordered,nodelalloc,noacl)
tmpfs on /.eaccelerator.tmp type tmpfs (rw,size=32M)

Code: Select all

[~] # cat /proc/mdstat
Personalities : [linear] [raid0] [raid1] [raid10] [raid6] [raid5] [raid4] [multipath]
md0 : active raid6 sda3[0] sdh3[7] sdg3[6] sdf3[5] sde3[4] sdd3[3] sdc3[2] sdb3[1]
      11711673600 blocks level 6, 64k chunk, algorithm 2 [8/8] [UUUUUUUU]

md8 : active raid1 sdh2[2](S) sdg2[3](S) sdf2[4](S) sde2[5](S) sdd2[6](S) sdc2[7](S) sdb2[1] sda2[0]
      530048 blocks [2/2] [UU]

md13 : active raid1 sda4[0] sdh4[7] sdg4[6] sdf4[5] sde4[4] sdd4[3] sdc4[2] sdb4[1]
      458880 blocks [8/8] [UUUUUUUU]
      bitmap: 0/57 pages [0KB], 4KB chunk

md9 : active raid1 sda1[0] sdh1[7] sdg1[6] sde1[5] sdf1[4] sdd1[3] sdc1[2] sdb1[1]
      530048 blocks [8/8] [UUUUUUUU]
      bitmap: 0/65 pages [0KB], 4KB chunk

unused devices: <none>

[schumaku]

The dmesg looks like sharp after a boot, and not like a pure QNAP (busybox) standard dmesg (back data mode, time stamps, ...) output. Different shell, config, or dmesg image in place?

Have experiened any 20 sec. pauses since this boot?

Please alternativley provide the output from this command:

[~] # tail -1000 /mnt/HDA_ROOT/.logs/kmsg

[AdrianW]

Yes, I've had the delays today - it happens every day. I have the NAS set to automatically power up and power down each day. It normally stays on for around 10 hours a day.

Here's the kmsg log (immediately after I copied a file & had the delay occur again):

Code: Select all

<6>[   32.292612] hub 5-0:1.0: USB hub found
<6>[   32.292750] hub 5-0:1.0: 2 ports detected
<6>[   32.293055] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ                 23
<7>[   32.293224] uhci_hcd 0000:00:1d.0: setting latency timer to 64
<6>[   32.293234] uhci_hcd 0000:00:1d.0: UHCI Host Controller
<6>[   32.293437] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus nu                mber 6
<6>[   32.293715] uhci_hcd 0000:00:1d.0: irq 23, io base 0x0000a400
<6>[   32.302429] hub 6-0:1.0: USB hub found
<6>[   32.302587] hub 6-0:1.0: 2 ports detected
<6>[   32.302939] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ                 19
<7>[   32.303124] uhci_hcd 0000:00:1d.1: setting latency timer to 64
<6>[   32.303135] uhci_hcd 0000:00:1d.1: UHCI Host Controller
<6>[   32.303324] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus nu                mber 7
<6>[   32.303627] uhci_hcd 0000:00:1d.1: irq 19, io base 0x0000a080
<6>[   32.325833] hub 7-0:1.0: USB hub found
<6>[   32.325987] hub 7-0:1.0: 2 ports detected
<6>[   32.326303] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ                 18
<7>[   32.326489] uhci_hcd 0000:00:1d.2: setting latency timer to 64
<6>[   32.326499] uhci_hcd 0000:00:1d.2: UHCI Host Controller
<6>[   32.326656] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus nu                mber 8
<6>[   32.326895] uhci_hcd 0000:00:1d.2: irq 18, io base 0x0000a000
<6>[   32.369194] hub 8-0:1.0: USB hub found
<6>[   32.369363] hub 8-0:1.0: 2 ports detected
<6>[   32.450179] Initializing USB Mass Storage driver...
<6>[   32.453181] usbcore: registered new interface driver usb-storage
<6>[   32.453363] USB Mass Storage support registered.
<4>[   32.453528] usb: create proc systemp successfully
<4>[   32.453671] usb: create proc systemp successfully
<6>[   32.540044] usb 2-1: new high speed USB device using ehci_hcd and address                 2
<4>[   32.664367] Using EHCI controller.
<6>[   32.664688] scsi12 : usb-storage 2-1:1.0
<6>[   32.922040] usb 8-1: new low speed USB device using uhci_hcd and address 2
<5>[   37.666487] scsi 12:0:0:0: Direct-Access              USB DISK MODULE  PMA                P PQ: 0 ANSI: 0 CCS
<5>[   37.668164] sd 12:0:0:0: Attached scsi generic sg23 type 0
<5>[   37.668420] sd 12:0:0:0: [sdx] 1007616 512-byte logical blocks: (515 MB/49                2 MiB)
<5>[   37.672854] sd 12:0:0:0: [sdx] Write Protect is off
<7>[   37.672990] sd 12:0:0:0: [sdx] Mode Sense: 23 00 00 00
<3>[   37.672998] sd 12:0:0:0: [sdx] Assuming drive cache: write through
<3>[   37.675995] sd 12:0:0:0: [sdx] Assuming drive cache: write through
<6>[   37.676187]  sdx: sdx1 sdx2 sdx3 sdx4 < sdx5 sdx6 >
<3>[   37.690660] sd 12:0:0:0: [sdx] Assuming drive cache: write through
<5>[   37.690813] sd 12:0:0:0: [sdx] Attached SCSI removable disk
<6>[   42.720889] kjournald starting.  Commit interval 5 seconds
<6>[   42.720905] EXT3-fs (sda1): mounted filesystem with writeback data mode
<6>[   42.793995] kjournald starting.  Commit interval 5 seconds
<6>[   42.794012] EXT3-fs (sdb1): mounted filesystem with writeback data mode
<6>[   42.858994] kjournald starting.  Commit interval 5 seconds
<6>[   42.859014] EXT3-fs (sdc1): mounted filesystem with writeback data mode
<6>[   42.957396] kjournald starting.  Commit interval 5 seconds
<6>[   42.957416] EXT3-fs (sdd1): mounted filesystem with writeback data mode
<6>[   43.037296] kjournald starting.  Commit interval 5 seconds
<6>[   43.037314] EXT3-fs (sde1): mounted filesystem with writeback data mode
<6>[   43.126142] kjournald starting.  Commit interval 5 seconds
<6>[   43.126160] EXT3-fs (sdf1): mounted filesystem with writeback data mode
<6>[   43.232175] kjournald starting.  Commit interval 5 seconds
<6>[   43.232192] EXT3-fs (sdg1): mounted filesystem with writeback data mode
<6>[   43.342400] kjournald starting.  Commit interval 5 seconds
<6>[   43.342419] EXT3-fs (sdh1): mounted filesystem with writeback data mode
<6>[   43.807685] md: md9 stopped.
<6>[   43.889647] md: bind<sdb1>
<6>[   43.889919] md: bind<sdc1>
<6>[   43.890181] md: bind<sdd1>
<6>[   43.890497] md: bind<sdf1>
<6>[   43.890814] md: bind<sde1>
<6>[   43.891126] md: bind<sdg1>
<6>[   43.891453] md: bind<sdh1>
<6>[   43.891701] md: bind<sda1>
<6>[   43.893560] raid1: raid set md9 active with 8 out of 8 mirrors
<6>[   43.898200] md9: bitmap initialized from disk: read 5/5 pages, set 0 bits
<6>[   43.898319] created bitmap (65 pages) for device md9
<6>[   43.922480] md9: detected capacity change from 0 to 542769152
<6>[   43.927046]  md9: unknown partition table
<6>[   44.977659] kjournald starting.  Commit interval 5 seconds
<6>[   45.121189] EXT3-fs (md9): using internal journal
<6>[   45.121375] EXT3-fs (md9): mounted filesystem with writeback data mode
<6>[   45.593030] md: md13 stopped.
<6>[   45.884420] md: bind<sdb4>
<6>[   45.884691] md: bind<sdc4>
<6>[   45.884943] md: bind<sdd4>
<6>[   45.885265] md: bind<sde4>
<6>[   45.885588] md: bind<sdf4>
<6>[   45.885900] md: bind<sdg4>
<6>[   45.886207] md: bind<sdh4>
<6>[   45.886471] md: bind<sda4>
<6>[   45.888314] raid1: raid set md13 active with 8 out of 8 mirrors
<6>[   45.892319] md13: bitmap initialized from disk: read 4/4 pages, set 0 bits
<6>[   45.892440] created bitmap (57 pages) for device md13
<6>[   45.932616] md13: detected capacity change from 0 to 469893120
<6>[   45.937173]  md13: unknown partition table
<6>[   47.395992] kjournald starting.  Commit interval 5 seconds
<6>[   47.505669] EXT3-fs (md9): using internal journal
<6>[   47.505853] EXT3-fs (md9): mounted filesystem with writeback data mode
<6>[   65.560685] kjournald starting.  Commit interval 5 seconds
<6>[   65.652236] EXT3-fs (md9): using internal journal
<6>[   65.652436] EXT3-fs (md9): mounted filesystem with writeback data mode
<6>[  116.408328] kjournald starting.  Commit interval 5 seconds
<6>[  116.515013] EXT3-fs (md13): using internal journal
<6>[  116.515223] EXT3-fs (md13): mounted filesystem with writeback data mode
<6>[  125.023285] usbcore: registered new interface driver hiddev
<6>[  125.513982] generic-usb 0003:051D:0002.0001: hiddev96: USB HID v1.10 Devic                e [APC Back-UPS ES 700G FW:871.O2 .I USB FW:O2 ] on usb-0000:00:1d.2-1/input0
<6>[  125.514623] usbcore: registered new interface driver usbhid
<6>[  125.514769] usbhid: USB HID core driver
<4>[  125.520403] Register ICH/PCH RTC driver.
<6>[  125.529508] iTCO_vendor_support: vendor-support=0
<6>[  125.536199] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.05
<6>[  125.537103] iTCO_wdt: Found a ICH9R TCO device (Version=2, TCOBASE=0x0860)
<6>[  125.542239] iTCO_wdt: initialized. heartbeat=120 sec (nowayout=0)
<6>[  125.552516] usbcore: registered new interface driver usblp
<4>[  125.563106] ufsd: module license 'Commercial product' taints kernel.
<4>[  125.563230] Disabling lock debugging due to kernel taint
<5>[  125.589499] ufsd: driver 8.3 (Mar 31 2011 01:50:57) with acl LBD=OFF with                 ioctl loaded at ffffffffa00ae000
<5>[  125.589505] NTFS read/write support included
<5>[  125.589507] Hfs+/HfsX read/write support included
<6>[  125.613324] fnotify: Load file notify kernel module.
<6>[  125.613799] fnotify:   Global_Private_Data_List_Init()
<6>[  125.613981] fnotify:   Launch the fnotify thread: 1899
<6>[  125.613999] fnotify:   The fnotify thread starts...
<6>[  126.674449] usbcore: registered new interface driver snd-usb-audio
<6>[  126.684087] usbcore: registered new interface driver snd-usb-caiaq
<6>[  126.712074] 802.1Q VLAN Support v1.8 Ben Greear <greearb@candelatech.com>
<6>[  126.712210] All bugs added by David S. Miller <davem@redhat.com>
<6>[  127.255188] kjournald starting.  Commit interval 5 seconds
<6>[  127.270502] EXT3-fs (md9): using internal journal
<6>[  127.270687] EXT3-fs (md9): mounted filesystem with writeback data mode
<6>[  129.975136] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Contro                l: RX/TX
<6>[  133.274325] md: bind<sda2>
<6>[  133.276038] raid1: raid set md8 active with 1 out of 1 mirrors
<6>[  133.276200] md8: detected capacity change from 0 to 542769152
<6>[  134.281413]  md8: unknown partition table
<6>[  136.333228] Adding 530040k swap on /dev/md8.  Priority:-1 extents:1 across                :530040k
<6>[  141.001794] md: bind<sdb2>
<4>[  141.012625] RAID1 conf printout:
<4>[  141.012750]  --- wd:1 rd:2
<4>[  141.012869]  disk 0, wo:0, o:1, dev:sda2
<4>[  141.012989]  disk 1, wo:1, o:1, dev:sdb2
<6>[  141.013270] md: recovery of RAID array md8
<6>[  141.013413] md: minimum _guaranteed_  speed: 5000 KB/sec/disk.
<6>[  141.013535] md: using maximum available idle IO bandwidth (but not more th                an 200000 KB/sec) for recovery.
<6>[  141.013708] md: using 128k window, over a total of 530048 blocks.
<6>[  143.111179] md: bind<sdc2>
<6>[  145.306910] md: bind<sdd2>
<6>[  147.404115] md: bind<sde2>
<6>[  149.600198] md: bind<sdf2>
<6>[  151.773916] md: bind<sdg2>
<6>[  152.995541] md: md8: recovery done.
<4>[  153.034176] RAID1 conf printout:
<4>[  153.034288]  --- wd:2 rd:2
<4>[  153.034388]  disk 0, wo:0, o:1, dev:sda2
<4>[  153.034492]  disk 1, wo:0, o:1, dev:sdb2
<6>[  153.874300] md: bind<sdh2>
<4>[  156.567239] active port 0 :139
<4>[  156.567359] active port 1 :445
<4>[  156.567455] active port 2 :20
<6>[  174.474737] md: md0 stopped.
<6>[  174.485115] md: md0 stopped.
<6>[  174.621339] md: bind<sdb3>
<6>[  174.621623] md: bind<sdc3>
<6>[  174.621875] md: bind<sdd3>
<6>[  174.622206] md: bind<sde3>
<6>[  174.622515] md: bind<sdf3>
<6>[  174.622837] md: bind<sdg3>
<6>[  174.623158] md: bind<sdh3>
<6>[  174.623416] md: bind<sda3>
<6>[  174.625032] raid5: device sda3 operational as raid disk 0
<6>[  174.625144] raid5: device sdh3 operational as raid disk 7
<6>[  174.625249] raid5: device sdg3 operational as raid disk 6
<6>[  174.625359] raid5: device sdf3 operational as raid disk 5
<6>[  174.625467] raid5: device sde3 operational as raid disk 4
<6>[  174.625572] raid5: device sdd3 operational as raid disk 3
<6>[  174.625677] raid5: device sdc3 operational as raid disk 2
<6>[  174.625782] raid5: device sdb3 operational as raid disk 1
<6>[  174.644088] raid5: allocated 135840kB for md0
<4>[  174.644372] 0: w=1 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
<4>[  174.644484] 7: w=2 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
<4>[  174.644588] 6: w=3 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
<4>[  174.644693] 5: w=4 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
<4>[  174.644798] 4: w=5 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
<4>[  174.644902] 3: w=6 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
<4>[  174.645022] 2: w=7 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
<4>[  174.645127] 1: w=8 pa=0 pr=8 m=2 a=2 r=8 op1=0 op2=0
<4>[  174.645232] raid5: raid level 6 set md0 active with 8 out of 8 devices, al                gorithm 2
<4>[  174.645398] RAID5 conf printout:
<4>[  174.645493]  --- rd:8 wd:8
<4>[  174.645588]  disk 0, o:1, dev:sda3
<4>[  174.645686]  disk 1, o:1, dev:sdb3
<4>[  174.645783]  disk 2, o:1, dev:sdc3
<4>[  174.645881]  disk 3, o:1, dev:sdd3
<4>[  174.645978]  disk 4, o:1, dev:sde3
<4>[  174.646087]  disk 5, o:1, dev:sdf3
<4>[  174.646189]  disk 6, o:1, dev:sdg3
<4>[  174.646286]  disk 7, o:1, dev:sdh3
<6>[  174.646482] md0: detected capacity change from 0 to 11992753766400
<6>[  175.950519]  md0: unknown partition table
<6>[  188.700631] EXT4-fs (md0): mounted filesystem with ordered data mode
<6>[  214.723108] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Contro                l: RX/TX
<6>[  244.541144] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Contro                l: RX/TX
<4>[  268.993195] active port 0 :139
<4>[  268.993307] active port 1 :445
<4>[  268.993407] active port 2 :20
<4>[  302.353179]  Set Adpater:port=0:0 standby to 242 (3600 secs).
<4>[  302.357883]  Set Adpater:port=0:1 standby to 242 (3600 secs).
<4>[  302.362604]  Set Adpater:port=0:2 standby to 242 (3600 secs).
<4>[  302.367411]  Set Adpater:port=0:3 standby to 242 (3600 secs).
<4>[  304.389297] rule type=1, num=2
<6>[  304.684814] Loading iSCSI transport class v2.0-871.
<5>[  304.732433] iscsi: registered transport (tcp)
[~] #

[AdrianW]

Looks like my problem is back in the "too-hard" basket.

[florian.baumert]

I think I ran into the same problem. I documented it here:

viewtopic.php?f=11&t=46573

[florian.baumert]

As I had the same Problem on my 410 (flush-8:0 in my case and smbd) I had the theory what it has something to do with the filling degree (92%) of my disks. My suspect was that it write to the disks and that the checksum information is distributed so that reading and updating it blocks a long time. Alternatively there is to few cache to handle this without a lot of disk-io...

I "fixed" this by adding another 2TB drive which brings the "disk full" to 62%. Immediately the problem is not reproducable., I can write locally and over samba with full speed.

Seems like something QNAP needs to fix really urgent!

[AdrianW]

I "fixed" this by adding another 2TB drive which brings the "disk full" to 62%. Immediately the problem is not reproducable., I can write locally and over samba with full speed.

Mine has been having the issue for a long time and it's only 50% full.

There's another thread about the same problem (here: QNAP firmware issues : Major file system bug) which suggests that the problem may be caused by the quantity of files on the NAS and not how full the file system is.

[forkless]

I've had symptoms like this on one of the TS-809s I do the maintenance for. It would even go as far as freezing the system mid SSH terminal session. Not just samba based file transfers.

This was on all firmwares (up until 3.3.x somewhere) when disk 5 in the RAID set decided to do b0rk. This disk never reported issues in S.M.A.R.T. nor did the regular scans show any issues. After replacing the faulty HDD and rebuilding the array, the freeze ups did not return. Which has been for several months now. As opposed to hourly hiccups.

The morale of the story is that latent damage to hardware can be bad enough to go into unwanted behavior but can be good enough to fly under the radar of your monitoring. While it is easy to lump up similar looking symptoms into a single issue, they may well stem from a wide range of unrelated causes.

Anyway, my personal observation aside, for this reason alone these kind of problems need to be thoroughly investigated and obviously fixed if induced by the product itself. Reality, however will be that even when a solution is provided you will never be able to satisfy everybody just by the rationale that not all problems are created equal.