Archive transfers taking too long

[gfr10598]

The daily archive transfers have been taking hours to run, such that the second transfer to archive-measurement-lab only has a fraction of the day's data.

[gfr10598]

#27 adds more transfers, and adds a 5 day max file age. The max file age is not applied to the final transfer, though, because of a code bug.

It also appears that the "computing" phase of the transfer is repeated once the early files have been moved. This means that the transfer job is chasing the incoming files from pusher, which is extending the duration of the job.

[gfr10598]

With transfers every six hours, and 5 day max file age, we are still seeing roughly 2.5 to 3 hour transfer times. The tail chasing behavior seems to be a major part of this, though.

[gfr10598]

After #29, the transfers are now every 6 hours, and most have maxFileAge of 12h.

The fact that pusher streams continuously means that the pusher->archive job spends a lot of time rechecking for more files. The file mtimes in archive-mlab-oti are a little surprising though. For the 0230Z transfer, console says that the job is scheduled at 10:30pm, and completes at 1:00:30. But the mtimes of the last block of files in archive-mlab-oti are all in the range 03:56:01Z to 03:56:05Z. The last file name is 20200711T034624, indicating it was transferred by pusher about 10 minutes before it was transferred by the transfer job. This corresponds to the 10 minute minFileAge parameter. The mtime on the file in pusher-mlab-oti is also 03:46:24, identical to the name provided by pusher. Generally the pusher mtime is within one or two seconds of the pusher filename.

The pusher mtimes of the files in this range are:
2020-07-11T03:05:31Z
2020-07-11T03:05:55Z
2020-07-11T03:11:00Z
2020-07-11T03:15:38Z
2020-07-11T03:19:25Z
2020-07-11T03:22:54Z
2020-07-11T03:25:33Z
2020-07-11T03:30:04Z
2020-07-11T03:37:50Z
2020-07-11T03:39:20Z
2020-07-11T03:44:51Z
2020-07-11T03:46:24Z
2020-07-11T04:04:05Z * not transferred
2020-07-11T04:04:49Z * not transferred
2020-07-11T04:09:15Z * not transferred
2020-07-11T04:15:13Z * not transferred
2020-07-11T04:19:36Z * not transferred

This strongly suggests that the computing phase of the transfer continues until there is last observed files is older than minFileAge, and then the transfer triggers. So we might want to try a shorter minFileAge, perhaps 1 minute, which might allow the transfer to begin and end earlier.

It also appears that the files all appear in the destination bucket a nearly identical time - within a few seconds of each other. HOWEVER the job completion time seems to be much later - 1:00:03 eastern time, which is 5:00:03Z, which is more than 1 hour after the last destination mtime. This seems very odd.

[gfr10598]

The 1430 transfer is currently running, and says 100%.
The last completed transfer would be the 0830 transfer, and the last visible file for 7/11 is consistent with that:

33688 2020-07-11T10:11:44Z gs://archive-mlab-oti/ndt/ndt5/2020/07/11/20200711T081957.448505Z-ndt5-mlab1-lax04-ndt.tgz

So, the 100% indicator in the transfer job status apparently means that it has scanned 100% of the files, but has apparently not moved (or at least made visible) any of the files.

The status looks like:
Jul 11, 2020, 10:30:00 AM
Transfer operation details
Status
In progress (100%)
Files 35495 of 35495
Bytes 3.41 GB of 3.41 GB
Completed date
Transfer files with prefix
host
ndt
neubot
utilization
wehe
Exclude files with prefix
Synchronization method
—
Time-based filtering
Maximum age 7 days
Minimum age 10 minutes

[laiyi-ohlsen]

Closing per @gfr10598