Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Empty source file can make Recreate download all dblock files fruitlessly with huge delay #3747

Closed
ts678 opened this issue Apr 23, 2019 · 9 comments

Comments

Projects
None yet
3 participants
@ts678
Copy link

commented Apr 23, 2019

  • I have searched open and closed issues for duplicates.

Environment info

  • Duplicati version: 2.0.4.5 beta
  • Operating system: Windows 10
  • Backend: Local folder

Description

This issue is a bug that is part of open Recreating broken DB takes forever [$25] #2889 and Database recreate runs forever #3668 problems. Here, an empty source file leads to Transferring/Reading Entire dblocks instead of dindex for rebuild #1928. There are many forum reports. Topic Recreating database logic/understanding/issue/slow is a good overview and includes much technical analysis and materials. This is much of what I would have put in a GitHub issue if I hadn't been responding to a user post too.

I tested 2.0.4.17 canary first to see if it showed the problem (it did), then went to 2.0.4.5 beta because it's widely used, I know it better and it avoids canary regression questions.

Beyond the initial test described in the forum, I also tried backing up a Linux ISO, recreate, add 1-byte-file, backup, recreate, add 0-byte file, backup, recreate. All downloaded only dindex files until the 0-byte file entered, at which time the recreate downloaded all of the dblock files after downloading the dindex.

From a resource point of view, this is not just wasted downloads, but also wasted potential decryption, unzip, and database operations due the missing block upload, thus the later inability to find its volume.

The countMissingInformation failure to drop to 0, as mentioned in Repair is downloading dblock files (responding to @kenkendk) and the big Recreating database logic/understanding/issue/slow analysis expands to SQL below. Try that on lengthtest - length 1 backup delete repair\bugreport after delete repair\log-database.sqlite in the zip file cited in "Debug log" below, and watch it return 1 due to VolumeID -1. Assembling and pretty-printing SQL suggests why a negative VolumeID upset it.

SELECT 
  COUNT(*) 
FROM 
  (
    SELECT 
      DISTINCT "VolumeID" 
    FROM 
      (
        SELECT 
          "VolumeID" 
        FROM 
          "Block" 
        WHERE 
          "VolumeID" < 0 
        UNION 
        SELECT 
          "VolumeID" 
        FROM 
          "Block", 
          (
            SELECT 
              "BlocklistHash"."Hash" 
            FROM 
              "BlocklistHash" 
              LEFT OUTER JOIN "BlocksetEntry" ON "BlocksetEntry"."Index" = ("BlocklistHash"."Index" * 3200) 
              AND "BlocksetEntry"."BlocksetID" = "BlocklistHash"."BlocksetID" 
            WHERE 
              "BlocksetEntry"."BlocksetID" IS NULL
          ) A 
        WHERE 
          "A"."Hash" = "Block"."Hash"
      )
  )

While I'm wondering if StreamBlockSplitter's block-read loop has a need to use ForceStreamReadAsync() return of 0 as an EOF indicator, my guess is that it could be doing that earlier, where it gets the stream from the channel, but I don't know the core design very well, and I don't know CoCoL very well either...

Regardless, the supplied test, logs, and dumps show an empty file issue, even if my code guess is wrong.

Steps to reproduce

  1. Backup an empty file
  2. Recreate DB while watching live log at Information level or better
  3. ...
  • Actual result:
    After index file downloads, continue and download all dblock files
  • Expected result:
    Only index files should be downloaded

Screenshots

Some DB screenshots are here as an attempted escalation from earlier forum posts which weren't quite as graphic.

Debug log

Some logs and DB bug reports are here along with lots of explanation by me in forum topic Recreating database logic/understanding/issue/slow.

Here is a DB bug report after the length 0 backup (after ISO then length 1) and then the slow recreate:

bugreport after repair of backup 3 of length 0.zip

@warwickmm

This comment has been minimized.

Copy link
Contributor

commented Apr 24, 2019

Thanks @ts678 for the detailed description.

The log from a user also seems to indicate some queries for each dblock download that take longer than I would expect (over 2 minutes in some cases):

