Swift sync --checksum calls HEAD on every object so is very slow

mcv21 · April 21, 2022, 10:51am

What is the problem you are having with rclone?

I want to use rclone sync to keep two large swift containers up to date; I want sync --checksum to use the container listing, rather than doing a HEAD on every object in the container. Despite the container listing containing correct 'hash' info, rclone is still doing a HEAD every time, which is slow.

Run the command 'rclone version' and share the full output of the command.

mvernon@ms-fe1012:~$ ./rclone version
rclone v1.58.0
- os/version: debian 11.3 (64 bit)
- os/kernel: 5.10.0-13-amd64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.17.8
- go/linking: static
- go/tags: none

Which cloud storage system are you using? (eg Google Drive)

Openstack Swift (self-hosted)

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

./rclone sync --checksum --dry-run eqiad:wikipedia-testcommons-local-public codfw:wikipedia-testcommons-local-public --include '0/01/3a1e15ca-ee52-118e-65dc-705273b6c7af.jpg' -vv --dump requests,responses --log-file=rclone-sync.log

The rclone config contents with secrets removed.

[eqiad]
type = swift
env_auth = false
user = REDACTED
key = SECRET
auth = http://ms-fe.svc.eqiad.wmnet/auth/v1.0

[codfw]
type = swift
env_auth = false
user = REDACTED
key = SECRET
auth = https://ms-fe.svc.codfw.wmnet/auth/v1.0

A log from the command with the `-vv` flag

Here are the key highlights (the whole lot is a bit large to paste here), showing rclone getting a listing from the remotes, that listing containing the md5 hash, and then rclone still calling HEAD...

2022/04/21 10:33:54 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/04/21 10:33:54 DEBUG : HTTP REQUEST (req 0xc000efe200)
2022/04/21 10:33:54 DEBUG : GET /v1/AUTH_mw/wikipedia-testcommons-local-public?delimiter=%2F&format=json&limit=1000&prefix=0%2F01%2F HTTP/1.1
Host: ms-fe.svc.codfw.wmnet
User-Agent: rclone/v1.58.0
Transfer-Encoding: chunked
X-Auth-Token: XXXX
Accept-Encoding: gzip

0

2022/04/21 10:33:54 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/04/21 10:33:54 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/04/21 10:33:54 DEBUG : HTTP REQUEST (req 0xc00013f100)
2022/04/21 10:33:54 DEBUG : GET /v1/AUTH_mw/wikipedia-testcommons-local-public?delimiter=%2F&format=json&limit=1000&prefix=0%2F01%2F HTTP/1.1
Host: ms-fe.svc.eqiad.wmnet
User-Agent: rclone/v1.58.0
Transfer-Encoding: chunked
X-Auth-Token: XXXX
Accept-Encoding: gzip

0

2022/04/21 10:33:54 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/04/21 10:33:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/04/21 10:33:54 DEBUG : HTTP RESPONSE (req 0xc00013f100)
2022/04/21 10:33:54 DEBUG : HTTP/1.1 200 OK
Content-Length: 198
Accept-Ranges: bytes
Content-Type: application/json; charset=utf-8
Date: Thu, 21 Apr 2022 10:33:54 GMT
Last-Modified: Sat, 18 Apr 2020 00:10:57 GMT
X-Container-Bytes-Used: 1141507372
X-Container-Object-Count: 474
X-Container-Read: mw:thumbor,mw:media,.r:*
X-Container-Write: mw:thumbor,mw:media
X-Openstack-Request-Id: tx4286998d61c24aa6997dd-0062613312
X-Storage-Policy: standard
X-Timestamp: 1546886239.26298
X-Trans-Id: tx4286998d61c24aa6997dd-0062613312

[{"hash": "7461d99daf3f1e0742401ff05ed0fe0b", "last_modified": "2022-01-25T20:55:48.225080", "bytes": 1000578, "name": "0/01/3a1e15ca-ee52-118e-65dc-705273b6c7af.jpg", "content_type": "image/jpeg"}]
2022/04/21 10:33:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/04/21 10:33:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/04/21 10:33:54 DEBUG : HTTP RESPONSE (req 0xc000efe200)
2022/04/21 10:33:54 DEBUG : HTTP/1.1 200 OK
Content-Length: 198
Accept-Ranges: bytes
Content-Type: application/json; charset=utf-8
Date: Thu, 21 Apr 2022 10:33:54 GMT
Last-Modified: Sat, 18 Apr 2020 00:10:57 GMT
X-Container-Bytes-Used: 1141507372
X-Container-Object-Count: 474
X-Container-Read: mw:thumbor,mw:media,.r:*
X-Container-Write: mw:thumbor,mw:media
X-Storage-Policy: standard
X-Timestamp: 1546886239.61129
X-Trans-Id: tx663b73681cb748c290101-0062613312

