So the retry mechanism didn’t kick in. I found out that the shouldRetry function didn’t catch the error (type *net.OpError with Op being “dial”).
Please download the rebuilt 1.2.5 version (fixed by this commit) and try it again.
I’ve also started working on a new GCS storage based on the official Google client library. Normally this is at most one-day work but I’m busy with a big job (multithreaded downloading/uploading for all storages), so it will probably be done by next week.
Thanks a ton! I’ll give it a try.
A week sounds pretty fast to me. The multithreading sounds great too!
Well it’s been running for quite some time now. Looks like it may be working.
I’d say the fix is a success since it ran all night. It does seem like it is going to take quite some time though. (only a few days, so not that bad)
I stopped the process just now. I am going to wait to test the multithreading changes. Speed is an important factor. I need to know that I can throw a fist full of new data at it and not have to worry about my data not being backed up for a week or so while the process runs. I know I could create multiple backup sets, and I used to, but this option doesn’t solve the problem as well as it used to due to personal workflow changes.
Not to sound impatient because I thought your original estimate of the changes was kind of short anyway, but any word on the next release with multithreading and new GCP support? I’m waiting on this before finishing my testing.
I finished the code changes for the multithreading support. Working on tests now and I hope to get the new version ready by the end of next week at the latest. The new GCP backend should also be out about the same time if everything goes as planned.
Version 2.0.0 (CLI only) is now available on the github page. The -threads option is now supported by all storage backends for both the backup and the restore commands.
To use the new GCS backend, set the storage url to gcs://bucket. You will need a token file, which can be downloaded by either authorizing Dupliacy to access your Google Cloud Storage account or by downloading it from your Google service account page.
Please let me know if you find any issues.
I have the token registered. Does this only support the root directory of the bucket? Currently I am in a directory 1 level beyond the root. I tried setting the storage to gcs://duplicacy/myFolderName, but receive the following error.
2017-05-15 12:29:56.333 ERROR STORAGE_CONFIG Failed to download the configuration file from the storage: googleapi: Error 400: Invalid bucket name: ‘duplicacy/aydindirl-dc’, invalid
PS
without the /myFolderName, it of course just says that it has not been initialized.
I redid the 2.0.0 release. It should now accept a storage path after the bucket in the GCS storage url.
Seems to be working. I gave it 8 threads and over 5 TB to run until completion this time.
This warning message is a bit odd, but it didn’t prevent it from running. Almost looks like it tried to scan the .duplicacy directory.
2017-05-16 08:14:53.593 INFO VSS_CREATE Creating a shadow copy for E:
2017-05-16 08:15:03.493 INFO VSS_DONE Shadow copy {15673AD1-7260-48E6-A415-8B782261620C} created
2017-05-16 08:15:03.494 INFO BACKUP_INDEXING Indexing E:
2017-05-16 08:15:03.542 INFO SNAPSHOT_FILTER Loaded 8 include/exclude pattern(s)
2017-05-16 08:19:39.194 INFO LIST_ATTRIBUTES Discarding file attributes
2017-05-16 08:20:53.327 WARN LIST_FAILURE Failed to list subdirectory: open E:/.duplicacy\shadow\/System Volume Information: Access is denied.
Earlier versions of Go have trouble accessing the UNC paths to shadow volumes (such as \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy16) so a symbolic link .duplicacy\shadow has to be created which points to the newly created shadow volume. When it reads E:\/.duplicacy\shadow\/System Volume Information, it is just a shadow copy of E:\System Volume Information.
2017-05-16 18:57:31.352 INFO UPLOAD_PROGRESS Uploaded chunk 301210 size 4778347, 35.97MB/s 1 day 07:37:14 25.1% 2017-05-16 18:57:31.687 INFO UPLOAD_PROGRESS Uploaded chunk 301211 size 2300343, 35.97MB/s 1 day 07:37:14 25.1% 2017-05-16 18:57:32.906 INFO UPLOAD_PROGRESS Uploaded chunk 301212 size 6354316, 35.97MB/s 1 day 07:37:16 25.1% 2017-05-16 18:57:33.345 INFO UPLOAD_PROGRESS Uploaded chunk 301213 size 4656704, 35.97MB/s 1 day 07:37:19 25.1% 2017-05-16 18:57:33.707 INFO UPLOAD_PROGRESS Uploaded chunk 301214 size 2680479, 35.97MB/s 1 day 07:37:19 25.1% 2017-05-16 18:57:34.101 INFO UPLOAD_PROGRESS Uploaded chunk 301215 size 6142834, 35.97MB/s 1 day 07:37:21 25.1% 2017-05-16 18:57:34.979 INFO UPLOAD_PROGRESS Uploaded chunk 301216 size 11652732, 35.97MB/s 1 day 07:37:20 25.1% 2017-05-16 18:57:35.811 INFO UPLOAD_PROGRESS Uploaded chunk 301217 size 10109932, 35.97MB/s 1 day 07:37:22 25.1% 2017-05-16 18:57:36.263 INFO UPLOAD_PROGRESS Uploaded chunk 301218 size 4170093, 35.97MB/s 1 day 07:37:24 25.1% 2017-05-16 18:57:37.031 INFO UPLOAD_PROGRESS Uploaded chunk 301219 size 11407268, 35.97MB/s 1 day 07:37:26 25.1% 2017-05-16 18:57:37.451 INFO UPLOAD_PROGRESS Uploaded chunk 301220 size 2712485, 35.97MB/s 1 day 07:37:26 25.1% 2017-05-16 18:57:37.934 INFO UPLOAD_PROGRESS Uploaded chunk 301221 size 4371216, 35.97MB/s 1 day 07:37:25 25.1% 2017-05-16 18:57:38.252 INFO UPLOAD_PROGRESS Uploaded chunk 301222 size 1677083, 35.97MB/s 1 day 07:37:28 25.1% 2017-05-16 18:57:39.348 INFO UPLOAD_PROGRESS Uploaded chunk 301223 size 16777216, 35.97MB/s 1 day 07:37:29 25.1% 2017-05-16 18:57:39.751 INFO UPLOAD_PROGRESS Uploaded chunk 301224 size 4283336, 35.97MB/s 1 day 07:37:29 25.1% 2017-05-16 18:57:40.228 INFO UPLOAD_PROGRESS Uploaded chunk 301225 size 7206354, 35.97MB/s 1 day 07:37:31 25.1% 2017-05-16 18:57:40.579 INFO UPLOAD_PROGRESS Uploaded chunk 301226 size 2676535, 35.97MB/s 1 day 07:37:31 25.1% 2017-05-16 18:57:40.933 INFO UPLOAD_PROGRESS Uploaded chunk 301227 size 2012126, 35.97MB/s 1 day 07:37:31 25.1% 2017-05-16 18:57:41.398 INFO UPLOAD_PROGRESS Uploaded chunk 301228 size 2848430, 35.96MB/s 1 day 07:37:33 25.1% 2017-05-16 18:57:41.729 INFO UPLOAD_PROGRESS Uploaded chunk 301229 size 1334207, 35.96MB/s 1 day 07:37:33 25.1% 2017-05-16 18:57:42.003 INFO UPLOAD_PROGRESS Uploaded chunk 301230 size 1925156, 35.96MB/s 1 day 07:37:36 25.1% 2017-05-16 18:57:43.156 INFO UPLOAD_PROGRESS Uploaded chunk 301231 size 11814879, 35.96MB/s 1 day 07:37:38 25.1% 2017-05-16 18:57:43.719 INFO UPLOAD_PROGRESS Uploaded chunk 301232 size 3451290, 35.96MB/s 1 day 07:37:37 25.1% 2017-05-16 18:57:44.477 INFO UPLOAD_PROGRESS Uploaded chunk 301233 size 9205176, 35.96MB/s 1 day 07:37:39 25.1% 2017-05-16 18:57:44.832 INFO UPLOAD_PROGRESS Uploaded chunk 301234 size 1699071, 35.96MB/s 1 day 07:37:39 25.1% 2017-05-16 18:57:45.168 INFO UPLOAD_PROGRESS Uploaded chunk 301235 size 1564499, 35.96MB/s 1 day 07:37:42 25.1% 2017-05-16 18:57:45.964 INFO UPLOAD_PROGRESS Uploaded chunk 301236 size 9931223, 35.96MB/s 1 day 07:37:41 25.1% 2017-05-16 18:57:46.275 INFO UPLOAD_PROGRESS Uploaded chunk 301237 size 1266517, 35.96MB/s 1 day 07:37:44 25.1% 2017-05-16 18:57:47.102 INFO UPLOAD_PROGRESS Uploaded chunk 301238 size 14956466, 35.96MB/s 1 day 07:37:45 25.1% 2017-05-16 18:57:47.524 INFO UPLOAD_PROGRESS Uploaded chunk 301239 size 5600455, 35.96MB/s 1 day 07:37:44 25.1% 2017-05-16 18:57:48.651 INFO UPLOAD_PROGRESS Uploaded chunk 301240 size 16777216, 35.96MB/s 1 day 07:37:46 25.1% 2017-05-16 18:57:49.250 INFO UPLOAD_PROGRESS Uploaded chunk 301241 size 8099832, 35.96MB/s 1 day 07:37:48 25.1% 2017-05-16 18:57:49.556 INFO UPLOAD_PROGRESS Uploaded chunk 301242 size 1375306, 35.96MB/s 1 day 07:37:48 25.1% 2017-05-16 18:57:49.895 INFO UPLOAD_PROGRESS Uploaded chunk 301243 size 2291442, 35.96MB/s 1 day 07:37:47 25.1% 2017-05-16 18:57:50.226 INFO UPLOAD_PROGRESS Uploaded chunk 301244 size 2074003, 35.96MB/s 1 day 07:37:50 25.1% 2017-05-16 18:57:50.699 INFO UPLOAD_PROGRESS Uploaded chunk 301245 size 6310147, 35.96MB/s 1 day 07:37:49 25.1% 2017-05-16 18:57:51.128 INFO UPLOAD_PROGRESS Uploaded chunk 301246 size 6102071, 35.96MB/s 1 day 07:37:52 25.1% 2017-05-16 18:57:51.545 INFO UPLOAD_PROGRESS Uploaded chunk 301247 size 3112765, 35.96MB/s 1 day 07:37:52 25.1% 2017-05-16 18:57:51.860 INFO UPLOAD_PROGRESS Uploaded chunk 301248 size 2296881, 35.96MB/s 1 day 07:37:51 25.1% 2017-05-16 18:57:52.269 INFO UPLOAD_PROGRESS Uploaded chunk 301249 size 2276301, 35.96MB/s 1 day 07:37:54 25.1% 2017-05-16 18:57:52.693 INFO UPLOAD_PROGRESS Uploaded chunk 301250 size 5147593, 35.96MB/s 1 day 07:37:53 25.1% 2017-05-16 18:57:53.049 INFO UPLOAD_PROGRESS Uploaded chunk 301251 size 3391892, 35.96MB/s 1 day 07:37:56 25.1% 2017-05-16 18:57:53.919 INFO UPLOAD_PROGRESS Uploaded chunk 301252 size 14985564, 35.96MB/s 1 day 07:37:54 25.1% 2017-05-16 18:57:54.371 INFO UPLOAD_PROGRESS Uploaded chunk 301253 size 3663569, 35.96MB/s 1 day 07:37:57 25.1% 2017-05-16 18:57:54.660 INFO UPLOAD_PROGRESS Uploaded chunk 301254 size 1231399, 35.96MB/s 1 day 07:37:57 25.1% 2017-05-16 18:57:55.354 INFO UPLOAD_PROGRESS Uploaded chunk 301255 size 8671454, 35.96MB/s 1 day 07:37:59 25.1% 2017-05-16 18:57:55.700 INFO UPLOAD_PROGRESS Uploaded chunk 301256 size 2874809, 35.96MB/s 1 day 07:37:59 25.1% 2017-05-16 18:57:56.028 INFO UPLOAD_PROGRESS Uploaded chunk 301257 size 1678656, 35.95MB/s 1 day 07:38:02 25.1% 2017-05-16 18:57:56.620 INFO UPLOAD_PROGRESS Uploaded chunk 301258 size 6741827, 35.95MB/s 1 day 07:38:01 25.1% 2017-05-16 18:57:56.917 INFO UPLOAD_PROGRESS Uploaded chunk 301259 size 2216930, 35.95MB/s 1 day 07:38:01 25.1% 2017-05-16 18:57:57.072 ERROR UPLOAD_CHUNK Failed to upload the chunk 3c8bc56bb9bbd558583dc50ff822647beb27107e1e261310ee08d1faec545ea3: googleapi: Error 503: Backend Error, backendError
Ran for about 10 hrs before getting this error (see log above). First uploaded chunk was about 5 hrs before the error, the rest was all skipped.
2017-05-16 13:58:40.095 INFO UPLOAD_PROGRESS Skipped chunk 268774 size 6890693, 59.92MB/s 19:43:18 22.2% 2017-05-16 13:58:40.180 INFO UPLOAD_PROGRESS Skipped chunk 268775 size 4136196, 59.92MB/s 19:43:18 22.2% 2017-05-16 13:58:40.231 INFO UPLOAD_PROGRESS Skipped chunk 268776 size 4459409, 59.92MB/s 19:43:18 22.2% 2017-05-16 13:58:40.432 INFO UPLOAD_PROGRESS Skipped chunk 268777 size 11993642, 59.92MB/s 19:43:17 22.2% 2017-05-16 13:58:40.582 INFO UPLOAD_PROGRESS Skipped chunk 268778 size 9719979, 59.92MB/s 19:43:16 22.2% 2017-05-16 13:58:40.679 INFO UPLOAD_PROGRESS Skipped chunk 268779 size 6204391, 59.92MB/s 19:43:16 22.2% 2017-05-16 13:58:40.731 INFO UPLOAD_PROGRESS Skipped chunk 268780 size 3143608, 59.92MB/s 19:43:16 22.2% 2017-05-16 13:58:40.805 INFO UPLOAD_PROGRESS Skipped chunk 268781 size 5303558, 59.92MB/s 19:43:15 22.2% 2017-05-16 13:58:40.849 INFO UPLOAD_PROGRESS Skipped chunk 268782 size 2129622, 59.92MB/s 19:43:15 22.2% 2017-05-16 13:58:40.891 INFO UPLOAD_PROGRESS Skipped chunk 268783 size 3417456, 59.92MB/s 19:43:15 22.2% 2017-05-16 13:58:40.950 INFO UPLOAD_PROGRESS Skipped chunk 268784 size 7167851, 59.92MB/s 19:43:14 22.2% 2017-05-16 13:58:41.026 INFO UPLOAD_PROGRESS Skipped chunk 268785 size 5628600, 59.92MB/s 19:43:17 22.2% 2017-05-16 13:58:41.152 INFO UPLOAD_PROGRESS Skipped chunk 268786 size 9803939, 59.92MB/s 19:43:17 22.2% 2017-05-16 13:58:41.197 INFO UPLOAD_PROGRESS Skipped chunk 268787 size 1859756, 59.92MB/s 19:43:17 22.2% 2017-05-16 13:58:41.247 INFO UPLOAD_PROGRESS Skipped chunk 268788 size 4054580, 59.92MB/s 19:43:16 22.2% 2017-05-16 13:58:41.356 INFO UPLOAD_PROGRESS Skipped chunk 268789 size 10461919, 59.92MB/s 19:43:16 22.2% 2017-05-16 13:58:41.610 INFO UPLOAD_PROGRESS Skipped chunk 268790 size 9315676, 59.92MB/s 19:43:15 22.2% 2017-05-16 13:58:41.703 INFO UPLOAD_PROGRESS Skipped chunk 268791 size 7178719, 59.92MB/s 19:43:14 22.2% 2017-05-16 13:58:41.750 INFO UPLOAD_PROGRESS Skipped chunk 268792 size 2199389, 59.92MB/s 19:43:14 22.2% 2017-05-16 13:58:41.803 INFO UPLOAD_PROGRESS Skipped chunk 268793 size 2164017, 59.92MB/s 19:43:14 22.2% 2017-05-16 13:58:41.847 INFO UPLOAD_PROGRESS Skipped chunk 268794 size 5326768, 59.92MB/s 19:43:14 22.2% 2017-05-16 13:58:42.405 INFO UPLOAD_PROGRESS Uploaded chunk 268795 size 3133691, 59.92MB/s 19:43:17 22.2% 2017-05-16 13:58:42.980 INFO UPLOAD_PROGRESS Uploaded chunk 268796 size 6482551, 59.92MB/s 19:43:16 22.2% 2017-05-16 13:58:43.388 INFO UPLOAD_PROGRESS Uploaded chunk 268797 size 2773082, 59.92MB/s 19:43:20 22.2% 2017-05-16 13:58:43.751 INFO UPLOAD_PROGRESS Uploaded chunk 268798 size 1462498, 59.92MB/s 19:43:20 22.2% 2017-05-16 13:58:44.112 INFO UPLOAD_PROGRESS Uploaded chunk 268799 size 1810903, 59.92MB/s 19:43:23 22.2% 2017-05-16 13:58:44.627 INFO UPLOAD_PROGRESS Uploaded chunk 268800 size 3987189, 59.92MB/s 19:43:23 22.2% 2017-05-16 13:58:45.239 INFO UPLOAD_PROGRESS Uploaded chunk 268801 size 5770960, 59.91MB/s 19:43:26 22.2% 2017-05-16 13:58:45.729 INFO UPLOAD_PROGRESS Uploaded chunk 268802 size 3485746, 59.91MB/s 19:43:26 22.2%
Although the official GCS client library claims that a retry mechanism is in place for all methods, after some code digging I came to the conclusion that at least the upload method doesn’t support it because of the way the code is written.
I’ll add a retry logic to the outer layer in the GCS storage backend. Should be done by the end of tomorrow.
I thought it was weird when I received the message because I had also read in like one of the first paragraphs of their documentation that all of their requests implement an infinite retry. Thanks for looking into it.
On another note… Unfortunately it’s hard to get a grasp on how fast this application is and how long it has left since I have not gotten it to complete on my larger data set yet.
I did a basic verify and it thinks that I have 200 GB uploaded while GCP reports 1.21 TiB which I’m guessing is because each time it fails and restarts it removes the incomplete snapshot and starts over again, skipping existing chunks with the pre-upload check. This throws off the time estimate quite a bit. It also slows down a retry for such a large dataset quite a bit. I’m having to wait for a lot of skipped chunks before it starts uploading again.
From what I can tell from my smaller backup, it will not take as much time to check every single chunk. In fact, it doesn’t seem to do that at all. Can you confirm this behavior? I’d hate to get all of this uploaded only to find out that each backup takes a couple of days.
Assuming that backups after the initial are faster, is it possible to support partial backups whether due to failure or OS restart or other reasons? I suppose the chunks that were still in progress would have to be re-checked/ uploaded in case they didn’t finish, but it would make this type of situation much faster.
Lastly, with this much data, should I consider changing the chunk size? This may be subject to opinion and situation. I have a mix of many small files as well as some extra large files and every size in between (probably up to ~100 GB for 1 file). I don’t mind starting the upload over if it would be better. I was thinking about doing that anyway to get an idea of how fast the backup is.
If the previous backup successfully finished, Duplicacy will just check the timestamp and size of each file to see if any of them changed from the last backup. It will then run the chunking algorithm on changed files and upload chunks created from these files. This is the default behavior unless the -hash option is specified.
However, if previous backups all failed for some reason, Duplicacy will have to run the chunk algorithm on all files. This is unfortunate as you can see from your tests that a considerable amount of time is spent just to recreate all chunks and then find out they all had already been uploaded. The solution I have in mind is to save the incomplete snapshot locally, which stores the files that have been scanned and uploaded. And then when you specify a -resume option, it will load this incomplete snapshot and only work on files not included or different from those in that snapshot.
I uploaded a new 2.0.0 build that implements the retry logic for uploading chunks. Please give it a try.
It’s running now. It will be about 5 hours again before it starts uploading I’m guessing.
One thing I noticed that is not really a big deal, but may be worth noting in the documentation/ guide what the limitations are (if any):
I upped the thread count from 8 to 12 to try to get passed the skipped chunks part faster and it actually slowed down significantly. I went from 10-20 chunks per second to 1-10. Looking in the task manager, It seemed that only 1 core was being used at a time with 12 threads specified, but when I changed it back to 8, several are being used again.
12 is completely unnecessary and I don’t think I want to use that much processing power anyway, but I thought I’d let you know what I observed.
Did you have any recommendation on chunk size? Should I leave it default? TBH, variable sized chunking is a bit hard to conceptualize how that even works in the deduplication processes.