Apr 23, 2019 11:51 AM: Starting - ExecuteScalarInt64: SELECT "VolumeID" FROM "Block" WHERE "Hash" = "HkcwyjxO/OhKiNnX3UJzIt/o1QAIWmutLoRH0dgm0gY=" AND "Size" = 102400 
Apr 23, 2019 11:49 AM: Starting - ExecuteNonQuery: INSERT INTO "BlocksetEntry" ("BlocksetID", "Index", "BlockID") SELECT DISTINCT "H"."BlocksetID", "H"."Index", "H"."BlockID" FROM (SELECT "E"."BlocksetID" AS "BlocksetID", "D"."FullIndex" AS "Index", "F"."ID" AS "BlockID" FROM ( SELECT "E"."BlocksetID", "F"."Index" + ("E"."BlocklistIndex" * 3200) AS "FullIndex", "F"."BlockHash", MIN(102400, "E"."Length" - (("F"."Index" + ("E"."BlocklistIndex" * 3200)) * 102400)) AS "BlockSize", "E"."Hash", "E"."BlocklistSize", "E"."BlocklistHash" FROM ( SELECT * FROM ( SELECT "A"."BlocksetID", "A"."Index" AS "BlocklistIndex", MIN(3200 * 32, ((("B"."Length" + 102400 - 1) / 102400) - ("A"."Index" * (3200))) * 32) AS "BlocklistSize", "A"."Hash" AS "BlocklistHash", "B"."Length" FROM "BlocklistHash" A, "Blockset" B WHERE "B"."ID" = "A"."BlocksetID" ) C, "Block" D WHERE "C"."BlocklistHash" = "D"."Hash" AND "C"."BlocklistSize" = "D"."Size" ) E, "TempBlocklist-681BF9E1F669BF4C9D1A03258D28C3F1" F WHERE "F"."BlocklistHash" = "E"."Hash" ORDER BY "E"."BlocksetID", "FullIndex" ) D, "BlocklistHash" E, "Block" F, "Block" G WHERE "D"."BlocksetID" = "E"."BlocksetID" AND "D"."BlocklistHash" = "E"."Hash" AND "D"."BlocklistSize" = "G"."Size" AND "D"."BlocklistHash" = "G"."Hash" AND "D"."Blockhash" = "F"."Hash" AND "D"."BlockSize" = "F"."Size" UNION SELECT "Blockset"."ID" AS "BlocksetID", 0 AS "Index", "Block"."ID" AS "BlockID" FROM "Blockset", "Block", "TempSmalllist-3D9871FF54CA4F4FBE225C5B8D8939FA" S WHERE "Blockset"."Fullhash" = "S"."FileHash" AND "S"."BlockHash" = "Block"."Hash" AND "S"."BlockSize" = "Block"."Size" AND "Blockset"."Length" = "S"."BlockSize" AND "Blockset"."Length" <= 102400 ) H WHERE ("H"."BlocksetID" || ':' || "H"."Index") NOT IN (SELECT ("ExistingBlocksetEntries"."BlocksetID" || ':' || "ExistingBlocksetEntries"."Index") FROM "BlocksetEntry" "ExistingBlocksetEntries" )
Apr 23, 2019 11:49 AM: ExecuteNonQuery: INSERT INTO "Block" ("Hash", "Size", "VolumeID") SELECT "FullHash" AS "Hash", "Length" AS "Size", -1 AS "VolumeID" FROM (SELECT "A"."FullHash", "A"."Length", CASE WHEN "B"."Hash" IS NULL THEN '' ELSE "B"."Hash" END AS "Hash", CASE WHEN "B"."Size" is NULL THEN -1 ELSE "B"."Size" END AS "Size" FROM (SELECT DISTINCT "FullHash", "Length" FROM (SELECT "BlockHash" AS "FullHash", "BlockSize" AS "Length" FROM ( SELECT "E"."BlocksetID", "F"."Index" + ("E"."BlocklistIndex" * 3200) AS "FullIndex", "F"."BlockHash", MIN(102400, "E"."Length" - (("F"."Index" + ("E"."BlocklistIndex" * 3200)) * 102400)) AS "BlockSize", "E"."Hash", "E"."BlocklistSize", "E"."BlocklistHash" FROM ( SELECT * FROM ( SELECT "A"."BlocksetID", "A"."Index" AS "BlocklistIndex", MIN(3200 * 32, ((("B"."Length" + 102400 - 1) / 102400) - ("A"."Index" * (3200))) * 32) AS "BlocklistSize", "A"."Hash" AS "BlocklistHash", "B"."Length" FROM "BlocklistHash" A, "Blockset" B WHERE "B"."ID" = "A"."BlocksetID" ) C, "Block" D WHERE "C"."BlocklistHash" = "D"."Hash" AND "C"."BlocklistSize" = "D"."Size" ) E, "TempBlocklist-681BF9E1F669BF4C9D1A03258D28C3F1" F WHERE "F"."BlocklistHash" = "E"."Hash" ORDER BY "E"."BlocksetID", "FullIndex" ) UNION SELECT "BlockHash", "BlockSize" FROM "TempSmalllist-3D9871FF54CA4F4FBE225C5B8D8939FA" )) A LEFT OUTER JOIN "Block" B ON "B"."Hash" = "A"."FullHash" AND "B"."Size" = "A"."Length" ) WHERE "FullHash" != "Hash" AND "Length" != "Size" took 0:00:02:08.067
...
Apr 23, 2019 11:47 AM: Starting - ExecuteScalarInt64: SELECT "VolumeID" FROM "Block" WHERE "Hash" = "HLzAbC7XLs4VDKoOhhimwWpKeXFOzEuS8meZSnwZ3Ss=" AND "Size" = 102400
Apr 23, 2019 11:45 AM: Starting - ExecuteNonQuery: INSERT INTO "BlocksetEntry" ("BlocksetID", "Index", "BlockID") SELECT DISTINCT "H"."BlocksetID", "H"."Index", "H"."BlockID" FROM (SELECT "E"."BlocksetID" AS "BlocksetID", "D"."FullIndex" AS "Index", "F"."ID" AS "BlockID" FROM ( SELECT "E"."BlocksetID", "F"."Index" + ("E"."BlocklistIndex" * 3200) AS "FullIndex", "F"."BlockHash", MIN(102400, "E"."Length" - (("F"."Index" + ("E"."BlocklistIndex" * 3200)) * 102400)) AS "BlockSize", "E"."Hash", "E"."BlocklistSize", "E"."BlocklistHash" FROM ( SELECT * FROM ( SELECT "A"."BlocksetID", "A"."Index" AS "BlocklistIndex", MIN(3200 * 32, ((("B"."Length" + 102400 - 1) / 102400) - ("A"."Index" * (3200))) * 32) AS "BlocklistSize", "A"."Hash" AS "BlocklistHash", "B"."Length" FROM "BlocklistHash" A, "Blockset" B WHERE "B"."ID" = "A"."BlocksetID" ) C, "Block" D WHERE "C"."BlocklistHash" = "D"."Hash" AND "C"."BlocklistSize" = "D"."Size" ) E, "TempBlocklist-681BF9E1F669BF4C9D1A03258D28C3F1" F WHERE "F"."BlocklistHash" = "E"."Hash" ORDER BY "E"."BlocksetID", "FullIndex" ) D, "BlocklistHash" E, "Block" F, "Block" G WHERE "D"."BlocksetID" = "E"."BlocksetID" AND "D"."BlocklistHash" = "E"."Hash" AND "D"."BlocklistSize" = "G"."Size" AND "D"."BlocklistHash" = "G"."Hash" AND "D"."Blockhash" = "F"."Hash" AND "D"."BlockSize" = "F"."Size" UNION SELECT "Blockset"."ID" AS "BlocksetID", 0 AS "Index", "Block"."ID" AS "BlockID" FROM "Blockset", "Block", "TempSmalllist-3D9871FF54CA4F4FBE225C5B8D8939FA" S WHERE "Blockset"."Fullhash" = "S"."FileHash" AND "S"."BlockHash" = "Block"."Hash" AND "S"."BlockSize" = "Block"."Size" AND "Blockset"."Length" = "S"."BlockSize" AND "Blockset"."Length" <= 102400 ) H WHERE ("H"."BlocksetID" || ':' || "H"."Index") NOT IN (SELECT ("ExistingBlocksetEntries"."BlocksetID" || ':' || "ExistingBlocksetEntries"."Index") FROM "BlocksetEntry" "ExistingBlocksetEntries" )
Apr 23, 2019 11:45 AM: ExecuteNonQuery: INSERT INTO "Block" ("Hash", "Size", "VolumeID") SELECT "FullHash" AS "Hash", "Length" AS "Size", -1 AS "VolumeID" FROM (SELECT "A"."FullHash", "A"."Length", CASE WHEN "B"."Hash" IS NULL THEN '' ELSE "B"."Hash" END AS "Hash", CASE WHEN "B"."Size" is NULL THEN -1 ELSE "B"."Size" END AS "Size" FROM (SELECT DISTINCT "FullHash", "Length" FROM (SELECT "BlockHash" AS "FullHash", "BlockSize" AS "Length" FROM ( SELECT "E"."BlocksetID", "F"."Index" + ("E"."BlocklistIndex" * 3200) AS "FullIndex", "F"."BlockHash", MIN(102400, "E"."Length" - (("F"."Index" + ("E"."BlocklistIndex" * 3200)) * 102400)) AS "BlockSize", "E"."Hash", "E"."BlocklistSize", "E"."BlocklistHash" FROM ( SELECT * FROM ( SELECT "A"."BlocksetID", "A"."Index" AS "BlocklistIndex", MIN(3200 * 32, ((("B"."Length" + 102400 - 1) / 102400) - ("A"."Index" * (3200))) * 32) AS "BlocklistSize", "A"."Hash" AS "BlocklistHash", "B"."Length" FROM "BlocklistHash" A, "Blockset" B WHERE "B"."ID" = "A"."BlocksetID" ) C, "Block" D WHERE "C"."BlocklistHash" = "D"."Hash" AND "C"."BlocklistSize" = "D"."Size" ) E, "TempBlocklist-681BF9E1F669BF4C9D1A03258D28C3F1" F WHERE "F"."BlocklistHash" = "E"."Hash" ORDER BY "E"."BlocksetID", "FullIndex" ) UNION SELECT "BlockHash", "BlockSize" FROM "TempSmalllist-3D9871FF54CA4F4FBE225C5B8D8939FA" )) A LEFT OUTER JOIN "Block" B ON "B"."Hash" = "A"."FullHash" AND "B"."Size" = "A"."Length" ) WHERE "FullHash" != "Hash" AND "Length" != "Size" took 0:00:01:06.377
...
Apr 23, 2019 11:44 AM: ExecuteScalarInt64: SELECT "VolumeID" FROM "Block" WHERE "Hash" = "54RZj9day9f93s0FXFLs+GMrpsSsgzP17fpQM1/zobI=" AND "Size" = 102400 took 0:00:00:00.000
Apr 23, 2019 11:42 AM: Starting - ExecuteNonQuery: INSERT INTO "BlocksetEntry" ("BlocksetID", "Index", "BlockID") SELECT DISTINCT "H"."BlocksetID", "H"."Index", "H"."BlockID" FROM (SELECT "E"."BlocksetID" AS "BlocksetID", "D"."FullIndex" AS "Index", "F"."ID" AS "BlockID" FROM ( SELECT "E"."BlocksetID", "F"."Index" + ("E"."BlocklistIndex" * 3200) AS "FullIndex", "F"."BlockHash", MIN(102400, "E"."Length" - (("F"."Index" + ("E"."BlocklistIndex" * 3200)) * 102400)) AS "BlockSize", "E"."Hash", "E"."BlocklistSize", "E"."BlocklistHash" FROM ( SELECT * FROM ( SELECT "A"."BlocksetID", "A"."Index" AS "BlocklistIndex", MIN(3200 * 32, ((("B"."Length" + 102400 - 1) / 102400) - ("A"."Index" * (3200))) * 32) AS "BlocklistSize", "A"."Hash" AS "BlocklistHash", "B"."Length" FROM "BlocklistHash" A, "Blockset" B WHERE "B"."ID" = "A"."BlocksetID" ) C, "Block" D WHERE "C"."BlocklistHash" = "D"."Hash" AND "C"."BlocklistSize" = "D"."Size" ) E, "TempBlocklist-681BF9E1F669BF4C9D1A03258D28C3F1" F WHERE "F"."BlocklistHash" = "E"."Hash" ORDER BY "E"."BlocksetID", "FullIndex" ) D, "BlocklistHash" E, "Block" F, "Block" G WHERE "D"."BlocksetID" = "E"."BlocksetID" AND "D"."BlocklistHash" = "E"."Hash" AND "D"."BlocklistSize" = "G"."Size" AND "D"."BlocklistHash" = "G"."Hash" AND "D"."Blockhash" = "F"."Hash" AND "D"."BlockSize" = "F"."Size" UNION SELECT "Blockset"."ID" AS "BlocksetID", 0 AS "Index", "Block"."ID" AS "BlockID" FROM "Blockset", "Block", "TempSmalllist-3D9871FF54CA4F4FBE225C5B8D8939FA" S WHERE "Blockset"."Fullhash" = "S"."FileHash" AND "S"."BlockHash" = "Block"."Hash" AND "S"."BlockSize" = "Block"."Size" AND "Blockset"."Length" = "S"."BlockSize" AND "Blockset"."Length" <= 102400 ) H WHERE ("H"."BlocksetID" || ':' || "H"."Index") NOT IN (SELECT ("ExistingBlocksetEntries"."BlocksetID" || ':' || "ExistingBlocksetEntries"."Index") FROM "BlocksetEntry" "ExistingBlocksetEntries" )
Apr 23, 2019 11:42 AM: ExecuteNonQuery: INSERT INTO "Block" ("Hash", "Size", "VolumeID") SELECT "FullHash" AS "Hash", "Length" AS "Size", -1 AS "VolumeID" FROM (SELECT "A"."FullHash", "A"."Length", CASE WHEN "B"."Hash" IS NULL THEN '' ELSE "B"."Hash" END AS "Hash", CASE WHEN "B"."Size" is NULL THEN -1 ELSE "B"."Size" END AS "Size" FROM (SELECT DISTINCT "FullHash", "Length" FROM (SELECT "BlockHash" AS "FullHash", "BlockSize" AS "Length" FROM ( SELECT "E"."BlocksetID", "F"."Index" + ("E"."BlocklistIndex" * 3200) AS "FullIndex", "F"."BlockHash", MIN(102400, "E"."Length" - (("F"."Index" + ("E"."BlocklistIndex" * 3200)) * 102400)) AS "BlockSize", "E"."Hash", "E"."BlocklistSize", "E"."BlocklistHash" FROM ( SELECT * FROM ( SELECT "A"."BlocksetID", "A"."Index" AS "BlocklistIndex", MIN(3200 * 32, ((("B"."Length" + 102400 - 1) / 102400) - ("A"."Index" * (3200))) * 32) AS "BlocklistSize", "A"."Hash" AS "BlocklistHash", "B"."Length" FROM "BlocklistHash" A, "Blockset" B WHERE "B"."ID" = "A"."BlocksetID" ) C, "Block" D WHERE "C"."BlocklistHash" = "D"."Hash" AND "C"."BlocklistSize" = "D"."Size" ) E, "TempBlocklist-681BF9E1F669BF4C9D1A03258D28C3F1" F WHERE "F"."BlocklistHash" = "E"."Hash" ORDER BY "E"."BlocksetID", "FullIndex" ) UNION SELECT "BlockHash", "BlockSize" FROM "TempSmalllist-3D9871FF54CA4F4FBE225C5B8D8939FA" )) A LEFT OUTER JOIN "Block" B ON "B"."Hash" = "A"."FullHash" AND "B"."Size" = "A"."Length" ) WHERE "FullHash" != "Hash" AND "Length" != "Size" took 0:00:01:05.926
@warwickmm

