rsync throughput declines after a time

[jorgesilva]

I am running rsyncon my rockpi nas pulling  from another nas and the performance initially pretty good at around 90MB/s and after a while, it degrades to 39Mbs with high io/wait times - any ideas/suggestions are welcome. Here are the outputs of amrbianmonitor -U

 

Time       big.LITTLE   load %cpu %sys %usr %nice %io %irq   CPU  C.St.

15:33:55:  600/1416MHz  0.85   4%   1%   0%   0%   1%   0% 41.7°C  0/6
15:34:00:  600/1008MHz  0.78   1%   0%   0%   0%   0%   0% 41.1°C  0/6
15:34:05:  816/1200MHz  0.72   1%   0%   0%   0%   0%   0% 41.7°C  0/6
15:34:10: 1800/1200MHz  0.66  10%   5%   4%   0%   0%   0% 46.9°C  0/6
15:34:16: 2016/1512MHz  0.85  39%  21%   6%   0%   9%   1% 52.2°C  0/6
15:34:21: 2016/1512MHz  1.10  52%  25%   7%   0%  16%   3% 52.2°C  0/6
15:34:26: 2016/1200MHz  1.17  31%  17%   7%   0%   4%   1% 48.8°C  0/6
15:34:31: 2016/1512MHz  1.32  43%  24%   6%   0%  10%   2% 53.3°C  0/6
15:34:36: 1800/1200MHz  1.45  43%  27%   7%   0%   6%   3% 52.8°C  0/6
15:34:41: 2016/1512MHz  1.42  40%  26%   8%   0%   3%   3% 52.2°C  0/6
15:34:46: 2016/1416MHz  1.54  44%  27%   6%   0%   6%   2% 53.9°C  0/6
15:34:52: 2016/1512MHz  2.07  33%  19%   7%   0%   4%   2% 54.4°C  0/6
15:34:57: 2016/1200MHz  2.14  50%  29%   6%   0%   9%   3% 53.9°C  0/6
15:35:02: 2016/1416MHz  2.29  44%  12%   5%   0%  24%   1% 53.9°C  0/6
Time       big.LITTLE   load %cpu %sys %usr %nice %io %irq   CPU  C.St.
15:35:07: 2016/1416MHz  2.35  46%  25%   6%   0%  12%   2% 54.4°C  0/6
15:35:12: 2016/1200MHz  2.40  38%  19%   5%   0%  10%   2% 51.7°C  0/6
15:35:17: 2016/1512MHz  2.37  44%  21%   6%   0%  13%   2% 53.3°C  0/6
15:35:22: 2016/1416MHz  2.58  48%  27%   6%   0%  11%   2% 51.1°C  0/6
15:35:28: 1416/1200MHz  2.69  48%  11%   4%   0%  32%   0% 48.8°C  0/6
15:35:33: 1416/1416MHz  2.72  42%  16%   4%   0%  19%   1% 50.0°C  0/6
15:35:38: 2016/1008MHz  2.82  37%   8%   3%   0%  24%   0% 46.2°C  0/6
15:35:43: 2016/1512MHz  2.84  44%  23%   6%   0%  11%   2% 52.8°C  0/6
15:35:48: 2016/1200MHz  2.93  39%  20%   5%   0%  11%   2% 54.4°C  0/6
15:35:53: 1200/1008MHz  3.02  37%  16%   5%   0%  13%   2% 48.1°C  0/6
15:35:58: 2016/1416MHz  3.09  38%   9%   3%   0%  24%   1% 48.1°C  0/6
15:36:04: 2016/1416MHz  3.17  42%  20%   5%   0%  15%   2% 53.3°C  0/6
15:36:09: 2016/1512MHz  3.23  40%  12%   4%   0%  21%   1% 46.9°C  0/6
15:36:14: 1608/1008MHz  3.38  44%  20%   5%   0%  16%   1% 48.8°C  0/6
15:36:19: 2016/1200MHz  3.51  42%  11%   3%   0%  26%   1% 48.1°C  0/6
Time       big.LITTLE   load %cpu %sys %usr %nice %io %irq   CPU  C.St.
15:36:24: 1416/1008MHz  3.55  44%   7%   3%   0%  32%   0% 46.2°C  0/6
15:36:29: 1008/1512MHz  3.58  42%  17%   4%   0%  18%   1% 48.8°C  0/6
15:36:34: 1800/1416MHz  3.62  38%  12%   3%   0%  21%   1% 46.2°C  0/6
15:36:40: 1416/1200MHz  3.65  44%  10%   3%   0%  29%   1% 45.6°C  0/6
15:36:45: 1008/1416MHz  3.68  50%  11%   4%   0%  33%   0% 45.6°C  0/6
15:36:50: 1800/ 816MHz  3.70  38%   9%   2%   0%  25%   0% 45.0°C  0/6
15:36:55: 2016/1200MHz  3.73  36%   6%   1%   0%  28%   0% 48.1°C  0/6
15:37:00: 2016/1200MHz  3.75  43%  20%   5%   0%  16%   2% 50.6°C  0/6
15:37:05:  816/1512MHz  3.77  41%  19%   5%   0%  14%   2% 45.0°C  0/6
15:37:10:  600/1008MHz  3.79  46%  15%   5%   0%  23%   1% 45.0°C  0/6
15:37:16: 1200/1008MHz  3.88  37%  12%   4%   0%  19%   0% 44.4°C  0/6
15:37:21: 2016/1200MHz  3.89  43%  18%   4%   0%  16%   2% 48.8°C  0/6
15:37:26:  600/1200MHz  3.82  41%  19%   4%   0%  14%   1% 50.6°C  0/6
15:37:31:  600/1200MHz  3.84  46%  13%   5%   0%  25%   1% 45.0°C  0/6
15:37:36: 1416/ 816MHz  3.85  44%   8%   3%   0%  31%   0% 43.9°C  0/6
Time       big.LITTLE   load %cpu %sys %usr %nice %io %irq   CPU  C.St.
15:37:41:  600/ 816MHz  3.94  42%  12%   4%   0%  24%   1% 46.9°C  0/6
15:37:46:  600/1200MHz  3.95  43%   8%   2%   0%  31%   0% 43.9°C  0/6
15:37:51: 2016/1200MHz  3.87  43%   9%   3%   0%  28%   0% 50.6°C  0/6
15:37:57: 1008/1008MHz  3.88  46%  21%   4%   0%  18%   1% 51.1°C  0/6
15:38:02: 2016/1008MHz  3.97  41%  13%   3%   0%  23%   1% 45.6°C  0/6
15:38:07: 2016/1416MHz  4.14  41%   7%   2%   0%  31%   0% 45.6°C  0/6
15:38:12:  600/1008MHz  4.21  34%   9%   4%   0%  20%   0% 43.9°C  0/6
15:38:17:  600/1416MHz  4.27  46%  10%   2%   0%  32%   0% 43.9°C  0/6
15:38:22:  600/1200MHz  4.25  47%  11%   3%   0%  31%   0% 45.0°C  0/6
15:38:27: 1800/1200MHz  4.15  49%  13%   3%   0%  31%   1% 51.1°C  0/6
15:38:32: 2016/1200MHz  4.22  49%  12%   4%   0%  31%   1% 45.0°C  0/6^

 

 

 

