1.1-maint vs master performance difference

[ThomasWaldmann]

In #3955 the question came up, why borg create with master branch code is slower than with 1.1-maint branch code. The benchmarks I did there were archiving lots of relatively small files.

I did a source code based analysis, checking the "hot" code path that is taken when backing up known, unchanged, regular files (like when doing a 2nd backup right after a first one, without much changes).

Found this difference, in process_file (simplified pseudo code that is new in master):

        fd = open(path)
        st_fd = fstat(fd)
        stat_update_check(st_path, st_fd)

These changes were done when switching borg master branch to work based on a FD (file descriptor) to avoid race conditions and potential security issues. See #4043.

For this, master code does it like this:

• st_path = stat(path) - before dispatching to file-type handler
• dispatch based on st_path (e.g. to process_file, process_fifo, process_symlink, ...)
• fd = open(path) - get an FD, so we can do other operations based on this FD. new in master (1.1-maint did not open unchanged files and did acquire all metadata based on the path)
• stat_update_check: determining st_fd = fstat(fd) to check for a race condition ("did we dispatch to correct file-type handler?") by comparing st_fd to st_path. this call / this check is new in master
• reading file contents (based on open fd, but not in the "hot" case, here we know contents have not changed)
• reading bsdflags (based on open fd on linux, based on st_fd on others)
• reading xattrs (based on open fd)
• reading ACLs (based on open fd)

[ThomasWaldmann]

For the case of a changed file, there is also an additional fstat(fd) call after reading the file's content, to check whether the file changed while we read it.

[FabioPedretti]

Related: #4497.

[FabioPedretti]

Used this script (based on an early script posted here) to check performance with many (20000) small (0 byte) files.

I run the script overnight many times (when the system load is at the minimum), and while the timing varies somewhat from run to run, I can conclude that:

• 1.2.0a6 is a bit faster than 1.1.9 with default setting and cold cache
• 1.2.0a6 is similar than 1.1.9 with default setting and hot cache
• 1.2.0a6 is a bit faster than 1.1.9 with nobsdflags, first backup and cold cache
• 1.2.0a6 is about +100% slower than 1.1.9 with nobsdflags, second backup and cold cache
• 1.2.0a6 is about +50% slower than 1.1.9 with nobsdflags, and hot cache
• 1.1.9 is about +100% slower and 1.2.0a6 about +200% slower than tar

Example run:

Repo:   remote SSHFS
Source: NFS on rotating disks

Testing with 20000 empty files

1.1.9 default cold cache, first backup:  1:11.61
1.1.9 default cold cache, second backup: 0:56.24
1.1.9 default hot cache, first backup:   0:45.28
1.1.9 default hot cache, second backup:  0:45.19

1.1.9 nobsdflags cold cache, first backup:  0:59.90
1.1.9 nobsdflags cold cache, second backup: 0:32.38
1.1.9 nobsdflags hot cache, first backup:   0:30.31
1.1.9 nobsdflags hot cache, second backup:  0:30.90

1.2.0a6 default cold cache, first backup:  0:56.54
1.2.0a6 default cold cache, second backup: 0:45.92
1.2.0a6 default hot cache, first backup:   0:42.75
1.2.0a6 default hot cache, second backup:  0:43.93

1.2.0a6 nobsdflags cold cache, first backup:  0:55.23
1.2.0a6 nobsdflags cold cache, second backup: 0:56.11
1.2.0a6 nobsdflags hot cache, first backup:   0:44.63
1.2.0a6 nobsdflags hot cache, second backup:  0:43.70

tar + gzip cold cache, for comparison: 0:12.90

[ThomasWaldmann]

@FabioPedretti Thanks for doing measurements.

Nice to see that in some cases it got faster.

For the case (usage with --nobsdflags), where it got slower:

• for 1.1, nobsdflags on linux avoids an open() call which is needed to read the bsdflags for unchanged files (we do not read unchanged files' contents, but we read metadata: acls, xattrs, bsdflags)
• for 1.2, nobsdflags does not avoid the open() call, because we always need to open to work based on a file descriptor (to avoid race conditions)

So it seems that a cold cache open() on NFS is rather slow (maybe not totally unexpected).

Empty files might be the totally worst case here, because there is no content data transfer needing time, so the timing is totally dominated by metadata processing and network delays. It's also the worst case for borg's trick for unchanged files which usually saves lots of time by not having to read the file's content - for 0 bytes, there is nothing to save here.

I also suspect that you have quite a bit of measurement errors due to other influences (I had the same problem even in my local fs measurements), see for example these cases:

1.2.0a6 default cold cache, second backup: 0:45.92
1.2.0a6 nobsdflags cold cache, second backup: 0:56.11   <-- !

1.2.0a6 default hot cache, first backup:   0:42.75
1.2.0a6 nobsdflags hot cache, first backup:   0:44.63

Don't think there can be a reason why borg could be slower when not getting/processing bsdflags.

Somehow embarrassing how fast tar/gz is in this case. :)

