Please describe what you are doing to trigger the bug:
I have a scheduled command line COPY job which runs on my local Ubuntu 16.04 server right after the daily server backup. Multiple machines are backed up to the Ubuntu server, but the server is the only machine running the COPY command to sync with my offsite server.
Please describe what you expect to happen (but doesn’t):
I expect the COPY process to be completed relatively quickly, in 20-30 minutes tops and with minimal RAM usage.
Please describe what actually happens (the wrong behaviour):
Running v2.7.2, Duplicacy filled my 8GB physical RAM and 8GB swap file, then the process terminated. This seems like a problem with snapshot information being retained in RAM such as reported in Memory consumption grows steadily during most operations.
Workaround:
I set environment variable DUPLICACY_ATTRIBUTE_THRESHOLD to 1, enabled debug & logging, then re-ran the COPY command. It took about 12 hours to run and generated a 37MB log file but finished (barely) without running out of memory. Relevant log contents:
2020-11-25 21:39:48.301 DEBUG DOWNLOAD_FILE_CACHE Loaded file snapshots/fifi/369 from the snapshot cache 2020-11-25 21:39:48.302 DEBUG DOWNLOAD_FILE_CACHE Loaded file snapshots/fifi/370 from the snapshot cache 2020-11-25 21:39:48.303 TRACE SNAPSHOT_LIST_REVISIONS Listing revisions for snapshot benjamin 2020-11-25 21:39:48.305 INFO SNAPSHOT_EXIST Snapshot benjamin at revision 190 already exists at the destination storage 2020-11-25 21:39:48.305 TRACE SNAPSHOT_COPY Copying snapshot frodo at revision 588 2020-11-25 21:39:48.392 DEBUG CHUNK_CACHE Chunk bb95b6c5215535af9e9ad5596b862b459450e30782a6107eb23c61d26f17feac has been loaded from the snapshot cache 2020-11-25 21:39:48.398 DEBUG DOWNLOAD_FETCH Fetching chunk a57218282a6ef865c37d930b37b4dcee67617e0e61fe3c8d2bdd8b1e98a33b4c 2020-11-25 21:39:48.477 DEBUG CHUNK_CACHE Chunk a57218282a6ef865c37d930b37b4dcee67617e0e61fe3c8d2bdd8b1e98a33b4c has been loaded from the snapshot cache <------ continues for ~9 hours -------> 2020-11-26 06:38:31.501 DEBUG DOWNLOAD_FETCH Fetching chunk c4fe7dbf67752d474e5d152e9fa1b51470a4e93c7482a3d2b50fc1610c79579c 2020-11-26 06:38:31.557 DEBUG CHUNK_CACHE Chunk c4fe7dbf67752d474e5d152e9fa1b51470a4e93c7482a3d2b50fc1610c79579c has been loaded from the snapshot cache 2020-11-26 06:42:50.976 TRACE LIST_FILES Listing chunks/ 2020-11-26 06:42:52.331 TRACE LIST_FILES Listing chunks/ff/ 2020-11-26 06:42:59.438 TRACE LIST_FILES Listing chunks/ff/fe/ ... 2020-11-26 07:05:51.009 TRACE LIST_FILES Listing chunks/00/00/ 2020-11-26 07:05:51.524 DEBUG SNAPSHOT_COPY Found 257637 chunks on destination storage 2020-11-26 07:05:53.087 INFO SNAPSHOT_COPY Chunks to copy: 43134, to skip: 240148, total: 283282
Note: The chunk copying operation took about ~40 minutes as compared to 9 hours to download snapshot information.
After the above was complete I re-ran the COPY command with very different results. The log file was only about 4kB and took only 15 minutes to run. Minimal RAM was used. Relevant log contents:
2020-11-26 21:37:13.158 INFO SNAPSHOT_EXIST Snapshot fifi at revision 369 already exists at the destination storage 2020-11-26 21:37:13.158 INFO SNAPSHOT_EXIST Snapshot fifi at revision 370 already exists at the destination storage 2020-11-26 21:37:13.158 TRACE SNAPSHOT_LIST_REVISIONS Listing revisions for snapshot benjamin 2020-11-26 21:37:13.210 INFO SNAPSHOT_EXIST Snapshot benjamin at revision 190 already exists at the destination storage 2020-11-26 21:37:13.210 TRACE SNAPSHOT_COPY Copying snapshot frodo at revision 1104 2020-11-26 21:37:13.314 DEBUG CHUNK_CACHE Chunk f0d277b361c3abc849a66b0a7875d397cbf4001cc94ae17a1eb6a4362eeba8b3 has been loaded from the snapshot cache 2020-11-26 21:37:13.324 DEBUG DOWNLOAD_FETCH Fetching chunk c2172cbb8e9a3433d76d6f54d4526167cbfaf900d21557100cfa5148d28bab1e 2020-11-26 21:37:13.390 DEBUG CHUNK_CACHE Chunk c2172cbb8e9a3433d76d6f54d4526167cbfaf900d21557100cfa5148d28bab1e has been loaded from the snapshot cache 2020-11-26 21:37:13.404 DEBUG DOWNLOAD_FETCH Fetching chunk 13fa6806234ce40143cb15f84a7aa38229c5966d0aa05647b270ab57520d93c6 2020-11-26 21:37:13.483 DEBUG CHUNK_CACHE Chunk 13fa6806234ce40143cb15f84a7aa38229c5966d0aa05647b270ab57520d93c6 has been loaded from the snapshot cache 2020-11-26 21:37:13.500 DEBUG DOWNLOAD_FETCH Fetching chunk e773da0ee14c47f488d863ecd4904581a3284c29a281629367fe68d3f29b0ae3 2020-11-26 21:37:13.540 DEBUG CHUNK_CACHE Chunk e773da0ee14c47f488d863ecd4904581a3284c29a281629367fe68d3f29b0ae3 has been loaded from the snapshot cache 2020-11-26 21:37:14.172 TRACE SNAPSHOT_COPY Copying snapshot alex2 at revision 598 2020-11-26 21:37:14.172 DEBUG DOWNLOAD_FETCH Fetching chunk 7aeda5fafd6f76a8220ac1e7aad759233fc0ae8501a0c7af20e4931424ea7910 2020-11-26 21:37:14.633 DEBUG CHUNK_DOWNLOAD Chunk 7aeda5fafd6f76a8220ac1e7aad759233fc0ae8501a0c7af20e4931424ea7910 has been downloaded 2020-11-26 21:37:14.655 TRACE SNAPSHOT_COPY Copying snapshot scott2 at revision 88 2020-11-26 21:37:14.655 DEBUG DOWNLOAD_FETCH Fetching chunk e9b294525de6a3afb2ecfb37d601638edab424b5bd2e633028d0acde0bf73485 2020-11-26 21:37:15.023 DEBUG CHUNK_DOWNLOAD Chunk e9b294525de6a3afb2ecfb37d601638edab424b5bd2e633028d0acde0bf73485 has been downloaded 2020-11-26 21:37:15.085 TRACE LIST_FILES Listing chunks/ 2020-11-26 21:37:16.243 TRACE LIST_FILES Listing chunks/ff/ 2020-11-26 21:37:56.645 TRACE LIST_FILES Listing chunks/ff/ff/ ... 2020-11-26 21:52:23.171 TRACE LIST_FILES Listing chunks/00/00/ 2020-11-26 21:52:23.428 DEBUG SNAPSHOT_COPY Found 300771 chunks on destination storage 2020-11-26 21:52:23.854 INFO SNAPSHOT_COPY Chunks to copy: 11, to skip: 237850, total: 237861
Hypothesis:
If the COPY process is interrupted it triggers download of all the remote snapshot information next time COPY runs, and all the snapshot information is retained in RAM. Note the interrupted copy state mentioned in this hypothesis was induced while running version 2.1.2. I updated to current as the first step in troubleshooting and prior to running the two sequences above.