[{"hash": "7461d99daf3f1e0742401ff05ed0fe0b", "last_modified": "2022-01-25T20:55:48.451190", "bytes": 1000578, "name": "0/01/3a1e15ca-ee52-118e-65dc-705273b6c7af.jpg", "content_type": "image/jpeg"}]
2022/04/21 10:33:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/04/21 10:33:54 DEBUG : Swift container wikipedia-testcommons-local-public: Waiting for checks to finish
2022/04/21 10:33:54 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/04/21 10:33:54 DEBUG : HTTP REQUEST (req 0xc000efe400)
2022/04/21 10:33:54 DEBUG : HEAD /v1/AUTH_mw/wikipedia-testcommons-local-public/0/01/3a1e15ca-ee52-118e-65dc-705273b6c7af.jpg HTTP/1.1
Host: ms-fe.svc.eqiad.wmnet
User-Agent: rclone/v1.58.0
Transfer-Encoding: chunked
X-Auth-Token: XXXX

0

2022/04/21 10:33:54 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/04/21 10:33:54 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/04/21 10:33:54 DEBUG : HTTP REQUEST (req 0xc00013fd00)
2022/04/21 10:33:54 DEBUG : HEAD /v1/AUTH_mw/wikipedia-testcommons-local-public/0/01/3a1e15ca-ee52-118e-65dc-705273b6c7af.jpg HTTP/1.1
Host: ms-fe.svc.codfw.wmnet
User-Agent: rclone/v1.58.0
Transfer-Encoding: chunked
X-Auth-Token: XXXX

0

2022/04/21 10:33:54 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/04/21 10:33:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/04/21 10:33:54 DEBUG : HTTP RESPONSE (req 0xc000efe400)
2022/04/21 10:33:54 DEBUG : HTTP/1.1 200 OK
Content-Length: 1000578
Accept-Ranges: bytes
Content-Type: image/jpeg
Date: Thu, 21 Apr 2022 10:33:54 GMT
Etag: 7461d99daf3f1e0742401ff05ed0fe0b
Last-Modified: Tue, 25 Jan 2022 20:55:49 GMT
X-Object-Meta-Sha1base36: kvcbxf34p98aldxygpsnqyusl2b5vbx
X-Openstack-Request-Id: txec2710ac9c0e4e92b6248-0062613312
X-Timestamp: 1643144148.22508
X-Trans-Id: txec2710ac9c0e4e92b6248-0062613312

2022/04/21 10:33:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/04/21 10:33:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/04/21 10:33:54 DEBUG : HTTP RESPONSE (req 0xc00013fd00)
2022/04/21 10:33:54 DEBUG : HTTP/1.1 200 OK
Content-Length: 1000578
Accept-Ranges: bytes
Content-Type: image/jpeg
Date: Thu, 21 Apr 2022 10:33:54 GMT
Etag: 7461d99daf3f1e0742401ff05ed0fe0b
Last-Modified: Tue, 25 Jan 2022 20:55:49 GMT
X-Object-Meta-Sha1base36: kvcbxf34p98aldxygpsnqyusl2b5vbx
X-Timestamp: 1643144148.45119
X-Trans-Id: tx8ce5254bc3d84835a8f13-0062613312

2022/04/21 10:33:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/04/21 10:33:54 DEBUG : 0/01/3a1e15ca-ee52-118e-65dc-705273b6c7af.jpg: md5 = 7461d99daf3f1e0742401ff05ed0fe0b OK
2022/04/21 10:33:54 DEBUG : 0/01/3a1e15ca-ee52-118e-65dc-705273b6c7af.jpg: Size and md5 of src and dst objects identical
2022/04/21 10:33:54 DEBUG : 0/01/3a1e15ca-ee52-118e-65dc-705273b6c7af.jpg: Unchanged skipping

Full log (secrets redacted) is here: ✎ P25943 rclone sync debug output

I think this is rclone ignoring the hash header and so deciding it must HEAD each object for an ETag; but that defeats the point of sync --checksum that I want rclone to just rely on the container listing...

ncw · April 21, 2022, 12:19pm

I think these HEAD request are due to static/dynamic large objects.

Rclone needs to figure out if the object is really a chunked object. In that case the hash in the listing will be the hash of the manifest file so should be returned as an empty string indicating the hash is unknown.

I don't think you can figure out if the object is a chunked object just from the listing

Do you have any chunked objects?

ncw · April 21, 2022, 12:21pm

Here is the code

github.com

