Re: Very slow transfers to/from micro SD card on a RPi B+

I just double-checked for certainty and it looks good:

sdhc0: SDHC 3.0, rev 153, platform DMA, 250000 kHz, HS SDR50 3.3V, re-tuning mode 1, 1024 byte blocks

sdmmc0 at sdhc0 slot 0

uhub0 at usb0: vendor 0000 DWC2 root hub, class 9/0, rev 2.00/1.00, addr 1

uhub0: 1 port with 1 removable, self powered

uhub1 at uhub0 port 1: vendor 0424 product 9514, class 9/0, rev 2.00/2.00, addr 2

uhub1: multiple transaction translators

uhub1: 5 ports with 4 removable, self powered

ld0 at sdmmc0: <0x82:0x4a54:NCard:0x10:0x3360f1f3:0x0ea>

ld0: 15087 MB, 7663 cyl, 64 head, 63 sec, 512 bytes/sect x 30898176 sectors

ld0: 4-bit width, SDR50, 100.000 MHz

Sequential write speed was about 8,6 MB/s this time. However, it fluctuates between ~3 - 11 MB/s.

tty ld0 CPU

tin tout KB/t t/s MB/s us ni sy in id

2 50 52.15 79 4.034 0 0 12 1 86

0 44 62.86 55 3.403 0 0 25 0 75

0 44 62.84 54 3.342 0 0 15 0 84

0 44 61.63 53 3.218 0 0 7 0 93

0 44 62.59 44 2.663 1 0 5 0 93

0 44 60.20 132 7.741 0 0 16 1 82

0 44 62.51 128 7.797 1 0 14 0 85

0 44 63.50 127 7.859 0 0 14 0 85

0 44 64.00 126 7.859 1 0 15 0 83

0 44 59.48 160 9.317 0 0 22 1 77

0 7553 64.00 110 6.869 1 0 15 0 83

0 44 52.44 160 8.215 0 0 15 0 84

0 44 64.00 177 11.08 0 0 23 0 77

0 44 64.00 177 11.08 0 0 23 2 75

0 44 64.00 167 10.46 2 0 20 2 76

tty ld0 CPU

tin tout KB/t t/s MB/s us ni sy in id

0 44 63.73 175 10.91 0 0 23 0 77

0 131 64.00 121 7.550 0 0 16 1 83

0 44 63.20 79 4.889 0 0 11 0 89

0 44 63.61 164 10.21 1 0 21 0 78

0 44 64.00 174 10.89 0 0 24 5 71

0 44 63.63 169 10.52 1 0 21 1 77

0 44 64.00 73 4.579 0 0 9 0 91

1 158 62.93 177 10.89 0 0 14 0 86

0 44 58.70 82 4.711 0 0 3 1 96

0 44 61.79 106 6.393 0 0 0 1 99

0 44 0.000 0 0.000 0 0 0 0 100

0 45 0.000 0 0.000 0 0 0 0 100

This is the locking situation within a 30 sec. period:

Elapsed time: 30.00 seconds.

-- Adaptive mutex spin

Total% Count Time/ms Lock Caller

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

72.12 1236 2.97 0000000081d48a00 <all>

11.94 192 0.49 0000000081d48a00 uvm_aio_aiodone+b4

10.28 111 0.42 0000000081d48a00 ufs_balloc_range+114

7.50 173 0.31 0000000081d48a00 biodone2+18

6.88 86 0.28 0000000081d48a00 genfs_getpages+30c

6.44 117 0.26 0000000081d48a00 uvm_aio_aiodone_pages+68

6.22 103 0.26 0000000081d48a00 genfs_lock+68

4.96 114 0.20 0000000081d48a00 biowait+18

4.53 84 0.19 0000000081d48a00 uvm_vnp_setwritesize+20

4.03 92 0.17 0000000081d48a00 brelsel+268

2.92 43 0.12 0000000081d48a00 ufs_balloc_range+1f0

2.40 46 0.10 0000000081d48a00 uvm_vnp_setsize+48

2.31 45 0.09 0000000081d48a00 ufs_post_write_update.isra.2+9c

1.09 14 0.04 0000000081d48a00 ubc_fault+1f4

0.24 8 0.01 0000000081d48a00 ubc_alloc+53c

0.14 3 0.01 0000000081d48a00 nestiobuf_done+24

0.09 2 0.00 0000000081d48a00 genfs_getpages+38c

0.06 1 0.00 0000000081d48a00 ffs_write+408

0.06 1 0.00 0000000081d48a00 ubc_fault+13c

