Restore of 1Tb with local repo is unbelievably slow

Jack · July 1, 2020, 11:25am

Hi All,

I’ve been having a great time backing up with restic, bar trying to prune the repo at B2 but that’s another story. I’m using restic 0.9.6. The problem is restore is very slow.

I have backed up my server at OVH with approx 1Tb of data to my home server via rest-server so that I have the restic repo locally. I have 1Gb/s connection and this took about 9hrs, so the disks can write 1Tb in 9hrs.

I have three disks in a raidz: 3x 4Tb HDD.

NAME                                                STATE     READ WRITE CKSUM
	rpool                                               ONLINE       0     0     0
	  raidz1-0                                          ONLINE       0     0     0
	    ata-WDC_WD40EFRX-68N32N0_WD-WCC7K1ZNKUA6-part3  ONLINE       0     0     0
	    ata-WDC_WD40EFRX-68N32N0_WD-WCC7K7JES0C3-part3  ONLINE       0     0     0
	    ata-WDC_WD40EFRX-68N32N0_WD-WCC7K7UTTRCN-part3  ONLINE       0     0     0

The repository and disk I am trying to restore to are :

data: /mnt/mysql
rpool/data/subvol-102-disk-0  30.6G   969G     30.6G  /rpool/data/subvol-102-disk-0

repo: /mnt/restic
rpool/data/subvol-102-disk-1  1.11T   863G     1.11T  /rpool/data/subvol-102-disk-1

The restore has been running 17hrs, and only restored 30.6Gb.

100000   13427 11746 99 Jun30 ?        1-16:56:12 restic -r /mnt/restic/db1 -p /etc/rest-server/password restore 413620dd --target /mnt/mysql

The server is not busy, its Ryzen 5 3600 6 core, 64Gb RAM, restic is the only process using CPU.

top - 13:16:42 up 2 days,  1:46,  1 user,  load average: 3.12, 3.48, 3.72
Tasks: 521 total,   3 running, 518 sleeping,   0 stopped,   0 zombie
%Cpu(s): 24.8 us,  0.3 sy,  0.0 ni, 71.6 id,  0.6 wa,  0.0 hi,  2.7 si,  0.0 st
MiB Mem :  64273.7 total,  26390.2 free,  36746.9 used,   1136.6 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.  27409.8 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                      
13427 100000    20   0 3275232   1.3g   9584 R 304.3   2.1   2461:46 restic

There is no iowait and the disks are not thrashing, or in fact doing much at all, they can manage 1000 tps, the raid members are sda,sdb,sdc.

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          11.39    0.00    0.83    0.53    0.00   87.26

Device             tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
sda              34.40       731.20       318.40       3656       1592
sdb              30.20       780.80       308.80       3904       1544
sdd               0.00         0.00         0.00          0          0
sdc              35.20       924.00       320.00       4620       1600
sde               0.00         0.00         0.00          0          0
zd0               0.00         0.00         0.00          0          0
zd16              0.00         0.00         0.00          0          0

Any ideas please?

strace -f -p $(pgrep restic)