This comment has been minimized.

Copy link
Contributor

commented Apr 25, 2019

Great investigation @ts678. I can reproduce this. With a backup with 200 MB source, 50 MB block size, and 1 backup version, recreating the database takes

  • between 1 and 2 minutes if the source contains an empty file
  • around 2 seconds if the source does not contain an empty file
@ts678

This comment has been minimized.

Copy link
Author

commented Apr 25, 2019

Thanks for the help and confirmation @warwickmm. If you got a profiling log (preferably also with --profile-all-sql-queries), you might find a long version of what I showed in the forum materials for length 0 (see "log of delete repair.txt") which is that it gets the dindex, does a SELECT series, then finishes with the INSERT you show. Recreate with length 0 then fruitlessly continues to processes the dblock and do an INSERT like above. In comparison, the length 1 log shows that it does the dindex and doesn't do dblock. Length 0 line sampler:

2019-04-22 17:25:50 -04 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-FilelistsRestored]: Filelists restored, downloading 1 index files
2019-04-22 17:25:50 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i784d436b70594566904b67a4297a1e06.dindex.zip (567 bytes)
2019-04-22 17:25:50 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "VolumeID" FROM "Block" WHERE "Hash" = "h0/YzKz6SsH4hvwQJ1JzIGkXMis7WlfU6ZSUepbg1Ro=" AND "Size" = 137  took 0:00:00:00.000
2019-04-22 17:25:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Block" ("Hash", "Size", "VolumeID") SELECT "FullHash" AS "Hash", "Length" AS "Size", -1 AS "VolumeID" ... took 0:00:00:00.135
2019-04-22 17:25:51 -04 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingAllBlocklistVolumes]: Processing all of the 1 volumes for blocklists: duplicati-beddfc3da6f4541aa8a3df41c6fc2e36f.dblock.zip
2019-04-22 17:25:51 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-beddfc3da6f4541aa8a3df41c6fc2e36f.dblock.zip (509 bytes)
2019-04-22 17:25:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "VolumeID" FROM "Block" WHERE "Hash" = "h0/YzKz6SsH4hvwQJ1JzIGkXMis7WlfU6ZSUepbg1Ro=" AND "Size" = 137  took 0:00:00:00.000
2019-04-22 17:25:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Block" ("Hash", "Size", "VolumeID") SELECT "FullHash" AS "Hash", "Length" AS "Size", -1 AS "VolumeID" ... took 0:00:00:00.000

