Debian OS and transfer speeds

[fregster]

After moving to Debian I have (And google shows many others) been suffering slow file transfer speeds.

The CPU also seems to be been taxed quite highly be most operations.

Attached is some hdparm results and triobench results


N2100:/home/paul# tiobench --size 32
Run #1: /usr/bin/tiotest -t 8 -f 4 -r 500 -b 4096 -d . -TTT

Unit information
================
File size = megabytes
Blk Size = bytes
Rate = megabytes per second
CPU% = percentage of CPU used during the test
Latency = milliseconds
Lat% = percent of requests that took longer than X seconds
CPU Eff = Rate divided by CPU% - throughput per cpu load

Sequential Reads
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.18-4-iop32x 32 4096 1 28.21 99.62% 0.125 3.08 0.00000 0.00000 28
2.6.18-4-iop32x 32 4096 2 27.79 99.86% 0.253 160.14 0.00000 0.00000 28
2.6.18-4-iop32x 32 4096 4 28.54 99.89% 0.405 300.24 0.00000 0.00000 29
2.6.18-4-iop32x 32 4096 8 27.64 98.47% 0.587 710.08 0.00000 0.00000 28

Random Reads
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.18-4-iop32x 32 4096 1 26.90 99.86% 0.128 3.10 0.00000 0.00000 27
2.6.18-4-iop32x 32 4096 2 27.04 98.65% 0.254 100.12 0.00000 0.00000 27
2.6.18-4-iop32x 32 4096 4 27.38 99.88% 0.459 180.17 0.00000 0.00000 27
2.6.18-4-iop32x 32 4096 8 27.23 97.58% 0.252 502.29 0.00000 0.00000 28

Sequential Writes
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.18-4-iop32x 32 4096 1 9.44 88.47% 0.289 6.55 0.00000 0.00000 11
2.6.18-4-iop32x 32 4096 2 9.62 90.50% 0.585 180.44 0.00000 0.00000 11
2.6.18-4-iop32x 32 4096 4 9.84 93.82% 1.248 400.42 0.00000 0.00000 10
2.6.18-4-iop32x 32 4096 8 9.95 95.46% 2.294 771.00 0.00000 0.00000 10

Random Writes
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.18-4-iop32x 32 4096 1 8.00 34.82% 0.111 2.35 0.00000 0.00000 23
2.6.18-4-iop32x 32 4096 2 8.13 35.38% 0.187 100.22 0.00000 0.00000 23
2.6.18-4-iop32x 32 4096 4 8.60 44.58% 0.331 300.12 0.00000 0.00000 19
2.6.18-4-iop32x 32 4096 8 9.35 61.01% 0.352 289.77 0.00000 0.00000 15


N2100:/home/paul# hdparm -tT /dev/sda

/dev/sda:
Timing cached reads: 66 MB in 2.05 seconds = 32.25 MB/sec
Timing buffered disk reads: 68 MB in 3.06 seconds = 22.24 MB/sec

N2100:/home/paul# hdparm -tT /dev/md0

/dev/md0:
Timing cached reads: 66 MB in 2.05 seconds = 32.26 MB/sec
Timing buffered disk reads: 62 MB in 3.05 seconds = 20.33 MB/sec




Comparing this to my Kuro HG (PPC 266Mhz) I get 200MB/sec and 50 MB/sec

There has been suggestions that perhaps the Debian kernel is not "optimised" for the N2100 very well, perhaps Thecus could release what kernel compilation options they used and what modules that need to be included.

Any suggestions or anyone else having these problems?

Many thanks

[fregster]

After a failed upgrade to testing (Lenney) I have got unstable installed here are the results

N2100:/home/paul# tiobench --size 32
Run #1: /usr/bin/tiotest -t 8 -f 4 -r 500 -b 4096 -d . -TTT

Unit information
================
File size = megabytes
Blk Size = bytes
Rate = megabytes per second
CPU% = percentage of CPU used during the test
Latency = milliseconds
Lat% = percent of requests that took longer than X seconds
CPU Eff = Rate divided by CPU% - throughput per cpu load

Sequential Reads
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.22-1-iop32x 32 4096 1 27.06 99.78% 0.130 0.76 0.00000 0.00000 27
2.6.22-1-iop32x 32 4096 2 27.07 195.3% 0.254 60.24 0.00000 0.00000 14
2.6.22-1-iop32x 32 4096 4 26.92 382.8% 0.508 62.27 0.00000 0.00000 7
2.6.22-1-iop32x 32 4096 8 27.44 723.8% 0.909 140.68 0.00000 0.00000 4