rclone/rclone/blob/03715f6c6b0db437fec1e12c82366a4cf39f9891/backend/swift/swift.go#L1067-L1085

      
        
            // Hash returns the Md5sum of an object returning a lowercase hex string
            func (o *Object) Hash(ctx context.Context, t hash.Type) (string, error) {
            	if t != hash.MD5 {
            		return "", hash.ErrUnsupported
            	}
            	isDynamicLargeObject, err := o.isDynamicLargeObject(ctx)
            	if err != nil {
            		return "", err
            	}
            	isStaticLargeObject, err := o.isStaticLargeObject(ctx)
            	if err != nil {
            		return "", err
            	}
            	if isDynamicLargeObject || isStaticLargeObject {
            		fs.Debugf(o, "Returning empty Md5sum for swift large object")
            		return "", nil
            	}
            	return strings.ToLower(o.md5), nil
            }

Unfortunetely those calls to isDynamicLargeObject(ctx) will cause a HEAD request.

mcv21 · April 21, 2022, 1:18pm

Thanks for the quick reply

I suspect we don't have chunked objects (of either type), but I'm not entirely sure (will try and find out).

From a sync point of view, I think the hash of the manifest is sufficient (for both static and dynamic large objects) to answer the "has this changed?" question.

How plausible would it be to have a "skip the large objects check" behaviour here? [I had the terrible idea of a MD5-lazy hash type or similar that would just return o.md5, but I don't know this codebase at all]

My use case is that we have two swift clusters, and in general expect them to be in sync (mediawiki should write to both clusters). We have some ancient home-brew python that does this (and does so just based on container listings) which I would like to replace with rclone; but we have enough objects that I really can't HEAD them all. [this cluster doesn't have the S3 interface enabled]

mcv21 · April 21, 2022, 1:58pm

I guess this would have to involve modifying newObjectWithInfo in the swift backend to know what sort of operation was involved, maybe?

[sorry, I've not looked into the rclone code before, and maybe slightly off-beam ideas aren't very useful!]

ncw · April 21, 2022, 2:05pm

It would be relatively easy to add a new flag - say no_large_files which would turn off all support for either static or dynamic large files. This would mean that you would be limited to files of 5GiB or less. However it would stop rclone doing all those annoying HEAD requests. (rclone also has to do HEAD requests on 0 length files in the listings to determine if they are large objects or not, to show the correct size).

If you do have large files with this flag then the hashes will be wrong, and the copies will fail because the lengths are wrong too.

TBH if we had that option then I'd use it on all my swift remotes as large file handling in swift is a minefield!

If you wanted to try an experiment you could try commenting these lines of code out

github.com

rclone/rclone/blob/03715f6c6b0db437fec1e12c82366a4cf39f9891/backend/swift/swift.go#L1072-L1079

      
        
            	isDynamicLargeObject, err := o.isDynamicLargeObject(ctx)
            	if err != nil {
            		return "", err
            	}
            	isStaticLargeObject, err := o.isStaticLargeObject(ctx)
            	if err != nil {
            		return "", err
            	}

And I think rclone will do what you want.

mcv21 · April 21, 2022, 3:18pm

That does (at least per --dry-run) look to be doing what I want, and just checking the container listing. So thank you

From a deployment point of view, it would be nice if this could be done properly - does the Hash function get enough state to know what it's being called for? e.g. so it could either do something different when asked to copy (or even just bail out)? Otherwise, as you say, I think this would work (presumably with an option that gets passed into ctx eventually) except in the case where a large object was out of sync (when it would, as you say, do something strange).

ncw · April 21, 2022, 4:35pm

Great!

My preferred way of doing this sort of thing is to add a backend flag.

We could add a very specific one no_head_hash which disabled head requests for that function only.

Or we could add a more general one like no_large_files like I discussed above.

I thought of a possible workaround also... Dynamic Large files always appear with size 0 in the listings, so rclone has to HEAD them to discover if they are really a 0 sized file or not. Rclone could record whether it has done this or not as a isDynamicLargeFile flag and then it wouldn't need to HEAD the object in the Hash method.

However I'm not sure how static large files appear in the directory listings - whether they appear as 0 length or not. If they do appear as 0 length then this workaround will work.

Do you have the ability to create dynamic / static large objects and check how they appear? You can use rclone ls -vv --dump bodies to see what the swift server actually returns.

mcv21 · April 21, 2022, 5:20pm

I tried a larger test, but RAM usage got to over 30G and the OOM-killer came calling...

