borgbackup
ACL code does a lot of user/group<->uid/gid lookups
Have you checked borgbackup docs, FAQ, and open Github issues?
Yes
Is this a BUG / ISSUE report or a QUESTION?
Issue
System information. For client/server mode post info for both machines.
Your borg version (borg -V).
client: borg 1.1.13
server: borg 1.1.13
Operating system (distribution) and version.
client: Centos 6
server: Centos 7
Hardware / network configuration, and filesystems used.
Backup via internet
How much data is handled by borg?
450GB
302366 files
Full borg commandline that lead to the problem (leave away excludes and passwords)
borg create -s -p -C lzma --list --filter=AME --exclude-from=/root/exclude-backup.txt --files-cache=ctime,size borg@server-ip:backup/pdc::pdc-{now} /home/data/
Describe the problem you're observing.
I experience slow 2nd+ backup with winbind as nss provider after a after successful 1st backup.
First backup takes 23 hours, next backups still takes >20 hours
Can you reproduce the problem? If so, describe how. If not, describe troubleshooting steps you took before opening the issue.
I have tried to remove /root/.cache , but still slow
Thanks
Include any warning/errors/backtraces from the system logs
none
Easiest explanation is that something frequently/regularly changes the ctime of many fs items, e.g. chmod/chown -R ....
Or, that the full path is changing (does not look like, you wrote that you use /home/data/).
Of course, after removing borg's cache, next backup is expected to be slow, but the one after that should then be faster again.
Another reason why you maybe do not see a huge speedup could be that you have lots of small files, which are in general less efficient to deal with. In that case 20h < 23h is maybe all the speedup you'll get.
Yes, there are lots of small files: roaming storage for windows users. Any suggestion for speeding up backup lots of small files? I'll try again using mtime,size . Ok.. using fresh cache (will do backup twice)
Thanks
Hi, i've tried 3 backups with clear borg's cache, using files-cache=ctime,size again Excluding some files, now files around 130.000
Time required for first backup is: 23 hours , next backups is 17 hours , and new files is not many
Is there any way to make next backups faster than 17 hours?
Probably xattr causes slow down while enumerating files? I checked the mount point is using xattr option for samba
Or maybe python dictionary lookup is that slow
Archive name: pdc-2020-08-13
Archive fingerprint: 9c72ae92713cf9313f85393f57d49edd7dd78156007666fca081c2b7161eee54
Comment:
Hostname: pdc
Username: root
Time (start): Thu, 2020-08-13 21:03:48
Time (end): Fri, 2020-08-14 20:20:07
Duration: 23 hours 16 minutes 18.47 seconds
Number of files: 131817
Utilization of maximum supported archive size: 0%
------------------------------------------------------------------------------
Original size Compressed size Deduplicated size
This archive: 236.07 GB 173.87 GB 21.28 MB
All archives: 4.54 TB 3.83 TB 176.91 GB
Unique chunks Total chunks
Chunk index: 334972 3362062
Archive name: pdc-2020-08-14
Archive fingerprint: c04886c76b7f0468884eee5e014c65d914e16ae747a3103129ebcb97c45c6243
Comment:
Hostname: pdc
Username: root
Time (start): Fri, 2020-08-14 21:18:05
Time (end): Sat, 2020-08-15 15:07:00
Duration: 17 hours 48 minutes 54.85 seconds
Number of files: 132209
Utilization of maximum supported archive size: 0%
------------------------------------------------------------------------------
Original size Compressed size Deduplicated size
This archive: 237.16 GB 174.94 GB 20.16 MB
All archives: 4.54 TB 3.83 TB 176.91 GB
Unique chunks Total chunks
Chunk index: 334972 3362062
Archive name: pdc-2020-08-15
Archive fingerprint: 6ca991b167276e2f76b17b2d1284172faae0cee9bf5de6c7b419b30add9ff2eb
Comment:
Hostname: pdc
Username: root
Time (start): Sat, 2020-08-15 23:24:51
Time (end): Sun, 2020-08-16 16:40:31
Duration: 17 hours 15 minutes 39.20 seconds
Number of files: 132369
Utilization of maximum supported archive size: 0%
------------------------------------------------------------------------------
Original size Compressed size Deduplicated size
This archive: 237.31 GB 175.09 GB 128.19 MB
All archives: 4.54 TB 3.83 TB 176.91 GB
Unique chunks Total chunks
Chunk index: 334972 3362062
Something is "wrong" in your setup.
Here are some stats from one of my backups:
Archive name: server-2020-08-15-23:42:01
Archive fingerprint: ...
Time (start): Sat, 2020-08-15 23:42:11
Time (end): Sat, 2020-08-15 23:45:23
Duration: 3 minutes 11.94 seconds
Number of files: 802035
Utilization of max. archive size: 0%
------------------------------------------------------------------------------
Original size Compressed size Deduplicated size
This archive: 669.61 GB 619.04 GB 4.72 MB
All archives: 86.02 TB 78.02 TB 1.14 TB
Unique chunks Total chunks
Chunk index: 7919874 241722469
So you see, for this backup, it took 3 minutes to process 800k files (most of them did not have changes, only a few new/with changes resulting in a deduped backup size of ~5MB).
Setup:
borg client:
- server-grade machine with a fast Xeon CPU and lots of RAM.
- the files are on HDD (not SSD) and the filesystem is ZFS (2-disk mirror).
- ubuntu linux 20.04
borg repo server:
- remote machine via ssh, ~40Mbit/s WAN connection
- relatively old/slow machine, AMD Turion CPU, 4GB RAM
- borg repo files on HDD, fs is ZFS (2-disk mirror).
- ubuntu linux 20.04
Stuff to check:
-
can you reproduce on something more recent than centos 6 (which is rather old). maybe try with a newer client and same repo server.
-
are you running out of (real) memory while borg is running (check client and server)? how much paging ("swapping") activity do you see?
-
you already run borg with
--list --filter AME, did you look into the output produced by that? when looking at the status chars at the beginning of the lines, you should see how many files borg considers as A)dded or M)odified, also check for any E)rrors. if it considers too much as A/M although it was not "really" (not intentionally) added/modified, there is something wrong and the files-cache thus can't work efficiently. -
is there other load on the client or on the server that maybe slows down borg? e.g. if a HDD is already rather busy seeking due to other load, borg performance will be impacted.
-
are there serious network issues slowing down borg? minor network issues (like minor latency or throughput issues) should not be an issue here - as the deduplication works quite good for you, there is not much to transfer to the repo.
-
the input files, are they local or are they mounted via some network filesystem? if the latter, check performance of that network fs.
You did not specify where you got borg 1.1.13 from. Is it the binary from github releases?
If yes, maybe also try an older binary on the centos6 machine.
borg 1.1.11 was built on (old) debian wheezy and might work better for old linux dists. See #5220. borg 1.1.13 was built on (more recent) debian jessie.
This only applies to the "fat binaries" offered on github releases (made with pyinstaller).
If you installed borg from source (including via pip), there is no reason to use an older borg release.
Wow thats very fast, 3 minutes.. Yes i think so something wrong with my setup 😭
Borg is compiled using pip, python is 3.6.10 , also compiled from source
Client is virtual machine, with 4 GB allocated. Load is below 1. Using iotop i can see no heavy read/write
I will check again.. Thanks
Hi.. I think I found the problem
When I stop samba while backup, borg skips many files very fast, when I start samba again, backup slow again . My system is using winbind as nss provider to resolve file owner
Using borg diff I found many lines like this:
[DOMAIN\myuser:users -> None:users]
If ext4 acl is already backup by borg, I think it is safe
Then I try backup again with --numeric-owner and samba started, but backup is slow not like when i stop samba. I hope backup is fast when using --numeric-owner , without stopping samba
Thanks
Interesting. So, which of --files-cache=ctime,size,inode does this trigger?
Hmm, maybe winbind does not produce cache misses (at least not if you always have it active), but it is just winbind being very slow compared to a normal stat() against the local filesystem?
TODO: check if borg create --numeric-ids ... does uid/gid -> name lookups.
Can confirm this behavior. It's a long running issue which only appears on system where samba+winbind is used as full nss provider. No file change problem occours, only added/modified/deleted files are processes, and there is no load on the disk (no real read/write happening).
Even using --numeric-ids the id resolution is triggered and extremely slow (16-20 hours for around 800G data from a RAID10/ext4 enterprise array). This could be around 20-30 mins top with active cache.
For comparsion:
- samba/wb stopped: borg uses 100% cpu core and finishes fast
- samba/wb running: borg uses around 2-3% cpu and samba/wb eats up around 85% for nothing
Any workaround would be appreciated.
The normal stat processing at backup time does not do any uid/gid to user/group name lookups if --numeric-owner (correct option name - sorry, i gave an incorrect one in my comment above) is specified.
But, no matter whether --numeric-owner is given or not, ACL processing might do user/group name to uid/gid lookups.
One thing is strange though: in borg 1.1.x, there is a LRU cache for the user/group/uid/gid lookup with unlimited capacity. Thus, after every id/name has been looked up once, this should be very fast and not cause significant slowdown.
So, guess we need an strace (with and without winbind nss) here to determine what's slow.
I'd provide strace output but I cannot mess with the system as it is running in production, but I made a short debug logging inside winbind and found that it's processing hundreds of getpwuid calls per second.
As this machine is an Active Directory member (server), the uid range is at 65000+ and what I found interesting is that the same uids get requested over and over again. The directory that is getting backed up is a samba share where the uid/gid is mapped from AD so 99% of the files use non-standard local uids.
So far it seems like borg is not using its uid lookup cache or some conditions prevents it to operate properly.
Hope these infos help to corner the issue, I'll try to gain more if possible.
@detoxhby thanks for the infos, I'll do some related tests (but I don't have an AD member to test on).
One idea for you might be to run strace and attach it to a running borg process via pid. You'ld need root and it might slow down things a bit, but other than that there should be no impact on a prod system.
The lru cache works, as expected (tried with borg 1.1-maint branch, which is ~ 1.1.15 and python 3.7.3 - but the lru cache stuff did not change recently):
(borg-env) user@development:~$ borg create repo::arch .
getpwuid(0) -> root [default:None]
getgrgid(0) -> root [default:None]
getpwuid(1000) -> user [default:1000]
# ^ the above are always done, come from arg parser setup
#
# v the below ones are from input file processing:
# everything in my home is owned by 1000:1000, but due to caching
# there is only 1 real call for getting the username and 1 for getting the group name
getpwuid(1000) -> user [default:None]
getgrgid(1000) -> user [default:None]
Update: calling print(uid2user.cache_info()) at the end of the run method shows huge counts of cache hits and little misses.
@detoxhby are the getpwuid calls really coming from the borg process? Do you have posix ACLs in there?
To get this output, I added a print() to some functions in borg/helpers.py, like e.g. this:
@lru_cache(maxsize=None)
def uid2user(uid, default=None):
try:
user = pwd.getpwuid(uid).pw_name
print(f"getpwuid({uid}) -> {user} [default:{default}]")
return user
except KeyError:
return default
BTW, this is the one and only place in borg code that calls getpwuid.
are the getpwuid calls really coming from the borg process?
Happens only if borg's running, so I think it's either coming from borg or any companion process borg uses.
ℹ️ I was able to reproduce the exact same behavior using getent or id command, so it's the generic uid resolution which triggers NSS -->Winbind-->Samba chain.
(no problem occours, everything is resolved properly; the borg side problem is only the trendemous call count).
Next weeks going to be super busy for us, but I'll try to find a bit time to trace the borg process. If you could find any other processing point where borg directly or indirectly resolving uid/gid that could point out how is borg related to this.
Do you have posix ACLs in there?
Nope, no ACLs on that mount (plain ext4, with just noatime/nodiratime).
To be precise, this is the version installed: https://launchpad.net/~costamagnagianfranco/+archive/ubuntu/borgbackup/+sourcepub/11995318/+listing-archive-extra
Calling acl_to_text_np faster?
diff --git a/src/borg/platform/linux.pyx b/src/borg/platform/linux.pyx
index b4991c51..8b8fdaef 100644
--- a/src/borg/platform/linux.pyx
+++ b/src/borg/platform/linux.pyx
@@ -50,6 +50,7 @@ cdef extern from "sys/acl.h":
int acl_set_fd(int fd, acl_t acl)
acl_t acl_from_text(const char *buf)
char *acl_to_text(acl_t acl, ssize_t *len)
+ char *acl_to_text_np(acl_t acl, ssize_t *len_p, int flags)
cdef extern from "acl/libacl.h":
int acl_extended_file(const char *path)
@@ -232,6 +233,7 @@ def acl_get(path, item, st, numeric_owner=False, fd=None):
cdef acl_t access_acl = NULL
cdef char *default_text = NULL
cdef char *access_text = NULL
+ cdef int acl_to_text_np_flags = 0
if stat.S_ISLNK(st.st_mode):
# symlinks can not have ACLs
@@ -246,6 +248,8 @@ def acl_get(path, item, st, numeric_owner=False, fd=None):
converter = acl_numeric_ids
else:
converter = acl_append_numeric_ids
+ # ACL_TEXT_NUMERIC_IDS
+ acl_to_text_np_flags = 2
try:
if fd is not None:
access_acl = acl_get_fd(fd)
@@ -255,11 +259,11 @@ def acl_get(path, item, st, numeric_owner=False, fd=None):
# only directories can have a default ACL. there is no fd-based api to get it.
default_acl = acl_get_file(path, ACL_TYPE_DEFAULT)
if access_acl:
- access_text = acl_to_text(access_acl, NULL)
+ access_text = acl_to_text_np(access_acl, NULL, acl_to_text_np_flags)
if access_text:
item['acl_access'] = converter(access_text)
if default_acl:
- default_text = acl_to_text(default_acl, NULL)
+ default_text = acl_to_text_np(default_acl, NULL, acl_to_text_np_flags)
if default_text:
item['acl_default'] = converter(default_text)
finally:
@biji good idea!
Guess the libacl code will internally do id -> name lookups if we do not explicitly request ACL_TEXT_NUMERIC_IDS (and as it seems from this ticket, it does no caching, but does a lot of lookups). There is also another acl_to_any_text call, not sure about the pros and cons.
Guess that fixing this will need looking at the converter code also and at the unit tests (we need to make very sure this does what it should do). Also, this code might be platform dependent, so we might need different code for linux, bsd, macOS, etc.
Until there is a better solution with improved ACL code, I will offer a workaround via #3955.
So, if backup/restore of ACLs is not really required, one will be able to work around this speed issue by using borg create --noacls ....
Until a better solution is available, one can use --noacls (1.1-maint and master branch), PRs #5701 #5702.
I updated the issue topic as this is likely a more general issue.
It was discovered in winbind/nss context as there is much more slowness involved due to network delays, but it likely is also not very efficient for local lookups.
Guess we could try to fix this in 2 ways:
- when running with
--numeric-owner, do not lookup user/group names - otherwise, try to work with our own LRU-cached lookup code rather than trigger uncached syscalls for lookups inside libacl.
Using --numeric-owner might cause issue when restoring to other system which have different id mapping, for example Samba PDC dan its BDC
Sure, stuff like --numeric-owner or --noacls is only for "if you know what you are doing". :-)
@ThomasWaldmann thank you for your work! Is there a way to release this as a patch version (e.g. v1.15.1) to have an offical compiled binary?
https://github.com/borgbackup/borg/pull/5718/files I will release 1.1.16 soon, including the --noacl workaround for people who do not need to backup ACLs.
Other than that, there is no real, finished fix for this issue yet.
The patch from @biji needs more work, review and testing. If new mechanisms are introduced, might also need more work and testing for other platforms than Linux (mainly freebsd and macOS iirc) as that code is platform-specific.
https://github.com/borgbackup/borg/releases/tag/1.1.16 borg 1.1.16 released with the --noacls workaround (IF you do not need to backup ACLs)