Initially is wasp copying over at approx 90MB/s which is close to the network max throughput then is slows down

amrbianmonitor_out

[lanefu]

Rsync performance can vary by filetype.  Ex lots of small files slow down throughput.

 

Anything in dmesg?   You could try running iperf3 between your sbc and nas for the same duration and see if performance degrades in a similar pattern or not

[jorgesilva]

Hi - dmesg is clean nothing, they are movies, which are 1-50 Gb in size. I have checked with Iperf and the throughput is 940Mbs network is ok - it is after 30-40 minutes that the iowait times are 40-50% and on some cores it is just sitting at 100% for a while.

[jorgesilva]

I decided to stop the rsync and restart - I have observed the same issue, however, I looked in dmesg and now :

 

[23518.884604] ksoftirqd/3: page allocation failure: order:0, mode:0xa20(GFP_ATOMIC), nodemask=(null),cpuset=/,mems_allowed=0
[23518.885667] CPU: 3 PID: 28 Comm: ksoftirqd/3 Tainted: G         C        5.10.21-rockchip64 #21.02.3
[23518.886492] Hardware name: Radxa ROCK Pi 4C (DT)
[23518.886916] Call trace:
[23518.887162]  dump_backtrace+0x0/0x200
[23518.887506]  show_stack+0x18/0x68
[23518.887823]  dump_stack+0xcc/0x124
[23518.888146]  warn_alloc+0x104/0x170
[23518.888477]  __alloc_pages_slowpath.constprop.114+0xb78/0xba0
[23518.889005]  __alloc_pages_nodemask+0x2d8/0x340
[23518.889425]  page_frag_alloc+0x1a4/0x1c8
[23518.889792]  __napi_alloc_skb+0xc0/0x138
[23518.890203]  stmmac_napi_poll_rx+0x510/0xbb8 [stmmac]
[23518.890671]  net_rx_action+0x178/0x4a8
[23518.891023]  efi_header_end+0x160/0x41c
[23518.891384]  run_ksoftirqd+0x58/0x70
[23518.891723]  smpboot_thread_fn+0x200/0x238
[23518.892103]  kthread+0x140/0x150
[23518.892408]  ret_from_fork+0x10/0x34
[23518.892803] Mem-Info:
[23518.893048] active_anon:892 inactive_anon:35673 isolated_anon:0
                active_file:30359 inactive_file:788240 isolated_file:0
                unevictable:488 dirty:87276 writeback:28673
                slab_reclaimable:42998 slab_unreclaimable:16867
                mapped:15336 shmem:3404 pagetables:1159 bounce:0
                free:3827 free_pcp:3371 free_cma:0