0.02 1 0.00 0000000081d48a00 bdwrite+a4

13.37 485 0.55 uvm_pageqlock <all>

3.41 163 0.14 uvm_pageqlock uvm_anon_dispose+108

3.34 98 0.14 uvm_pageqlock genfs_getpages+7f0

2.17 82 0.09 uvm_pageqlock uvm_fault_lower_enter.isra.9+10

2.15 88 0.09 uvm_pageqlock ufs_balloc_range+1fc

1.51 36 0.06 uvm_pageqlock uvm_fault_internal+700

0.54 6 0.02 uvm_pageqlock uvm_fault_internal+4c0

0.12 3 0.00 uvm_pageqlock ubc_fault+2b8

0.08 6 0.00 uvm_pageqlock uvm_fault_upper_enter.isra.6+cc

0.03 1 0.00 uvm_pageqlock uvm_aio_aiodone_pages+74

0.01 2 0.00 uvm_pageqlock uvm_fault_internal+cb8

5.24 208 0.22 pmap_lock <all>

1.58 60 0.07 pmap_lock pmap_enter+54c

1.39 69 0.06 pmap_lock pmap_enter+12c

1.20 36 0.05 pmap_lock pmap_remove+118

0.47 16 0.02 pmap_lock pmap_clear_modify+20

0.39 13 0.02 pmap_lock pmap_page_protect+e4

0.10 4 0.00 pmap_lock pmap_clearbit.isra.16+1d0

0.05 3 0.00 pmap_lock pmap_copy_page_generic+1e0

0.02 3 0.00 pmap_lock pmap_fault_fixup+140

0.02 2 0.00 pmap_lock pmap_protect+1ac

0.01 1 0.00 pmap_lock pmap_fault_fixup+2b8

0.01 1 0.00 pmap_lock pmap_clearbit.isra.16+120

2.56 3 0.11 0000000081d48740 uvm_fault_internal+280

1.60 3 0.07 00000000baf02300 uvm_fault_internal+550

1.42 12 0.06 00000000baeeef40 workqueue_worker+50

1.25 39 0.05 bufcache_lock <all>

0.76 17 0.03 bufcache_lock getblk+2c

0.27 16 0.01 bufcache_lock brelse+20

0.16 2 0.01 bufcache_lock bwrite+94

0.04 2 0.00 bufcache_lock bdwrite+d4

0.02 2 0.00 bufcache_lock vflushbuf+60

0.83 17 0.03 00000000b4b3c940 <all>

0.72 12 0.03 00000000b4b3c940 sopoll+2c

0.09 3 0.00 00000000b4b3c940 soreceive+77c

0.02 2 0.00 00000000b4b3c940 soreceive+a8

0.58 13 0.02 00000000baf029c0 <all>

0.39 5 0.02 00000000baf029c0 ubc_release+74

0.15 6 0.01 00000000baf029c0 ubc_alloc+7c

0.03 2 0.00 00000000baf029c0 uvm_fault_internal+464

0.46 23 0.02 pmap_pv_pool+74 <all>

0.44 19 0.02 pmap_pv_pool+74 pool_get+2c

0.02 4 0.00 pmap_pv_pool+74 pool_put+2c

0.37 1 0.02 00000000baf02940 sosend+38

0.15 2 0.01 00000000a3b4b240 <all>

0.13 1 0.01 00000000a3b4b240 soreceive+77c

0.02 1 0.00 00000000a3b4b240 soreceive+a8

0.06 1 0.00 0000000081d49680 sys___sigprocmask14+44

-- Adaptive mutex sleep

Total% Count Time/ms Lock Caller

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

86.54 16 0.40 0000000081d48a00 biodone2+18

13.46 2 0.06 uvm_pageqlock <all>

7.06 1 0.03 uvm_pageqlock genfs_getpages+7f0

6.40 1 0.03 uvm_pageqlock uvm_fault_internal+700

-- Spin mutex spin

Total% Count Time/ms Lock Caller

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

36.08 39 0.12 uvm_fpageqlock <all>

29.30 36 0.10 uvm_fpageqlock uvm_pagealloc_strat+2c

6.79 3 0.02 uvm_fpageqlock uvm_pagefree+1cc

16.86 60 0.06 00000000baf11040 turnstile_lookup+28

12.02 46 0.04 00000000baf11e40 <all>

9.21 44 0.03 00000000baf11e40 turnstile_lookup+28

2.81 2 0.01 00000000baf11e40 turnstile_block+2a0

