Untraceable long operation (query?) during backup

ts678 · May 22, 2020, 11:08am

I’m not sure it would log. I have it set, but the code is missing the parameter I guess it should give:

EDIT: had the wrong ExecuteNonQuery reference before

duplicati/duplicati/blob/41ea491bd77d39aaf33611ddf2e377c7e08c485a/Duplicati/Library/Main/Database/LocalBackupDatabase.cs#L733-L738


      
          if (!exclusionPredicate(path, size))
          {
              cmdAdd.SetParameterValue(1, row.GetInt64(1));
              cmdAdd.SetParameterValue(2, row.GetInt64(2));
              cmdAdd.ExecuteNonQuery();
          }

In terms of the ExecuteNonQuery call, I’m not sure where it’s wanting to go, but I wonder if it’s here:

github.com

duplicati/duplicati/blob/41ea491bd77d39aaf33611ddf2e377c7e08c485a/Duplicati/Library/Main/Database/ExtensionMethods.cs#L65-L68


      
          public static int ExecuteNonQuery(this System.Data.IDbCommand self, bool writeLog)

          {

              return ExecuteNonQuery(self, writeLog, null, null);

          }

Perhaps you can figure out the calling to see if you can get that INSERT loop logged, or breakpoint it.
It sure looks like a loop to me. You could try breakpoint and/or log something after loop, near Commit.
If Visual Studio can actually pause the program, some thread might be seen in the middle of the loop.
There are lots of threads though. My debug approach (using dnSpy) would probably try to breakpoint.

bramd · May 22, 2020, 1:25pm

For now, here is the log from todays backup. As you can see, it just continues normally after hanging for a logn time. I’ll investigate further.

2020-05-22 09:54:25 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT
	                      f."Path", fs."FileID", fs."Lastmodified", COALESCE(bs."Length", -1)
                      FROM (  SELECT DISTINCT "FileID", "Lastmodified"
		                      FROM "FilesetEntry"
		                      WHERE "FilesetID" = 25
		                      AND "FileID" NOT IN (
			                      SELECT "FileID"
			                      FROM "FilesetEntry"
			                      WHERE "FilesetID" = 26
		                      )) AS fs
                      LEFT JOIN "File" AS f ON fs."FileID" = f."ID"
                      LEFT JOIN "Blockset" AS bs ON f."BlocksetID" = bs."ID"; took 0:00:00:04.376