From reversing some complex INSERT text chunks using a text search, I think the execution we see is below:

// Insert all known blocks into block table with volumeid = -1
cmd.ExecuteNonQuery(insertBlocksCommand);

The complex INSERT which is taking a minute or two in your posted results from forum #6496 is sub-second for me, likely because of minimal-sizing of my test. For a 2 GB dblock size, it's 14-15 hours in issue Database recreate runs forever #3668, which also proposes exponential slowdown based on backup size. It's not clear how it scales with dblock size, but 2 GB is 40 times the default 50 MB, and 14 hours is more than 40 times some reports BUT Database recreate performance in the testing by @JonMikelV on an "older machine" did the complex INSERT in 37 minutes so maybe this is one of those cases where fast hardware (possibly with an SSD) helps. The complex INSERT shows up quite a bit in reports that got to an SQL level of detail, for example forum Slow Database Delete and Repair Queries and Re-generate database duration which appear to show it was a regression, perhaps after 2.0.3.5, which sounds plausible because 2.0.3.6 is where the big concurrency rewrite came in. StreamBlockSplitter.cs wasn't even there before, and when looking further at per-line history of its block loop, I found there was an interesting change committed into the concurrent_processing branch:

Fixed empty block handling in concurrent_processing branch #2637

Duplicati/Library/Main/Operation/Backup/StreamBlockSplitter.cs "This change changes the logic so that empty blocks are not stored at all." and reasons were given (but not specifically detailed). You can, however, see that ability to restore empty-file-without-block was special-cased, it still exists, and release code changed in 2.0.3.6.

