GoogleCloudPlatform / GoogleCloudPlatform/gsutil

Slow listing of destination bucket in AWS S3

Open
#1,248 5 comments 0 reactions 0 assignees View on GitHub
Dominant language
Python
Stars
918
Forks
335
PR merge metrics
No merged PRs in 30d

Description

I transferred 4.7 million files (about 2Tb in size in total) from a GCS bucket to an S3 bucket.

```
gsutil -m rsync -r -DD -J gs:// s3://
```

Then I ran the exact same command again to see how long it would take to sync diffs.

It took about 4 hours to list 700,000 files in the destination bucket.

The logs I am seeing look like this:

```
At destination listing 970000...
At destination listing 980000...
At destination listing 990000...
At destination listing 1000000...
```

From the code, it looks like all that is being done here is iterating over the contents of the destination bucket and checking properties of the objects inside. https://github.com/GoogleCloudPlatform/gsutil/blob/master/gslib/commands/rsync.py#L763

Listing the source bucket was quite quick, but listing the destination bucket is too slow for my purposes.

I was not running into any throttling issues on the AWS side, and when running `aws s3 ls s3://
ubuntu 3491288 3491279 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/bin/bootstrapping/gsutil.py -m rsync -r -J gs:// s3://
ubuntu 3491291 3491288 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491293 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491295 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491419 3491291 57 23:04 pts/3 00:09:52 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491420 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491422 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491426 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491431 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491436 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491439 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491446 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491449 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491453 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491457 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
ubuntu 3491462 3491291 0 23:04 pts/3 00:00:00 | \_ python3 /home/ubuntu/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id= -o Credentials:use_client_certificate=False -m rsync -r -J gs:// s3://
```

(The PID is such a high number because the command is being run in a screen session).

When running `strace` on some of the pids, I don't have the ability to follow up.

Some of the child processes appear to be timing out on network calls repeatedly:

```
futex(0x2ac1390, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1618874669, tv_nsec=401310000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
```

Another process is stuck on a read call:

```
read(6,
```

This child process seems to be the most interesting, as using `lsof` I can see that it has TCP connections from the EC2 instance to both AWS S3 (ESTABLISHED) and with GCP GCS (CLOSE_WAIT).

```
// omitted for brevity
python3 3491419 ubuntu 21u IPv4 169126341 0t0 TCP ip-x-x-x-x.us-west-2.compute.internal:59352->s3-us-west-2-r-w.amazonaws.com:https (ESTABLISHED)
python3 3491419 ubuntu 22w REG 259,1 0 2363 /tmp/gsutil-rsync-dst-7snw22qf
python3 3491419 ubuntu 23u REG 259,1 4962820 14023 /tmp/gsutil-rsync-dst-7snw22qf-000001
python3 3491419 ubuntu 24u unix 0x0000000000000000 0t0 169114737 type=STREAM
python3 3491419 ubuntu 25u IPv4 169102695 0t0 TCP ip-x-x-x-x.us-west-2.compute.internal:40466->sea15s11-in-f176.1e100.net:https (CLOSE_WAIT)
python3 3491419 ubuntu 26u REG 259,1 5143215 18625 /tmp/gsutil-rsync-dst-7snw22qf-000002
python3 3491419 ubuntu 28u IPv4 169114065 0t0 TCP ip-x-x-x-x.us-west-2.compute.internal:42018->sea09s29-in-f10.1e100.net:https (CLOSE_WAIT)
python3 3491419 ubuntu 120u REG 259,1 5153606 18816 /tmp/gsutil-rsync-dst-7snw22qf-000000
```

What this suggests to me is that the process has finished interacting with the GCS bucket (for now!), and is only interacting with the S3 bucket. This makes sense given that the only output I see from the command is `At destination listing x...`

I have been notified by AWS support that I am not approaching any rate limits for S3, and the point at which this code is being slow for me is after it has stopped interacting with GCS.

Does anyone have an idea of why this is so slow? If the virtual machine was running out of resources that would be one thing, but it appears to just not be doing much at all when inspecting it on the command line.

Contributor guide

Open the contributing guide

Research direction

Start at gslib/commands/rsync.py around line 763 and reproduce the destination listing with the reported gsutil -m rsync command, comparing it with aws s3 ls. Use the listed strace and process observations to isolate the slowdown; done means identifying the cause and establishing that destination listing no longer takes disproportionately longer.

Written by the indexing model from the issue text.

Assessment

Tech stack
aws, python
Domain
cli, cloud, performance
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.