Port-arm archive

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]

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
                  >
                  >










Home | Main Index | Thread Index | Old Index