[23518.896076] Node 0 active_anon:3568kB inactive_anon:142692kB active_file:121436kB inactive_file:3152960kB unevictable:1952kB isolated(anon):0kB isolated(file):0kB mapped:61344kB dirty:349124kB writeback:114692kB shmem:13616kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB kernel_stack:4080kB all_unreclaimable? no
[23518.898706] Node 0 DMA free:15000kB min:124kB low:1080kB high:2036kB reserved_highatomic:0KB active_anon:0kB inactive_anon:2500kB active_file:8172kB inactive_file:874184kB unevictable:0kB writepending:152300kB present:1046528kB managed:956812kB mlocked:0kB pagetables:136kB bounce:0kB free_pcp:6816kB local_pcp:1656kB free_cma:0kB
[23518.901430] lowmem_reserve[]: 0 2864 2864 2864
[23518.901871] Node 0 DMA32 free:308kB min:384kB low:3316kB high:6248kB reserved_highatomic:0KB active_anon:3568kB inactive_anon:140192kB active_file:113264kB inactive_file:2278776kB unevictable:1952kB writepending:311516kB present:3014656kB managed:2933404kB mlocked:1952kB pagetables:4500kB bounce:0kB free_pcp:6660kB local_pcp:1128kB free_cma:0kB
[23518.904661] lowmem_reserve[]: 0 0 0 0
[23518.905032] Node 0 DMA: 28*4kB (UME) 73*8kB (UME) 84*16kB (UME) 38*32kB (UME) 59*64kB (UME) 37*128kB (UME) 13*256kB (UME) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15096kB
[23518.906480] Node 0 DMA32: 1*4kB (M) 0*8kB 1*16kB (M) 9*32kB (UM) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 308kB
[23518.907631] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[23518.908471] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=32768kB
[23518.909250] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[23518.910014] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=64kB
[23518.910760] 822489 total pagecache pages
[23518.911124] 0 pages in swap cache
[23518.911434] Swap cache stats: add 0, delete 0, find 0/0
[23518.911908] Free swap  = 0kB
[23518.912234] Total swap = 0kB
[23518.912512] 1015296 pages RAM
[23518.912791] 0 pages HighMem/MovableOnly
[23518.913145] 42742 pages reserved
[23518.913444] 32768 pages cma reserved