11.98 4 0.04 00000000811a3c18 <all>

11.42 3 0.04 00000000811a3c18 dk_start+24

0.56 1 0.00 00000000811a3c18 dk_done+70

4.42 3 0.01 00000000baf11700 <all>

2.47 2 0.01 00000000baf11700 turnstile_lookup+28

1.95 1 0.01 00000000baf11700 turnstile_block+2a0

3.75 16 0.01 00000000baf11640 turnstile_lookup+28

3.42 11 0.01 00000000baf11440 turnstile_lookup+28

3.17 3 0.01 00000000bac7ff3c <all>

2.94 2 0.01 00000000bac7ff3c dwc2_intr+24

0.23 1 0.00 00000000bac7ff3c dwc2_device_start+208

2.24 12 0.01 00000000baf11a40 turnstile_lookup+28

1.55 2 0.01 00000000baf10880 wakeup+44

1.45 2 0.00 00000000baf02dc0 sched_idle+f4

1.15 1 0.00 00000000baf02e00 sched_pstats+130

0.95 3 0.00 pmap_tlb0_lock <all>

0.64 2 0.00 pmap_tlb0_lock pmap_tlb_asid_acquire+40

0.31 1 0.00 pmap_tlb0_lock pmap_tlb_invalidate_addr+24

0.61 2 0.00 00000000baf11240 turnstile_lookup+28

0.25 1 0.00 00000000baf11b40 turnstile_lookup+28

0.10 1 0.00 00000000baf02b80 sleepq_remove+b4

-- RW lock sleep (writer)

Total% Count Time/ms Lock Caller

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

66.39 1 0.24 00000000aa890db4 genfs_lock+60

33.61 5 0.12 00000000bafd7f44 vm_map_lock+6c

-- RW lock spin

Total% Count Time/ms Lock Caller

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

100.00 17 0.13 00000000bafd7f44 vm_map_lock+6c

-- Kernel lock spin

Total% Count Time/ms Lock Caller

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

100.00 10441 124.89 kernel_lock <all>

77.04 6410 96.22 kernel_lock pmap_extract+138

6.15 1927 7.69 kernel_lock sleepq_block+1c0

3.84 1050 4.79 kernel_lock pic_dispatch+34

3.61 75 4.51 kernel_lock pmap_remove+548

3.15 524 3.93 kernel_lock pmap_kenter_pa+40

2.35 239 2.93 kernel_lock pmap_kremove+3c

1.92 83 2.40 kernel_lock pmap_fault_fixup+28c

1.18 64 1.47 kernel_lock pmap_enter+270

0.57 35 0.71 kernel_lock pmap_clearbit.isra.16+328

0.09 3 0.11 kernel_lock usb_transfer_complete+630

0.03 10 0.04 kernel_lock callout_softclock+1f8

0.02 1 0.03 kernel_lock nd6_timer+60

0.01 4 0.02 kernel_lock cdev_poll+88

0.01 1 0.01 kernel_lock bpf_poll+28

0.01 3 0.01 kernel_lock usb_task_thread+100

0.00 3 0.01 kernel_lock frag6_fasttimo+2c

0.00 2 0.00 kernel_lock VOP_LOCK+58

0.00 1 0.00 kernel_lock pmap_page_protect+30c

0.00 1 0.00 kernel_lock tcp_send_wrapper+24

0.00 1 0.00 kernel_lock VFS_STATVFS+60

0.00 1 0.00 kernel_lock VOP_READ+60

0.00 1 0.00 kernel_lock knote_detach+120

0.00 1 0.00 kernel_lock VOP_UNLOCK+54

0.00 1 0.00 kernel_lock VOP_POLL+58

Creating 1000 empty files takes this time:

# time seq 1 1000 | xargs touch

9.20s real 0.02s user 0.27s system

All figures refer to a non-WAPBL FFS file system.

2015-08-04 15:48 GMT+00:00 Jared McNeill <jmcneill%invisible.ca@localhost>:

Class 10 is a high-speed rating, not UHS-I. Make sure you are using a UHS-I card. dmesg will tell you, i.e.:

ld0: 4-bit width, SDR50, 100.000 MHz

On Tue, 4 Aug 2015, Stephan wrote:

These are my numbers on a class 10 Sony-SD-card when extracting pkgsrc.tar.

      tty              ld0             CPU
