Backup effectively stops after 20-25 GB while trying to backup large files

[blacky14]

• I have searched open and closed issues for duplicates.

---

Environment info

• Duplicati version: 2.0.3.6,2.0.3.5, 2.0.3.2
• Operating system: Debian Linux 8.10 (headless)
• Backend: Backblaze B2 & Wasabi (S3 compatible)

Description

I do have a backup set of ~300 GB within 300.000 files or so, from very small text files to rather large VM images.
Every time I try to backup those files with Duplicati, I run into the same problem: it works fine at my max upload speed (~10 MBps) for some hours, then it drops to very slow speed (~10 KBps) until if finally seems to completely stall.
The point where the backup stops seems to be always at around 18-25 GB (remote backup size) and always during a big file (VM image with some GBs).
I tried various combinations, like

• backend: Backblaze B2 & Wasabi (S3 compatible)
• versions: Duplicati versions 2.0.3.6, 2.0.3.5, 2.0.3.2
• blocksize: 100 KB (default) & 1 MB
• remote volume size: 50 MB (default) & 100 MB

but the result is always basically the same.
At that point I don't see any activity in terms of CPU, network or IO of the Duplicati/mono processes, so it seems to be completely stalling. Also the live profiling log shows the last entries from hours ago (see below).

After some reading through previous issues, forum posts and https://www.duplicati.com/articles/Choosing-Sizes/, I especially hoped that increasing the blocksize would be beneficial for me, but not so far. Also the SQLite database is running on an SSD (2x RAID 1 SSDs actually).

I'm running out of ideas here, so I'd really appreciate any feedback on how I can get this working or do some more analysis.

many thx!

Debug log

This Debug Log is from ~11:00 AM, so some hours no log activity ... at least not shown in the Live Profiling Log UI.

May 5, 2018 7:09 AM: Backend event: Put - Started: duplicati-i48c8bf577b4f4db3813113fb7701e6d9.dindex.zip.aes (55.58 KB)
May 5, 2018 7:09 AM: ExecuteReader: SELECT "A"."Hash", "C"."Hash" FROM (SELECT "BlocklistHash"."BlocksetID", "Block"."Hash", * FROM "BlocklistHash","Block" WHERE "BlocklistHash"."Hash" = "Block"."Hash" AND "Block"."VolumeID" = ?) A, "BlocksetEntry" B, "Block" C WHERE "B"."BlocksetID" = "A"."BlocksetID" AND "B"."Index" >= ("A"."Index" * 32768) AND "B"."Index" < (("A"."Index" + 1) * 32768) AND "C"."ID" = "B"."BlockID" ORDER BY "A"."BlocksetID", "B"."Index" took 0:00:00:08.109
May 5, 2018 7:09 AM: Starting - ExecuteReader: SELECT "A"."Hash", "C"."Hash" FROM (SELECT "BlocklistHash"."BlocksetID", "Block"."Hash", * FROM "BlocklistHash","Block" WHERE "BlocklistHash"."Hash" = "Block"."Hash" AND "Block"."VolumeID" = ?) A, "BlocksetEntry" B, "Block" C WHERE "B"."BlocksetID" = "A"."BlocksetID" AND "B"."Index" >= ("A"."Index" * 32768) AND "B"."Index" < (("A"."Index" + 1) * 32768) AND "C"."ID" = "B"."BlockID" ORDER BY "A"."BlocksetID", "B"."Index"
May 5, 2018 7:09 AM: ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = ? took 0:00:00:00.000
May 5, 2018 7:09 AM: Starting - ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = ?
May 5, 2018 7:09 AM: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (?, ?, ?, ?, ?, ?, ?); SELECT last_insert_rowid(); took 0:00:00:00.000
May 5, 2018 7:09 AM: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (?, ?, ?, ?, ?, ?, ?); SELECT last_insert_rowid();
May 5, 2018 7:09 AM: CommitAfterUpload took 0:00:00:00.012
May 5, 2018 7:09 AM: Starting - CommitAfterUpload
May 5, 2018 7:09 AM: Backend event: Put - Completed: duplicati-b5a85fd2fd3d6488dae7fbb4303ca83db.dblock.zip.aes (99.12 MB)
May 5, 2018 7:09 AM: Uploaded 99.12 MB in 00:02:23.7315390, 706.13 KB/s
May 5, 2018 7:07 AM: CommitAddBlockToOutputFlush took 0:00:00:00.313
May 5, 2018 7:07 AM: Starting - CommitAddBlockToOutputFlush
May 5, 2018 7:07 AM: ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid(); took 0:00:00:00.000
May 5, 2018 7:07 AM: Starting - ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid();
May 5, 2018 7:07 AM: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 0:00:00:00.000
May 5, 2018 7:07 AM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
May 5, 2018 7:07 AM: ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid(); took 0:00:00:00.000
May 5, 2018 7:07 AM: Starting - ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid();
May 5, 2018 7:07 AM: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 0:00:00:00.000
May 5, 2018 7:07 AM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
May 5, 2018 7:07 AM: ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid(); took 0:00:00:00.000
May 5, 2018 7:07 AM: Starting - ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid();
May 5, 2018 7:07 AM: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 0:00:00:00.000
May 5, 2018 7:07 AM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
May 5, 2018 7:07 AM: ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid(); took 0:00:00:00.000
May 5, 2018 7:07 AM: Starting - ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid();
May 5, 2018 7:07 AM: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 0:00:00:00.000
May 5, 2018 7:07 AM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
May 5, 2018 7:07 AM: ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid(); took 0:00:00:00.000

[blacky14]

Update:

I stopped and restarted Duplicati, then I had to repair the database, as I got an AggregateException.
However, since I started the backup after that again, it seems like it's picking up and continuing the backup ... now I'm at least at ~36 GB remote backup size and growing.
It's showing "verifying backend data ..." in the UI, but it's definitely uploading backup data.

Still, it's not really increasing my confidence ... so if there's any ideas on why this happens, I'd be happy to hear them.

best regards

[blacky14]

Update #2:

It stopped again 7 hours ago at around ~47 GB at a large file.

[blacky14]

also I should maybe mention that the /var/tmp directory (which I set explicitly via TMPDIR) grew up to ~50 GB in size, which sounds way too much IMHO.

[OronDF343]

I'm having the same issue on Windows 7 x64, 2.0.3.6_canary_2018-04-23.

The issue is caused by the system drive filling up, since Duplicati puts many files in the %LocalAppData%\Temp folder (The AggregateException that I got said it was out of space, and I only had 100MB of free space on drive C). I'm not sure why Duplicati does this, but since I have multiple VM images being backed up (total for VMs 201GB, largest VM 48GB, free space on C: 84.7GB) I guess it doesn't clean up these files during the backup.

[drrlvn]

I'm having this issue as well with 2.0.3.6 (/tmp gets filled up) and it seems like the same problem described at https://forum.duplicati.com/t/backblase-b2-local-tmp-files-fills-up-entire-disk-ramdrive/3477.

[warwickmm]

Closing this as I think it duplicates #2465. If anyone disagrees, we can re-open this if necessary.