// Restore empty files. They might not have any blocks so don't appear in any volume.
foreach (var file in database.GetFilesToRestore(true).Where(item => item.Length == 0)) {
// Just create the file and close it right away, empty statement is intentional.
using (SystemIO.IO_OS.FileCreate(file.Path))
{
}
}

Because the special-case handling of empty files is already there and making backups, simply reverting to old behavior isn't enough to fix recreate (and it's not clear without a better understanding of the issue which was is best moving forward), so maybe we need to add more special-casing for empty file, to avoid dblock chases. There could sometimes still be legitimate reasons for it (e.g. backend corruption) though, so making it faster is good, but keeping it from being slow in normal case would be a huge improvement. I'm not sure if that's best done in C# or SQL (e.g. countMissingInformation). I've been impolitely suggesting that Duplicati needs more SQL/DBA expertise in its support and development people, but I might just be thinking of my own situation...

@Pectojin

This comment has been minimized.

Copy link
Member

commented Apr 27, 2019

size of the file is stored in the dlist, so we should be able to very quickly map out any files that do not have dblocks and just skip those.

    {
        "type": "File",
        "path": "/Users/rune/test/empty.txt",
        "hash": "47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=",
        "size": 0,
        "time": "20190427T164437Z",
        "metahash": "MS9OwTPnPnXO3VGuQ+9oGv/fiK8K7kZh2O9YYhihy3k=",
        "metasize": 193
    },
