Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Rustic restore slower than Restic when there are huge numbers of files. #32

Closed
LuckyFrost opened this issue Nov 4, 2023 · 4 comments · Fixed by #33
Closed

Rustic restore slower than Restic when there are huge numbers of files. #32

LuckyFrost opened this issue Nov 4, 2023 · 4 comments · Fixed by #33
Labels
S-triage Status: Waiting for a maintainer to triage this issue/PR

Comments

@LuckyFrost
Copy link

And restore is slower even if the files are already existing.

time restic restore latest --target=/srv/ -o s3.connections=64
Summary: Restored 25016167 files/dirs (4.092 TiB) in 3:10:02
real 190m23.339s

time rustic -r rclone:xxxxx:yyyyy restore latest --delete /srv/
using no config file, none of these exist: /root/.config/rustic/rustic.toml, /etc/rustic/rustic.toml, ./rustic.toml
[INFO] repository rclone:xxxxx:yyyyy: password is correct.
[INFO] using cache at /root/.cache/rustic/89660cf9b6e34051e0f099b6a3921def13ce9bd0a990d1150b3030b654c1fd8c
[00:00:02] reading index...               ████████████████████████████████████████        143/143
[00:00:00] getting latest snapshot...     ████████████████████████████████████████         63/63
[00:17:19] collecting file information...                                                                                                                                                                    Files:  0 to restore, 24894663 unchanged, 13253 verified, 0 to modify, 0 additional
Dirs:   0 to restore, 119560 to modify, 0 additional
[INFO] total restore size: 0 B
[INFO] using 4.1 TiB of existing file contents.
[INFO] all file contents are fine.
[00:00:00] restoring file contents...     ████████████████████████████████████████        0 B/0 B        0 B/s        (ETA -)
[00:00:00] setting metadata...            ⠁
[03:21:47] setting metadata...
restore done.

real    219m11.290s

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 34.41    0.865089           4    200338     68865 openat
 21.79    0.547918           3    153419           close
 13.03    0.327553           3     87648           newfstatat
  5.24    0.131846           3     37568           epoll_ctl
  3.69    0.092759           9      9423      3162 connect
  3.13    0.078629           3     25061           epoll_wait
  2.39    0.060189           6      9423           socket
  2.13    0.053659           8      6262           sendto
  1.90    0.047768           3     12522           getdents64
  1.83    0.046118          14      3131           fchownat
  1.56    0.039172           3     12524           fcntl
  1.29    0.032372           5      6277        16 recvfrom
  1.06    0.026609           4      6261           epoll_create1