./rclone sync --checkers=64 --transfers=64 --exclude-from rclone_exclude --no-update-modtime --use-mmap --dry-run --checksum -v -P eqiad: codfw:
#...
Transferred:       30.579 GiB / 30.579 GiB, 100%, 10.030 KiB/s, ETA 0s
Checks:         111330306 / 111330306, 100%
Transferred:       218059 / 218069, 100%
Elapsed time:   1h44m25.0s

Is that expected? Top was saying

1421296 mvernon   20   0   30.8g  28.5g   8624 S 356.8  92.0 288:48.34 rclone

Not long before OOM. [if it would be useful to put the memory-use in a separate ticket, I can do so]

ncw · April 21, 2022, 6:45pm

Hmm! Unusual, especially for a dry-run

Do you have folders with millions of entries in a single folder? If so then it is expected, otherwise probably not.

Rclone is relatively easy to profile in terms of memory use if you run with --rc: debugging memory use if you want to investigate further.

mcv21 · April 21, 2022, 9:20pm

A grep of my swift logs suggests the container it was working on at the time of the OOM was wikipedia-commons-local-thumb.81, which is about 7M entries:

mvernon@ms-fe1012:~$ rclone ls eqiad:wikipedia-commons-local-thumb.81 | wc -l
7088074

ncw · April 22, 2022, 8:27am

Ok that explains it!

In order to do a sync between two directories rclone currently loads them both into RAM as it can't trust the order of items that the backend delivers them.

Rclone might use ~1k of RAM per object and given that you have a source and a destination 30G of memory doesn't sound completely out of order!

Remember also that since you've set --checkers=64 rclone can be doing up to 64 of these super large directories at once. If you try lowering that number, rclone will use less memory.

This particular problem is talked about in various issues, for example: New listing interface for backends `ListP` paged listing · Issue #4788 · rclone/rclone · GitHub - I'd like to add this to rclone at some point which would fix your problem - maybe you'd like to sponsor the feature?

There are several practical things that can be done to improve things in the mean time. One is to try setting GOGC=20 as outlined here. That trades CPU time for memory and will make a difference.

Lowering --checkers will help if there is more than one directory with a huge number of files.

Its also possible to use rclone plus some unix tools, for example (choose a separator which doesn't appear in the files - it can be multiple characters). This lists the path, md5 sum and size of every file.

rclone lsf -R --hash MD5 --format phs --files-only --separator "|"  src: | sort > src-files
rclone lsf -R --hash MD5 --format phs --files-only --separator "|" dst: | sort > dst-files

Then you can do this to discover the files which need transferring to the dst and deleting from the dst

comm -23 src-files dst-files | cut -d "|" -f 1 > need-transfer
comm -13 src-files dst-files | cut -d "|" -f 1  > need-delete

You can then feed the need-transfer into rclone copy and the need delete into rclone delete.

Or maybe just find the changed files

comm -3 src-files dst-files | cut -d "|" -f 1 | uniq > changed

Then feeding changed into rclone sync --files-from changed src: dst: might be the best way.

system · May 22, 2022, 8:28am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

ncw · October 5, 2022, 4:51pm

I had a go at implementing --swift-no-large-objects - please have a go and see if it fixes your problem.

v1.60.0-beta.6475.64d4bb513.fix-swift-no-large-objects on branch fix-swift-no-large-objects (uploaded in 15-30 mins)

--swift-no-large-objects

Disable support for static and dynamic large objects

Swift cannot transparently store files bigger than 5 GiB. There are
two schemes for doing that, static or dynamic large objects, and the
API does not allow rclone to determine whether a file is a static or
dynamic large object without doing a HEAD on the object. Since these
need to be treated differently, this means rclone has to issue HEAD
requests for objects for example when reading checksums.

When no_large_objects is set, rclone will assume that there are no
static or dynamic large objects stored. This means it can stop doing
the extra HEAD calls which in turn increases performance greatly
especially when doing a swift to swift transfer with --checksum set.

Setting this option implies no_chunk and also that no files will be
uploaded in chunks, so files bigger than 5 GiB will just fail on
upload.

If you set this option and there are static or dynamic large objects,
then this will give incorrect hashes for them. Downloads will succeed,
but other operations such as Remove and Copy will fail.

Properties:

Config: no_large_objects
Env Var: RCLONE_SWIFT_NO_LARGE_OBJECTS
Type: bool
Default: false

mcv21 · October 12, 2022, 3:37pm

We've (lightly) tested this branch, and it looks good, thank you very much

ncw · October 13, 2022, 10:59am

Thanks for testing. I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.60

mcv21 · October 13, 2022, 1:16pm

Great, thanks! Do you have an intended timescale for the v1.60 release, OOI?

ncw · October 14, 2022, 10:20am

Very soon - just collecting the last patches!

system · October 17, 2022, 10:20am

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.