@ts678

This comment has been minimized.

Copy link
Author

commented Apr 27, 2019

If we assume that the countMissingInformation false positive is from VolumeID < 0, perhaps we could append that test with AND Size > 0. See the missingBlockInfo string in the source code shown below:

var missingBlockInfo =
@"SELECT ""VolumeID"" FROM ""Block"" WHERE ""VolumeID"" < 0 ";
var missingBlocklistVolumes = string.Format(
@"SELECT ""VolumeID"" FROM ""Block"", (" +
missingBlocklistEntries +
@") A WHERE ""A"".""Hash"" = ""Block"".""Hash"" "
);
var countMissingInformation = string.Format(
@"SELECT COUNT(*) FROM (SELECT DISTINCT ""VolumeID"" FROM ({0} UNION {1}))",
missingBlockInfo,
missingBlocklistVolumes);

Someone should probably put this on a debugger (because I haven't recently), however the additional Size check drove countMissingInformation (found at top of this issue) to 0 on a DB browse that used to find 1.

In other news, I verified that the empty file backup reading back the dblock was in 2.0.3.6 and not 2.0.3.5 which had the normal chain of Path --> BlocksetEntry --> Block --> VolumeID --> Name BUT taking the name of the dblock and trying to open it in Windows File Explorer or 7-Zip found the empty block stored wrong somehow. Comparing to a File Explorer created ZIP, I wonder if calling it Deflate method instead of Store method, and then storing packed size of 0 is valid? If I recall correctly, Duplicati sets compression per-block (which is how it can decide not to compress blocks from already compressed files, and intermix those with compressed blocks). If there was really a problem with empty files in Duplicati ZIP files, it might explain unit test failures that were fixed (attempted perhaps?) in Fixed some of the failing tests in concurrent_processing branch #2627 and then shortly after fixed more aggressively by not avoiding empty blocks. Recreate code apparently didn't get the memo on that, as the all-dblock load is bad, and the creation of the block with VolumeID -1 arguably shouldn't have happened, as that gives us not one but two non-standard ways of showing an empty file, on top of the normal way. Writing code around that is harder. The Pectojin plan might work, and gives one non-standard way of representing a file. Helpful simplification, but

I'd have preferred if 2017 fix (or maybe known fixes+unknown bugs) hadn't special-cased representation of an empty file. Who knows how many other spots needed fix? Need to check code and SQL pervasively. Going back to the old representation where an empty file is represented normally might take lots of doing though.

@Pectojin

This comment has been minimized.

Copy link
Member

commented Apr 27, 2019

Very valid concerns. I agree that it is logical to store empty blocks the old way, so that empty blocks and lost data doesn't look identical.

However, I'd also argue that even with the old implementation it's still worth implementing the size checks. Checking will boost performance in both restore and recreate functions because you're potentially avoiding download of a bunch of unneeded volumes.

It's a shame it was broken this way, but I think the right way forward is identifying and fixing any remaining issues with the new implementation.

We've had these changes for a while and, while there are unknown factors, the changes seem to be working with exception of this issue.

@warwickmm

This comment has been minimized.

Copy link
Contributor

commented May 3, 2019

Has anyone had a chance to test @ts678's suggestion of adding AND SIZE > 0 to the missingBlockInfo query? I'm not familiar with the details of the problem, but I tested it with a small backup with 200 MB source and 50 MB block size and 2 versions:

  1. Without adding AND SIZE > 0, recreating the database takes around 2 seconds if the source does not contain an empty file.
  2. Without adding AND SIZE > 0, recreating the database takes around 2 minutes if the source contains an empty file.
  3. After adding AND SIZE > 0, recreating the database takes around 2 seconds if the source contains an empty file. Subsequent backups, restores, and test commands all complete without any issue.
@Pectojin

This comment has been minimized.

Copy link
Member

commented May 3, 2019

I haven't had time yet but I can probably test it tomorrow.

@Pectojin

This comment has been minimized.

Copy link
Member

commented May 5, 2019

I might have been a little ambitious today. I set up the test on a fairly complex 50GB backup and it's still going on 7+ hours with the fix, so I abandoned it.

A slightly less ambitious test with a 1.39GB ISO

control backup:

  • backup time: 4:57
  • recreate with fix (1st run): 9 sec
  • recreate with fix (2nd run): 7 sec
  • recreate no fix (1st run): 7 sec
  • recreate no fix (2nd run): 7 sec

backup with empty file:

  • backup time: 3:43
  • recreate with fix (1st run): 10 sec
  • recreate with fix (2nd run): 8 sec
  • recreate no fix (1st run): 3:06
  • recreate no fix (2nd run): 3:05

The difference in backup time got me a little paranoid so I ran all the scenarios twice just to be sure. But it's definitely no question that it helps remarkably.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.