2020-05-22 14:02:25 +02 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "ChangeJournalData" ("FilesetID", "VolumeName", "JournalID", "NextUSN", "ConfigHash") VALUES (26, "C:\", 132345473577081046, 30821624, "24C84FA81E12D0D67486943DC243BF61");
2020-05-22 14:02:25 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "ChangeJournalData" ("FilesetID", "VolumeName", "JournalID", "NextUSN", "ConfigHash") VALUES (26, "C:\", 132345473577081046, 30821624, "24C84FA81E12D0D67486943DC243BF61"); took 0:00:00:00.001
2020-05-22 14:02:25 +02 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "ChangeJournalData" ("FilesetID", "VolumeName", "JournalID", "NextUSN", "ConfigHash") VALUES (26, "D:\", 132345475026354186, 3888, "24C84FA81E12D0D67486943DC243BF61");
2020-05-22 14:02:25 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "ChangeJournalData" ("FilesetID", "VolumeName", "JournalID", "NextUSN", "ConfigHash") VALUES (26, "D:\", 132345475026354186, 3888, "24C84FA81E12D0D67486943DC243BF61"); took 0:00:00:00.000
2020-05-22 14:02:25 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ba8cf37e7d1184805b7c39260a995c479.dblock.zip.aes (28.19 MB)
2020-05-22 14:02:25 +02 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "ChangeJournalData" SET "NextUSN" = 30821624 WHERE "FilesetID" = 25 AND "VolumeName" = "C:\" AND "JournalID" = 132345473577081046;
2020-05-22 14:02:25 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "ChangeJournalData" SET "NextUSN" = 30821624 WHERE "FilesetID" = 25 AND "VolumeName" = "C:\" AND "JournalID" = 132345473577081046; took 0:00:00:00.000
2020-05-22 14:02:25 +02 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "ChangeJournalData" SET "NextUSN" = 3888 WHERE "FilesetID" = 25 AND "VolumeName" = "D:\" AND "JournalID" = 132345475026354186;
2020-05-22 14:02:25 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "ChangeJournalData" SET "NextUSN" = 3888 WHERE "FilesetID" = 25 AND "VolumeName" = "D:\" AND "JournalID" = 132345475026354186; took 0:00:00:00.000
2020-05-22 14:02:25 +02 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "Fileset" SET "IsFullBackup" = True WHERE "ID" = 26;
2020-05-22 14:02:25 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "Fileset" SET "IsFullBackup" = True WHERE "ID" = 26; took 0:00:00:00.000
2020-05-22 14:02:25 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-BackupMainOperation]: BackupMainOperation took 0:04:24:46.665
2020-05-22 14:02:26 +02 - [Profiling-Timer.Begin-Duplicati.Library.Main.Operation.BackupHandler-VerifyConsistency]: Starting - VerifyConsistency
2020-05-22 14:02:26 +02 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "CalcLen", "Length", "A"."BlocksetID", "File"."Path" FROM (
SELECT 
    "A"."ID" AS "BlocksetID", 
    IFNULL("B"."CalcLen", 0) AS "CalcLen", 
    "A"."Length"
FROM
    "Blockset" A
LEFT OUTER JOIN
    (
        SELECT 
            "BlocksetEntry"."BlocksetID",
            SUM("Block"."Size") AS "CalcLen"
        FROM
            "BlocksetEntry"
        LEFT OUTER JOIN
            "Block"
        ON
            "Block"."ID" = "BlocksetEntry"."BlockID"
        GROUP BY "BlocksetEntry"."BlocksetID"
    ) B
ON
    "A"."ID" = "B"."BlocksetID"

) A, "File" WHERE "A"."BlocksetID" = "File"."BlocksetID" AND "A"."CalcLen" != "A"."Length" 
2020-05-22 14:02:50 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "CalcLen", "Length", "A"."BlocksetID", "File"."Path" FROM (
SELECT 
    "A"."ID" AS "BlocksetID", 
    IFNULL("B"."CalcLen", 0) AS "CalcLen", 
    "A"."Length"
FROM
    "Blockset" A
LEFT OUTER JOIN
    (
        SELECT 
            "BlocksetEntry"."BlocksetID",
            SUM("Block"."Size") AS "CalcLen"
        FROM
            "BlocksetEntry"
        LEFT OUTER JOIN
            "Block"
        ON
            "Block"."ID" = "BlocksetEntry"."BlockID"
        GROUP BY "BlocksetEntry"."BlocksetID"
    ) B
ON
    "A"."ID" = "B"."BlocksetID"

) A, "File" WHERE "A"."BlocksetID" = "File"."BlocksetID" AND "A"."CalcLen" != "A"."Length"  took 0:00:00:23.816

The rest is cut off due to max size of a message on the forum.

ts678 · May 22, 2020, 2:16pm

I hope I fixed mis-aimed code reference earlier, replacing it with the relevant ExecuteNonQuery().
I wonder, though, if the exclusionPredicate test is taking more time per file than INSERT itself.

I haven’t closely studied the code but there should now be links to both the caller and the called…
Regardless, a good first step would be to get some testing to see if INSERT loop is that slow spot.

Daniel_Gehriger · August 17, 2020, 1:37pm

I may have a solution to this issue. Instead of adding the files one by one in AppendFilesFromPreviousSetWithPredicate(), it may be much faster to first use AppendFilesFromPreviousSet() in its implementation, and then delete the entries that aren’t needed. I’ll investigate this.

See Feature/improve usn 2 by dgehri · Pull Request #4287 · duplicati/duplicati · GitHub

Daniel_Gehriger · August 17, 2020, 1:43pm

I can confirm that the predicate isn’t the bottleneck, but the INSERTs.

Daniel_Gehriger · October 18, 2020, 7:58am

Issue fixed as of Feature/improve usn 2 by dgehri · Pull Request #4287 · duplicati/duplicati · GitHub.