Maybe comparing a tar and a borg strace would be interesting (does your tar do the open()? does it read xattrs, acls, bsdflags?).

Of course borg can never win against tar in this zero-bytes files benchmark (there is no content to deduplicate, nothing to avoid reading, but borg still has all the overhead trying to do that anyway).

[FabioPedretti]

Empty files might be the totally worst case here... metadata processing...

Yes, I used them because I think they better isolate the problem with "huge amount of files, with very few changes between runs", that I and other experienced. I supposed most of the time of my backups are due to this issue.

I also suspect that you have quite a bit of measurement errors due to other influences...

Yes, sorry for that, I run it in on a production virtual system, also used by others. Indeed they are not perfectly comparable.

does your tar do the open()?

Using "tar (GNU tar) 1.29" from Debian stretch.
While borg binaries are the ones downloaded from github.

Maybe comparing a tar and a borg strace would be interesting

Here are the straces for a 10 files "0-byte" run.

[ThomasWaldmann]

it only straced the main process (and there is nothing interesting in there).

you need to use strace -f ... so it also follows to child processes.

[FabioPedretti]

New straces, now the empty test files have a "testfile-" prefix to make them better searchable.

[FabioPedretti]

BTW:

$ grep -c testfile- *
strace-borg-1.1.9 default cold cache, first backup:  .txt:50
strace-borg-1.1.9 default cold cache, second backup: .txt:41
strace-borg-1.1.9 default hot cache, first backup:   .txt:41
strace-borg-1.1.9 default hot cache, second backup:  .txt:41
strace-borg-1.1.9 nobsdflags cold cache, first backup:  .txt:40
strace-borg-1.1.9 nobsdflags cold cache, second backup: .txt:31
strace-borg-1.1.9 nobsdflags hot cache, first backup:   .txt:31
strace-borg-1.1.9 nobsdflags hot cache, second backup:  .txt:31
strace-borg-1.2.0a6 default cold cache, first backup:  .txt:20
strace-borg-1.2.0a6 default cold cache, second backup: .txt:20
strace-borg-1.2.0a6 default hot cache, first backup:   .txt:20
strace-borg-1.2.0a6 default hot cache, second backup:  .txt:20
strace-borg-1.2.0a6 nobsdflags cold cache, first backup:  .txt:20
strace-borg-1.2.0a6 nobsdflags cold cache, second backup: .txt:20
strace-borg-1.2.0a6 nobsdflags hot cache, first backup:   .txt:20
strace-borg-1.2.0a6 nobsdflags hot cache, second backup:  .txt:20
strace-tar.txt:23

[ThomasWaldmann]

that's because 1.1.x works filename-based (giving each call the path/filename) and 1.2 works fd-based (stats/opens once with the name, then uses the fd).

[ThomasWaldmann]

tar: doesn't do much here:

• I only see it stat-ing the files.
• It doesn't open the file (likely due to 0 bytes).
• It does not try to get xattrs, acls or bsdflags.

[ThomasWaldmann]

borg 1.2:

# name-based stat relative to dir fd to determine file type for dispatching to correct handler
newfstatat(6, "testfile-2", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
# name-based open relative to dir fd to get an FD for the file to avoid race conditions
openat(6, "testfile-2", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_NOFOLLOW|O_NOATIME|O_CLOEXEC) = 7
# everything below here is file-FD-based:
# stat again to detect filetype having changed (race) and whether we are in correct handler
fstat(7, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
# vvvvvvvvvvvvvvvv only for new/changed files:
# try reading contents
read(7, "", 8388608)        = 0
# avoid spoiling the cache with data we'll not need again
fadvise64(7, 0, 0, POSIX_FADV_DONTNEED) = 0
# stat again to see if file has changed while we were backing it up
fstat(7, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
# ^^^^^^^^^^^^^^^^ only for new/changed files
# get bsdflags
ioctl(7, FS_IOC_GETFLAGS, 0x7fff59a5e03c) = -1
# get xattrs
flistxattr(7, "", 4096)     = 0
# get acls
fgetxattr(7, "system.posix_acl_access", NULL, 0) = -1 EOPNOTSUPP (Operation not supported)
# done
close(7)                    = 0

(as expected)

[FabioPedretti]

Added new straces with small, non-empty, all different files.