[pid  6360] futex(0xc00011c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6353] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6353] futex(0xc00011c148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6360] <... futex resumed>)        = 0
[pid  6353] <... futex resumed>)        = 1
[pid  6360] futex(0xc00011c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6353] futex(0xc00011c148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6360] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid  6353] <... futex resumed>)        = 0
[pid  6360] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6360] futex(0xc00011dd48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6814] <... futex resumed>)        = 0
[pid  6360] <... futex resumed>)        = 1
[pid  6814] futex(0xc00011dd48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6368] futex(0xc00011c148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6360] futex(0xc00011c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6368] <... futex resumed>)        = 0
[pid  6360] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid  6360] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6360] futex(0xc00011dd48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6814] <... futex resumed>)        = 0
[pid  6360] <... futex resumed>)        = 1
[pid  6814] futex(0xc00011dd48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6360] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6353] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6353] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6353] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6353] futex(0xc00011dd48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6814] <... futex resumed>)        = 0
[pid  6353] <... futex resumed>)        = 1
[pid  6814] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6367] futex(0xc00010a4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6353] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6814] <... nanosleep resumed>NULL) = 0
[pid  6353] <... nanosleep resumed>NULL) = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6353] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6353] <... nanosleep resumed>NULL) = 0
[pid  6353] futex(0xc00010a4c8, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6367] <... futex resumed>)        = 0
[pid  6367] futex(0xc00010a4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6363] futex(0xc00010a4c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6367] <... futex resumed>)        = 0
[pid  6363] <... futex resumed>)        = 1
[pid  6367] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6367] <... nanosleep resumed>NULL) = 0
[pid  6367] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6367] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6363] futex(0xc000279d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6360] futex(0xc000279d48, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6363] <... futex resumed>)        = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6363] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6814] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6814] <... nanosleep resumed>NULL) = 0
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6814] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6367] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6368] futex(0xc00010a848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6814] <... nanosleep resumed>NULL) = 0
[pid  6367] <... nanosleep resumed>NULL) = 0
[pid  6814] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6367] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6814] <... nanosleep resumed>NULL) = 0
[pid  6367] <... nanosleep resumed>NULL) = 0
[pid  6367] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6367] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6367] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6367] futex(0xc00010a848, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6368] <... futex resumed>)        = 0
[pid  6367] <... futex resumed>)        = 1
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6368] futex(0xc00010a848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6365] futex(0xc0024464c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6363] futex(0xc000279d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6814] futex(0xc00011dd48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6367] futex(0xc00010a4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6360] futex(0xc00011dd48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6814] <... futex resumed>)        = 0
[pid  6360] <... futex resumed>)        = 1
[pid  6814] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6814] futex(0xc00010a4c8, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6367] <... futex resumed>)        = 0
[pid  6367] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6367] futex(0xc00010a848, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6368] <... futex resumed>)        = 0
[pid  6367] <... futex resumed>)        = 1
[pid  6368] futex(0xc00010a848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6367] futex(0xc00010a848, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6368] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid  6367] <... futex resumed>)        = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] futex(0xc0024464c8, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6365] <... futex resumed>)        = 0
[pid  6365] futex(0xc000279d48, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6363] <... futex resumed>)        = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6363] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6814] futex(0xc00011dd48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6368] futex(0xc00010a848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6360] futex(0xc00010a848, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6368] <... futex resumed>)        = 0
[pid  6360] <... futex resumed>)        = 1
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] futex(0xc00011dd48, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6814] <... futex resumed>)        = 0
[pid  6814] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6367] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6365] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6354] <... nanosleep resumed>NULL) = 0
[pid  6814] <... nanosleep resumed>NULL) = 0
[pid  6354] epoll_pwait(4, [], 128, 0, NULL, 139887396441520) = 0
[pid  6367] <... nanosleep resumed>NULL) = 0
[pid  6354] nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
[pid  6365] <... nanosleep resumed>NULL) = 0
[pid  6360] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6365] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6365] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6365] <... nanosleep resumed>NULL) = 0
[pid  6368] <... nanosleep resumed>NULL) = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6368] <... nanosleep resumed>NULL) = 0
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6363] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6368] futex(0xc00010a848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6365] futex(0xc0024464c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6814] futex(0xc00011dd48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6360] futex(0xc00011dd48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6814] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid  6360] <... futex resumed>)        = 0
[pid  6814] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6814] futex(0xc0024464c8, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6365] <... futex resumed>)        = 0
[pid  6365] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6365] futex(0xc00010a848, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6368] <... futex resumed>)        = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6367] futex(0xc000279d48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6363] futex(0xc000279d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6367] <... futex resumed>)        = 0
[pid  6365] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6363] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6365] <... nanosleep resumed>NULL) = 0
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6365] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6365] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6365] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6365] <... nanosleep resumed>NULL) = 0
[pid  6368] <... nanosleep resumed>NULL) = 0
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6368] <... nanosleep resumed>NULL) = 0
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6368] <... nanosleep resumed>NULL) = 0
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6363] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6368] futex(0xc00010a848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6365] futex(0xc0024464c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6360] futex(0xc00010a848, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6368] <... futex resumed>)        = 0
[pid  6360] <... futex resumed>)        = 1
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] futex(0xc0024464c8, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6365] <... futex resumed>)        = 0
[pid  6365] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid  6365] <... nanosleep resumed>NULL) = 0
[pid  6363] <... nanosleep resumed>NULL) = 0
[pid  6363] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6363] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6368] futex(0xc00010a848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6360] futex(0xc00010a848, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6368] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid  6360] <... futex resumed>)        = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6363] futex(0xc000279d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6353] <... futex resumed>)        = 0
[pid  6353] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6353] futex(0xc000279d48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6363] <... futex resumed>)        = 0
[pid  6353] <... futex resumed>)        = 1
[pid  6363] futex(0xc000279d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6367] futex(0xc00010a4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6814] futex(0xc00011dd48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6368] futex(0xc00010a848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6365] futex(0xc0024464c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6353] futex(0x1500a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  6360] futex(0x1500a88, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6353] <... futex resumed>)        = 0
[pid  6353] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6353] futex(0xc00010a848, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  6368] <... futex resumed>)        = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
[pid  6368] nanosleep({tv_sec=0, tv_nsec=3000}, ^Cstrace: Process 6353 detached
strace: Process 6354 detached
strace: Process 6355 detached

dionorgua · July 1, 2020, 12:00pm

There was huge restore performance improvement after 0.9.6 release. So try again with latest git version or use binaries from https://beta.restic.net/?sort=time&order=desc

Jack · July 1, 2020, 12:21pm

Update

Restoring to my mac book over wifi with ~400Mbs WiFi connection I get a solid 25-30Mb/s write speed which is acceptable, the macbook is SSD but I’m thinking that ZFS could be the culprit? My server is running Proxmox 6.2 and the restic is running in a LXC container, although I have tried running restic on the proxmox host directly and the speeds are the same.

             disk0       cpu    load average
    KB/t  tps  MB/s  us sy id   1m   5m   15m
   12.33 1198 14.42  36 20 44  4.07 4.44 3.94
   23.77  877 20.36  45 26 29  3.99 4.41 3.94
   16.24 1708 27.09  28 19 53  3.83 4.37 3.92
   10.61 1457 15.09  26 19 55  3.92 4.38 3.93
   10.93 1794 19.14  26 18 56  3.77 4.34 3.92
   14.85 1430 20.75  41 34 25  3.71 4.32 3.91
    9.41 1293 11.88  32 28 40  3.57 4.28 3.90
   16.89 1027 16.94  35 32 32  3.44 4.24 3.89
   16.10 2215 34.82  37 21 42  3.33 4.21 3.88
   10.97  997 10.69  34 20 46  5.06 4.55 4.00
   19.89 1265 24.57  30 21 48  4.90 4.52 4.00
   12.59 1266 15.57  32 18 50  4.75 4.50 3.99
    9.83 1453 13.95  24 14 61  4.53 4.46 3.98
   13.83 1523 20.56  32 18 50  4.32 4.42 3.97
   34.59  761 25.71  38 20 42  4.78 4.51 4.00
   34.25  373 12.48  45 20 35  4.88 4.53 4.01
   31.90  374 11.64  22 17 61  4.64 4.49 4.00
   24.38 1085 25.83  36 21 43  4.51 4.47 3.99
   11.24 1505 16.51  33 13 54  4.31 4.43 3.98

Jack · July 1, 2020, 12:21pm

Thanks - I’ll try it.

Jack · July 1, 2020, 12:47pm

Update 2

Running with

restic 0.9.6 (v0.9.6-247-g64976b1a) compiled with go1.14.3 on linux/amd64

Theres a lot of this, but it is now working better.

[pid   656] openat(AT_FDCWD, "/mnt/mysql/backup/xxxxxx/actions.ibd", O_WRONLY|O_CLOEXEC) = 10
[pid   656] epoll_ctl(3, EPOLL_CTL_ADD, 10, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=2892213992, u64=140572876844776}}) = -1 EPERM (Operation not permitted)
[pid   656] epoll_ctl(3, EPOLL_CTL_DEL, 10, 0xc01acab47c) = -1 EPERM (Operation not permitted)
[pid   656] pwrite64(10, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0p\20\26\10\241#D"..., 540181, 26970111930) = 540181
[pid   656] close(10)                   = 0

I’m seeing 50% iowait, so this now seems to be the limiting factor.

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2.11    0.00    2.73   51.28    0.00   43.88

Device             tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
sda             247.60     18841.60     14068.80      94208      70344
sdb             250.60     18845.60     14064.00      94228      70320
sdd               0.00         0.00         0.00          0          0
sdc             218.80     16940.80     14068.00      84704      70340
sde               0.00         0.00         0.00          0          0
zd0               0.00         0.00         0.00          0          0
zd16              0.00         0.00         0.00          0          0

Thanks, this is now ‘acceptable’ restore speed given its raid 5 and traditional HDD’s and I’m coping from one volume to another in the same array. I’ll test later with separate disks for the repo and the array.

It seems to be running 26 threads, it does make me wonder though if less threads would result in more speed due to less disk thrashing? I did a search but I see no option to run with less.

Interestingly (maybe …) restic is now showing a lot less CPU usage (21.9%) too.

  639 root      20   0 1743376   1.0g   6264 S  21.9   3.2   4:30.72 restic