Random Reads
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.22-1-iop32x 32 4096 1 25.65 96.85% 0.136 9.93 0.00000 0.00000 26
2.6.22-1-iop32x 32 4096 2 26.40 194.3% 0.262 20.50 0.00000 0.00000 14
2.6.22-1-iop32x 32 4096 4 26.32 350.3% 0.425 88.22 0.00000 0.00000 8
2.6.22-1-iop32x 32 4096 8 27.28 645.9% 0.858 140.24 0.00000 0.00000 4

Sequential Writes
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.22-1-iop32x 32 4096 1 9.61 89.77% 0.328 42.79 0.00000 0.00000 11
2.6.22-1-iop32x 32 4096 2 9.77 179.5% 0.626 140.70 0.00000 0.00000 5
2.6.22-1-iop32x 32 4096 4 9.67 344.9% 1.219 420.43 0.00000 0.00000 3
2.6.22-1-iop32x 32 4096 8 9.80 673.5% 1.950 760.32 0.00000 0.00000 1

Random Writes
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.22-1-iop32x 32 4096 1 8.06 37.12% 0.127 59.33 0.00000 0.00000 22
2.6.22-1-iop32x 32 4096 2 7.59 66.58% 0.208 20.37 0.00000 0.00000 11
2.6.22-1-iop32x 32 4096 4 8.40 154.8% 0.472 71.90 0.00000 0.00000 5
2.6.22-1-iop32x 32 4096 8 9.50 384.1% 0.360 376.90 0.00000 0.00000 2


N2100:/home/paul# hdparm -tT /dev/sda

/dev/sda:
Timing cached reads: 62 MB in 2.07 seconds = 30.02 MB/sec
Timing buffered disk reads: 66 MB in 3.01 seconds = 21.93 MB/sec

[fregster]

Further information,

After the upgrade to unstable samba performance is up from approx 1.2 - 1.7 MB/sec to 2.75 MB/sec with CPU down from 100% to 50% ish (usually lower)

Note: This is from a Vista client and moving to unstable readahead for vista clients is enabled.

[majority]

I just recently installed debian on my n2100, and wasn't aware of this slowdown in transfer speeds. I ran the tests you did and get the same results, sadly.

Do you have results from a stock thecus to compare with? Maybe we could get someone to run these tests on theirs.

Is it possible to check what options a kernel was compiled with?

regards

[majority]

I've been looking around and can see that someone posted this to the debian arm mailing list last month -- lists.debian.org/debian-arm/2007/07/msg00026.html -- and no one seemed to give a d**n, so I don't know how we're gonna get this solved, as if there's anyone competent enough to solve this issue it has to be someone on that mailing list.

[fregster]

Quote from link above


After installing Debian, I've found that the disc speed as reported by
hdparm has gone down. Before, I was getting:

/dev/sda:
Timing cached reads: 424 MB in 2.00 seconds = 212.00 MB/sec
Timing buffered disk reads: 158 MB in 3.01 seconds = 52.49 MB/sec

Whereas now I get:
Timing cached reads: 60 MB in 2.00 seconds = 29.95 MB/sec
Timing buffered disk reads: 60 MB in 3.07 seconds = 19.53 MB/sec

The discs are both Samsung HD501LJ
Looking at a comparison of dmesg outputs, I get the following line with
Debian:
sata_sil 0000:00:03.0: Applying R_ERR on DMA activate FIS errata fix
Is that perhaps related to this? Does anyone have an ideas on how to
improve the performance. The figures even for the Thecus firmware seem
rather poor compared to my desktop. I've checked the rc scripts in the
thecus firmware and can't see any relevant looking hdparm command.

I will post the results from my Kuro in a sec (PPC 266 at 173 MIPS)

[fregster]

Results from Kuro

KURO:/home/paul# tiobench --size 32
Run #1: /usr/bin/tiotest -t 8 -f 4 -r 500 -b 4096 -d . -TTT

Unit information
================
File size = megabytes
Blk Size = bytes
Rate = megabytes per second
CPU% = percentage of CPU used during the test
Latency = milliseconds
Lat% = percent of requests that took longer than X seconds
CPU Eff = Rate divided by CPU% - throughput per cpu load