tin tout KB/t t/s MB/s us ni sy in id
   1 130 27.20   83 2.206   1 0 4 1 93
   0 132 7.333 186 1.329   0 0 0 0 100
   0   45 7.839 258 1.978   0 0 1 0 98
   0   44 7.134 192 1.338   0 0 1 1 97
   0   44 7.806 215 1.638   0 0 0 0 99
   0   44 7.483 238 1.737   0 0 1 1 98
   0   44 7.250 158 1.122   0 0 1 0 99
   0   44 7.744 255 1.932   0 0 2 1 97
   0   44 6.830 169 1.129   1 0 4 0 95
   0   44 7.379 201 1.448   0 0 1 0 99
   0   44 7.702 226 1.698   0 0 1 1 98
   0   44 7.391 218 1.572   0 0 0 0 100
   0   45 7.161 215 1.503   0 0 1 1 98
   0   44 7.164 223 1.559   0 0 1 0 99
   0   44 7.701 192 1.445   0 0 1 0 99
   0   44 7.600 262 1.947   0 0 1 1 97
      tty              ld0             CPU
tin tout KB/t t/s MB/s us ni sy in id
   0   44 9.719 183 1.738   0 0 1 0 99
   0 131 8.244 178 1.435   0 0 0 1 99
   0   44 7.861 242 1.855   0 0 0 0 100
   0   45 7.539 215 1.582   0 0 0 1 99
   0   44 7.020 196 1.344   0 0 1 0 99
   0   44 7.266 216 1.532   0 0 3 0 97
   0   44 7.798 186 1.417   0 0 1 1 98
   0   44 7.184 221 1.549   0 0 1 0 99
   0   44 7.703 234 1.758   0 0 1 0 99
   0   44 7.268 211 1.497   0 0 1 1 98
   0   44 8.064 185 1.458   0 0 2 0 97
   0   44 7.485 257 1.882   0 0 1 1 98
   0   44 7.235 215 1.518   0 0 1 0 98
   0   44 7.071 194 1.340   0 0 0 0 100
   0   45 7.667 220 1.646   0 0 1 1 98
   0   44 6.915 232 1.564   0 0 1 0 99
      tty              ld0             CPU
tin tout KB/t t/s MB/s us ni sy in id
   0   44 7.703 180 1.356   0 0 0 1 99
   0 131 6.975 240 1.632   0 0 2 0 98

Sequential write is about 6 MB/s on average.

2015-08-04 16:45 GMT+02:00 Jared McNeill <jmcneill%invisible.ca@localhost>:
The autobuild server should have the changes:

http://nyftp.netbsd.org/pub/NetBSD-daily/HEAD/201508041020Z/evbarm-earmv6hf/binary/kernel/

objcopy is used to generate "netbsd.bin" from the ELF binary. Grab netbsd-RPI.bin.gz from that
link, gunzip it, and rename to kernel.img

On Tue, 4 Aug 2015, Stephan wrote:

Hi Jared,

I could. Can you provide a current kernel so I don?t need to set up a build
environment beforehand?

I was also wondering what kind of file "kernel.img" (on the boot partition) is and
how to build this.
According to file, a regular NetBSD kernel is an ELF binary, whereas "kernel.img" is
just "data"?!

Regards,

Stephan

2015-08-04 14:59 GMT+02:00 Jared McNeill <jmcneill%invisible.ca@localhost>:
Hi --

I've added UHS-I support in -current and enabled it for Raspberry Pi. Can you
update and see if
this makes a difference in SD card performance?

Thanks,
Jared

On Thu, 9 Jul 2015, Stephan wrote:

Well, you can finde a previous discussion here:

http://mail-index.netbsd.org/tech-kern/2014/08/22/msg017539.html

The point was that creating many (even empty) files leads to a very high
kernel CPU
consumtion along with
almost no disk activity. What happens behind the scenes is still unknown to
me. One should
check whether
WAPBL makes a difference here (mount option "log" enables WAPBL journaling).
It might be
helpful to have
DTrace working in order to investigate this.

Cheers!

2015-07-09 12:33 GMT+02:00 Jean-Baka Domelevo Entfellner <domelevo%gmail.com@localhost>:
Hallo Stephan,