strace 
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
fchownat(AT_FDCWD, "/srv/srv/PATHTOFILE", 63456, 504, AT_SYMLINK_NOFOLLOW) = 0
chmod("/srv/srv/PATHTOFILE", 0100660) = 0
llistxattr("/srv/srv/PATHTOFILE", NULL, 0) = 0
utimensat(AT_FDCWD, "/srv/srv/PATHTOFILE", [{tv_sec=1576755668, tv_nsec=0} /* 2019-12-19T11:41:08+0000 */, {tv_sec=1576755668, tv_nsec=0} /* 2019-12-19T11:41:08+0000 */], AT_SYMLINK_NOFOLLOW) = 0
newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0644, st_size=2980, ...}, 0) = 0
openat(AT_FDCWD, "/etc/group", O_RDONLY|O_CLOEXEC) = 7
newfstatat(7, "", {st_mode=S_IFREG|0644, st_size=621, ...}, AT_EMPTY_PATH) = 0
lseek(7, 0, SEEK_SET)                   = 0
read(7, "root:x:0:\nbin:x:1:\ndaemon:x:2:\ns"..., 4096) = 621
read(7, "", 4096)                       = 0
close(7)                                = 0
openat(AT_FDCWD, "/var/lib/sss/mc/group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/var/lib/sss/mc/group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
getpid()                                = 2745
socket(AF_UNIX, SOCK_STREAM, 0)         = 7
fcntl(7, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(7, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
fcntl(7, F_GETFD)                       = 0
fcntl(7, F_SETFD, FD_CLOEXEC)           = 0
connect(7, {sa_family=AF_UNIX, sun_path="/var/lib/sss/pipes/nss"}, 110) = -1 ENOENT (No such file or directory)
close(7)                                = 0
rt_sigprocmask(SIG_BLOCK, [HUP USR1 USR2 PIPE ALRM CHLD TSTP URG VTALRM PROF WINCH IO], [], 8) = 0
openat(AT_FDCWD, "/run/systemd/userdb/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 7
newfstatat(7, "", {st_mode=S_IFDIR|0755, st_size=60, ...}, AT_EMPTY_PATH) = 0
getdents64(7, 0x55ec01ac4880 /* 3 entries */, 32768) = 96
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 8
connect(8, {sa_family=AF_UNIX, sun_path="/run/systemd/userdb/io.systemd.DynamicUser"}, 45) = 0
epoll_create1(EPOLL_CLOEXEC)            = 9
timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 10
epoll_ctl(9, EPOLL_CTL_ADD, 10, {events=EPOLLIN, data={u32=25555648, u64=94472126198464}}) = 0
epoll_ctl(9, EPOLL_CTL_ADD, 8, {events=0, data={u32=28066992, u64=94472128709808}}) = 0
getdents64(7, 0x55ec01ac4880 /* 0 entries */, 32768) = 0
close(7)                                = 0
epoll_ctl(9, EPOLL_CTL_MOD, 8, {events=EPOLLIN|EPOLLOUT, data={u32=28066992, u64=94472128709808}}) = 0
timerfd_settime(10, TFD_TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=15055, tv_nsec=569876000}}, NULL) = 0
epoll_wait(9, [{events=EPOLLOUT, data={u32=28066992, u64=94472128709808}}], 8, 0) = 1
sendto(8, "{\"method\":\"io.systemd.UserDataba"..., 133, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 133
epoll_ctl(9, EPOLL_CTL_MOD, 8, {events=EPOLLIN, data={u32=28066992, u64=94472128709808}}) = 0
epoll_wait(9, [{events=EPOLLIN, data={u32=28066992, u64=94472128709808}}], 8, 0) = 1
recvfrom(8, "{\"error\":\"io.systemd.UserDatabas"..., 131080, MSG_DONTWAIT, NULL, NULL) = 66
epoll_ctl(9, EPOLL_CTL_MOD, 8, {events=0, data={u32=28066992, u64=94472128709808}}) = 0
epoll_wait(9, [], 8, 0)                 = 0
epoll_wait(9, [], 8, 0)                 = 0
epoll_ctl(9, EPOLL_CTL_DEL, 8, NULL)    = 0
close(8)                                = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "etc", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 8
newfstatat(8, "", {st_mode=S_IFDIR|0755, st_size=8192, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(8, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(8)                                = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "run", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 8
newfstatat(8, "", {st_mode=S_IFDIR|0755, st_size=960, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(8, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(8)                                = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "run", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 8
newfstatat(8, "", {st_mode=S_IFDIR|0755, st_size=960, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(8, "host", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(8)                                = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 8
newfstatat(8, "", {st_mode=S_IFDIR|0755, st_size=144, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(8, "local", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 7
newfstatat(7, "", {st_mode=S_IFDIR|0755, st_size=131, ...}, AT_EMPTY_PATH) = 0
close(8)                                = 0
openat(7, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 8
newfstatat(8, "", {st_mode=S_IFDIR|0755, st_size=6, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(8, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(8)                                = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 8
newfstatat(8, "", {st_mode=S_IFDIR|0755, st_size=144, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(8, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 7
newfstatat(7, "", {st_mode=S_IFDIR|0555, st_size=4096, ...}, AT_EMPTY_PATH) = 0
close(8)                                = 0
openat(7, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(7)                                = 0
openat(AT_FDCWD, "/etc/userdb/USERNAME_GROUPNAME.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/run/userdb/USERNAME_GROUPNAME.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/run/host/userdb/USERNAME_GROUPNAME.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/lib/userdb/USERNAME_GROUPNAME.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/userdb/USERNAME_GROUPNAME.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
close(9)                                = 0
close(10)                               = 0
openat(AT_FDCWD, "/run/systemd/userdb/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 7
newfstatat(7, "", {st_mode=S_IFDIR|0755, st_size=60, ...}, AT_EMPTY_PATH) = 0
getdents64(7, 0x55ec01ac4880 /* 3 entries */, 32768) = 96
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 8
connect(8, {sa_family=AF_UNIX, sun_path="/run/systemd/userdb/io.systemd.DynamicUser"}, 45) = 0
epoll_create1(EPOLL_CLOEXEC)            = 9
timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 10
epoll_ctl(9, EPOLL_CTL_ADD, 10, {events=EPOLLIN, data={u32=25555648, u64=94472126198464}}) = 0
epoll_ctl(9, EPOLL_CTL_ADD, 8, {events=0, data={u32=24888512, u64=94472125531328}}) = 0
getdents64(7, 0x55ec01ac4880 /* 0 entries */, 32768) = 0
close(7)                                = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "etc", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 11
newfstatat(11, "", {st_mode=S_IFDIR|0755, st_size=8192, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(11, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(11)                               = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "run", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 11
newfstatat(11, "", {st_mode=S_IFDIR|0755, st_size=960, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(11, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(11)                               = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "run", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 11
newfstatat(11, "", {st_mode=S_IFDIR|0755, st_size=960, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(11, "host", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(11)                               = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 11
newfstatat(11, "", {st_mode=S_IFDIR|0755, st_size=144, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(11, "local", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 7
newfstatat(7, "", {st_mode=S_IFDIR|0755, st_size=131, ...}, AT_EMPTY_PATH) = 0
close(11)                               = 0
openat(7, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 11
newfstatat(11, "", {st_mode=S_IFDIR|0755, st_size=6, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(11, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(11)                               = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 11
newfstatat(11, "", {st_mode=S_IFDIR|0755, st_size=144, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(11, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 7
newfstatat(7, "", {st_mode=S_IFDIR|0555, st_size=4096, ...}, AT_EMPTY_PATH) = 0
close(11)                               = 0
openat(7, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(7)                                = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "etc", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 11
newfstatat(11, "", {st_mode=S_IFDIR|0755, st_size=8192, ...}, AT_EMPTY_PATH) = 0
close(7)                                = 0
openat(11, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
close(11)                               = 0
openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 7
openat(7, "run", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 11

The situation is greatly improved by --numeric-id (~16m to restore), but I don’t understand why it chowns and chmods if nothing has changed, It spends half the time on this (I ran several times sequentially):

strace -cp rustic_pid
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 36.11    1.709402           6    265619           fchownat
 23.74    1.123784           4    265620           chmod
 22.48    1.063941           4    265620           utimensat
 17.67    0.836419           3    265620           llistxattr
------ ----------- ----------- --------- --------- ----------------
100.00    4.733546           4   1062479           total

Perhaps it's worth making numeric-id the default?
@github-actions github-actions bot added the S-triage Status: Waiting for a maintainer to triage this issue/PR label Nov 4, 2023
@aawsome aawsome transferred this issue from rustic-rs/rustic Nov 4, 2023
@aawsome
Copy link
Member

aawsome commented Nov 4, 2023

Thanks a lot for opening this issue!
You are right, currently restore always restores metadata - also if files already exist with correct metadata. This can be improved but would require bigger changes in restore which I would like to tackle after we have a better test coverage here...

Anyway, I am irritated by the fact that using names instead of uid/gid takes so much longer... I expected those to be cached so that each name has to be resolved just once. I'll have a look at it soon...

BTW: moved this to rustic_core as this is an issue within this crate.

@aawsome
Copy link
Member

aawsome commented Nov 4, 2023

Ok, I realized that there is no caching - I think this was lost when we changed it using the nix crate - IIRC this was due to some security alerts in the crate we used before...

So this explains it - each name is resolved by a syscall which is not optimal - we should add a caching again here.

@LuckyFrost
Copy link
Author

Also keep in mind that there may be nothing to cache, because... the user may not exist.
I’m also not sure that it will remain the optimal option as for default even with caching - there can be quite a lot of users/groups, although this is probably not the most common case.

@aawsome aawsome mentioned this issue Nov 5, 2023
Merged
@aawsome
Copy link
Member

aawsome commented Nov 5, 2023

About the default: AFAIK GNU tar also restores by default using user/group names instead of the uid/gid and this was influencing the choice of rustic's default behavior.
Anyway, there are --numeric-id and --no-ownership - so users can use whatever they prefer.

In #33 caching for uids/gids has been added. If you have many users/groups, this will take some memory, yes. But I think the performance gain should be worth it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
S-triage Status: Waiting for a maintainer to triage this issue/PR
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

restore: Add caching for uid/gid names rustic-rs/rustic_core
2 participants
@aawsome @LuckyFrost