Sequential Reads
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.18.1-mh7_kurobox_hg 32 4096 1 92.89 99.85% 0.040 0.29 0.00000 0.00000 93
2.6.18.1-mh7_kurobox_hg 32 4096 2 91.91 178.0% 0.074 100.09 0.00000 0.00000 52
2.6.18.1-mh7_kurobox_hg 32 4096 4 92.04 173.7% 0.072 260.44 0.00000 0.00000 53
2.6.18.1-mh7_kurobox_hg 32 4096 8 91.99 97.73% 0.040 0.17 0.00000 0.00000 94

Random Reads
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.18.1-mh7_kurobox_hg 32 4096 1 89.97 99.04% 0.039 0.09 0.00000 0.00000 91
2.6.18.1-mh7_kurobox_hg 32 4096 2 87.91 186.7% 0.075 20.08 0.00000 0.00000 47
2.6.18.1-mh7_kurobox_hg 32 4096 4 87.57 217.4% 0.093 32.08 0.00000 0.00000 40
2.6.18.1-mh7_kurobox_hg 32 4096 8 86.60 148.5% 0.063 89.93 0.00000 0.00000 58

Sequential Writes
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.18.1-mh7_kurobox_hg 32 4096 1 13.86 66.33% 0.219 94.51 0.00000 0.00000 21
2.6.18.1-mh7_kurobox_hg 32 4096 2 16.63 153.8% 0.352 136.10 0.00000 0.00000 11
2.6.18.1-mh7_kurobox_hg 32 4096 4 17.59 270.8% 0.486 368.18 0.00000 0.00000 6
2.6.18.1-mh7_kurobox_hg 32 4096 8 17.92 554.2% 0.688 759.25 0.00000 0.00000 3

Random Writes
File Blk Num Avg Maximum Lat% Lat% CPU
Identifier Size Size Thr Rate (CPU%) Latency Latency >2s >10s Eff
---------------------------- ------ ----- --- ------ ------ --------- ----------- -------- -------- -----
2.6.18.1-mh7_kurobox_hg 32 4096 1 11.90 34.42% 0.057 0.13 0.00000 0.00000 35
2.6.18.1-mh7_kurobox_hg 32 4096 2 11.21 60.28% 0.109 100.21 0.00000 0.00000 19
2.6.18.1-mh7_kurobox_hg 32 4096 4 12.96 119.1% 0.070 0.25 0.00000 0.00000 11
2.6.18.1-mh7_kurobox_hg 32 4096 8 13.28 200.5% 0.080 6.24 0.00000 0.00000 7

KURO:/home/paul# hdparm -tT /dev/hda

/dev/hda:
Timing cached reads: 228 MB in 2.01 seconds = 113.38 MB/sec
Timing buffered disk reads: 120 MB in 3.03 seconds = 39.58 MB/sec

[fregster]

from sata_lib driver

463 /* Apply R_ERR on DMA activate FIS errata workaround */
464 if (probe_ent->host_flags & SIL_FLAG_RERR_ON_DMA_ACT) {
465 int cnt;
466
467 for (i = 0, cnt = 0; i < probe_ent->n_ports; i++) {
468 tmp = readl(mmio_base + sil_port.sfis_cfg);
469 if ((tmp & 0x3) != 0x01)
470 continue;
471 if (!cnt)
472 dev_printk(KERN_INFO, &pdev->dev,
473 "Applying R_ERR on DMA activate "
474 "FIS errata fix\n");
475 writel(tmp & ~0x3, mmio_base + sil_port.sfis_cfg);
476 cnt++;
477 }
478 }


from the original dmsg

libata version 1.11 loaded.
sata_sil version 0.9
SFISCFG0: 0x10401554
SFISCFG1: 0x10401554
ata1: SATA max UDMA/100 cmd 0xD09EE080 ctl 0xD09EE08A bmdma 0xD09EE000 irq 29
ata2: SATA max UDMA/100 cmd 0xD09EE0C0 ctl 0xD09EE0CA bmdma 0xD09EE008 irq 29
ata1: dev 0 cfg 49:2f00 82:346b 83:7d01 84:4023 85:3469 86:3c01 87:4023 88:007f
ata1: dev 0 ATA, max UDMA/133, 312581808 sectors: lba48
ata1: dev 0 configured for UDMA/100
scsi0 : sata_sil
ata2: no device found (phy stat 00000000)
scsi1 : sata_sil
Vendor: ATA Model: ST3160812AS Rev: 3.AA
Type: Direct-Access ANSI SCSI revision: 05
Thecus Tray: 1, sda
SCSI device sda: 312581808 512-byte hdwr sectors (160042 MB)
SCSI device sda: drive cache: write back