Thanks for the advice: yes, you were damn right! With the dd command
you gave as example, on top of the untarring, we get very different
values:
tty ld0 CPU
tin tout KB/t t/s MB/s us ni sy in id
0 19 7.825 17 0.128 0 0 1 3 95
0 131 64.00 70 4.394 0 0 34 2 64
0 44 64.00 85 5.322 0 0 31 11 58
0 44 64.00 73 4.579 0 0 33 8 59
0 44 64.00 72 4.517 3 0 30 6 61
0 44 63.19 58 3.605 0 0 3 6 91
0 44 14.77 64 0.928 0 0 21 1 78
0 44 64.00 60 3.775 0 0 36 8 56
0 44 64.00 69 4.332 1 0 36 2 61
0 44 64.00 56 3.527 0 0 25 3 72
0 44 64.00 55 3.465 1 0 24 3 72
0 44 64.00 56 3.527 1 0 25 2 72
0 44 64.00 57 3.589 1 0 20 6 73
0 44 64.00 68 4.270 0 0 29 6 65
0 44 64.00 73 4.579 3 0 29 6 62
0 44 63.30 68 4.223 0 0 4 7 89
0 44 40.49 88 3.485 1 0 44 4 51
^C
rpi$ fg
dd if=/dev/zero of=myfile bs=4k
^C20720+0 records in
20719+0 records out
84865024 bytes transferred in 20.350 secs (4170271 bytes/sec)

So this means approximately 4MB/s, and that's indeed the nominal speed
of my microSD if it's indeed a class 4 card. Will check that once I
can switch the RPi off. Thanks!

So ffs is slow with creating files... Why is it still the standard in
NetBSD? Is the format of my partition (displayed with fstype=4.2BSD in
"disklabel /dev/ld0") also called "UFS1"? Would the format called
"UFS2" be faster regarding file creation?

And just another off-topic question sparked by this one: is there
really an added value in specifying "bs=4k"? According to the manpage,
the default is one sector, 512 bytes. When I use it (dd if=/dev/zero
of=myfile), I get 3048728 bytes/sec instead of 4170271 bytes/sec with
"bs=4k". Is that discrepancy explainable and reproducible? Thanks for
sharing your light! :)

JB

On Thu, Jul 9, 2015 at 11:39 AM, Stephan <stephanwib%googlemail.com@localhost>
wrote:
> Can you please check the speed of sequential write (e.g. dd
if=/dev/zero
> of=myfile bs=4k)? FFS has always been slow with allocating new files,
which
> certainly contributes to the issue you?re seeing.
>
> 2015-07-09 11:28 GMT+02:00 Jean-Baka Domelevo Entfellner
> <domelevo%gmail.com@localhost>:
>>
>> Hi there,
>>
>> I'm currently untarring a pkgsrc.tar.gz (48MB) to /usr. The
>> commandline I used is:
>> # nohup tar xfz pkgsrc.tar.gz -C /usr &
>>
>> so nothing is written to the stdout, it justs gunzips and untars. And
>> I have the feeling it's extremely slow. I'm running:
>> NetBSD rpi 7.0_RC1 NetBSD 7.0_RC1 (RPI.201507072130Z) evbarm
>> and it's on a RaspberryPi model B+
>>
>> The microSD card is an ADATA (32GB), I don't think it's class 10,
>> maybe class 4 (can't remove it from its slot now while the RPi is
>> running). The boot messages concerning it are:
>> ld0 at sdmmc0: <0x03:0x5344:SS32G:0x80:0x2554f92d:0x0e4>
>> ld0: 30436 MB, 7729 cyl, 128 head, 63 sec, 512 bytes/sect x 62333952
>> sectors
>> ld0: 4-bit width, bus clock 50.000 MHz
>>
>> So, while the untarring command is running, I check the speed with iostat:
>>
>> tty ld0 CPU
>> tin tout KB/t t/s MB/s us ni sy in id
>> 0 20 7.767 15 0.113 0 0 1 3 95
>> 0 131 8.194 31 0.246 0 0 3 3 94
>> 0 44 7.871 31 0.236 0 0 1 3 96
>> 0 44 7.793 29 0.219 1 0 1 2 96
>> 0 44 8.133 30 0.236 0 0 2 2 96
>> 0 44 7.871 31 0.236 0 0 1 1 98
>> 0 44 7.793 29 0.219 0 0 1 4 95
>> 0 44 7.939 33 0.253 0 0 2 1 97
>> 0 44 7.931 29 0.222 0 0 0 2 98
>> 0 44 7.571 28 0.205 0 0 6 4 90
>> 0 44 7.793 29 0.219 0 0 3 2 95
>> 0 44 8.294 34 0.273 0 0 3 5 92
>> 0 44 8.000 28 0.217 0 0 3 0 97
>> 0 44 8.067 30 0.234 0 0 0 3 97
>>
>> It's on average between 0.20 and 0.25 MB/s, don't you think it's
>> unreasonably slow? Do you have any piece of advice for me?
>>
>> Thanks,
>> JB
>
>