from my dmsg

sata_sil 0000:00:03.0: version 2.2
sata_sil 0000:00:03.0: Applying R_ERR on DMA activate FIS errata fix
scsi0 : sata_sil
scsi1 : sata_sil
ata1: SATA max UDMA/100 cmd 0xd0860080 ctl 0xd086008a bmdma 0xd0860000 irq 29
ata2: SATA max UDMA/100 cmd 0xd08600c0 ctl 0xd08600ca bmdma 0xd0860008 irq 29
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata1.00: ATA-7: WDC WD4000AAKS-00TMA0, 12.01C01, max UDMA/133
ata1.00: 781422768 sectors, multi 0: LBA48 NCQ (depth 0/32)
ata1.00: configured for UDMA/100
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata2.00: ATA-7: WDC WD4000AAKS-00TMA0, 12.01C01, max UDMA/133
ata2.00: 781422768 sectors, multi 0: LBA48 NCQ (depth 0/32)
ata2.00: configured for UDMA/100


lspci -v shows
00:03.0 Mass storage controller: Silicon Image, Inc. SiI 3512 [SATALink/SATARaid] Serial ATA Controller (rev 01)
Subsystem: Silicon Image, Inc. SiI 3512 SATALink Controller
Flags: bus master, 66MHz, medium devsel, latency 0, IRQ 29
I/O ports at 90000850
I/O ports at 90000860
I/O ports at 90000858
I/O ports at 90000864
I/O ports at 90000840
Memory at 800a0000 (32-bit, non-prefetchable)
[virtual] Expansion ROM at 80000000 [disabled]
Capabilities: [60] Power Management version 2



The libata driver is sata_sil which from the libata site shows:
Silicon Image 3112/3114
Driver name: sata_sil

Summary: No TCQ/NCQ. Looks like a PATA controller, but with full SATA control including hotplug and PM.

further information shows that the sata_sil driver may need some performance fixes (there are comparisons out there marked against the silimage driver (PATA)) and deboras says:

* Silicon Image Sil3512ECTU128 - S-ATA controller
sata_sil driver (needs performance fixing probably)

Perhaps we should donate access to some of our hardware to the libata team.

I will see if I can find any information on the SiI3512 and linux (http://www.siliconimage.com/products/product.aspx?id=29)

Paul

[mrfantasy]

Googling, I found kerneltrap.org/node/3813 which seems to indicate this may be a general problem with version 2.0 or later of the sata_sil driver. I'm going to look around some more.

I'm also using the unstable armel image on my N2100 and performance is similar to before, unfortunately. I was hoping a kernel rev might have helped.

[fregster]

I have tried to contact the developers of sata_sil and the libata team but I can get little response, I guess they do not want to / have not got the time to help.

P

[fregster]

For further information (Although I think this is a driver - chipset problem)

fdisk -l /dev/sda

Disk /dev/sda: 400.0 GB, 400088457216 bytes
255 heads, 63 sectors/track, 48641 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Disk identifier: 0x0001932b

hdparm -i /dev/sda

/dev/sda:

Model=WDC WD4000AAKS-00TMA0 , FwRev=12.01C01, SerialNo= WD-WCAPW0451439
Config={ HardSect NotMFM HdSw>15uSec SpinMotCtl Fixed DTR>5Mbs FmtGapReq }
RawCHS=16383/16/63, TrkSize=0, SectSize=0, ECCbytes=50
BuffType=unknown, BuffSize=16384kB, MaxMultSect=16, MultSect=?0?
CurCHS=16383/16/63, CurSects=16514064, LBA=yes, LBAsects=268435455
IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
PIO modes: pio0 pio3 pio4
DMA modes: mdma0 mdma1 mdma2
UDMA modes: udma0 udma1 udma2 udma3 udma4 *udma5
AdvancedPM=no WriteCache=enabled
Drive conforms to: Unspecified: ATA/ATAPI-1,2,3,4,5,6,7

* signifies the current active mode


from the driver:

/* sil_3512 */
{
.sht = &sil_sht,
.flags = SIL_DFL_PORT_FLAGS | SIL_FLAG_RERR_ON_DMA_ACT,
.pio_mask = 0x1f, /* pio0-4 */
.mwdma_mask = 0x07, /* mwdma0-2 */
.udma_mask = 0x3f, /* udma0-5 */
.port_ops = &sil_ops,
},

I am trying to find out what the errata fix does, anyone know?

[fregster]

fregster said:

I have tried to contact the developers of sata_sil and the libata team but I can get little response, I guess they do not want to / have not got the time to help.

P

Please ignore this comment they have been working little little angles.

Copy and pasted from a selection of emails I have recieved which might help others.



I tried two tests with 2.6.22 to see what might make a difference but I couldn't increase the performance:

- First, I reverted that R_ERR on DMA activate FIS errata fix which
you noticed in dmesg. Reverting this fix does not increase
performance.

- Second, I applied Intel's IOP patches from SourceForge but again
they didn't help.

------------------------------------------------------------

I believe a bug was found at some point in hdparm that caused it to generate incorrect test values (of by a factor of 2 as far as I remember). This would cause comparing the results between old (broken) and new (fixed) versions of hdparm to look as if things had suddenly gotten much worse.

Maybe that is what is the case here.

------------------------------------------------------------

Did you enable the dma engine in kernel config? There is three patches that could help:

try-dma-memcpy.patch
try-dma-copy-to-user.patch
try-dma-copy-from-user.patch

Although the comment about polling and no perfomance benefit seems to kill any hope..

> So I'm not quite sure why Debian with a modern kernel is much slower
> to whatever Thecus' firmware was using. If anyone else has any good
> ideas I'd love to hear them.

While running tiobench:

all6500-2:~# opreport --symbols -t 0.5 vmlinux
CPU: ARM/XScale PMU1, speed 0 MHz (estimated) Counted CPU_CYCLES events (clock cycles counter) with a unit mask of 0x00 (No unit mask) count 100000
samples % symbol name
200062 43.2117 default_idle
67639 14.6095 __copy_from_user
48539 10.4840 cfq_set_request
8185 1.7679 xscale_mc_clear_user_page
7379 1.5938 mc_copy_user_page
5635 1.2171 scsi_track_queue_full
4431 0.9571 cpu_idle
3926 0.8480 update_mmu_cache
3813 0.8236 xscale_flush_user_cache_range
3646 0.7875 memmove
2316 0.5002 generic_file_buffered_write
2250 0.4860 journal_init_revoke
2177 0.4702 scsi_execute_async
2148 0.4639 ext3_set_aops
1926 0.4160 _local_bh_enable

(The default_idle might simply be the time between tests)

While running hdparm -tT :

all6500-2:~# opreport --symbols -t 0.5 vmlinux
CPU: ARM/XScale PMU1, speed 0 MHz (estimated) Counted CPU_CYCLES events (clock cycles counter) with a unit mask of 0x00 (No unit mask) count 100000
samples % symbol name
127724 49.3465 __copy_from_user
26340 10.1765 xscale_mc_clear_user_page
13717 5.2996 scsi_track_queue_full
7914 3.0576 mc_copy_user_page
5234 2.0222 scsi_execute_async
4647 1.7954 update_mmu_cache
4181 1.6153 xscale_flush_user_cache_range
3933 1.5195 _local_bh_enable
3401 1.3140 memmove
2241 0.8658 __make_request
1552 0.5996 target_block
1442 0.5571 sys_readahead
1392 0.5378 __dabt_usr
1299 0.5019 cpu_xscale_switch_mm

..Almost everything memory rather than sata controller related.


---------------------------------------------------------------------

I'm glad your email caused me to double check. While the dma engine itself was enabled, some other options were missing. With the following options enabled, my performance goes to:

Timing cached reads: 382 MB in 2.01 seconds = 190.16 MB/sec
Timing buffered disk reads: 144 MB in 3.03 seconds = 47.59 MB/sec

CONFIG_DMA_ENGINE=y
CONFIG_DMA_COPY_CLEAR_PAGE=y
CONFIG_DMA_COPY_CLEAR_PAGE=y
CONFIG_POLLED_DMA_COPY_USER=y
CONFIG_INTEL_IOP_ADMA=y

I'll ask Dan Williams of Intel about the status of these patches.
If we're really lucky, maybe they'll be in the kernel that will be used for the "etch+0.5" update (i.e. a new 2.6.2x based kernel for etch).
If not, we can make a n2100 repository somewhere with a kernel that has the dma engine patches.


-----------------------------------------------------------


Yay !