might be the same as where my log looks like below, except I don’t have the huge gap in between…
2020-05-20 16:41:08 -04 - [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" = 874
AND "FileID" NOT IN (
SELECT "FileID"
FROM "FilesetEntry"
WHERE "FilesetID" = 875
)) 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:00.002
2020-05-20 16:41:08 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "ChangeJournalData" ("FilesetID", "VolumeName", "JournalID", "NextUSN", "ConfigHash") VALUES (875, "C:\", 131110814199265407, 96771819752, "410D0B5054C6796CE70A2CCC6B5191EF");
2020-05-20 16:41:08 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery:
INSERT INTO "ChangeJournalData" ("FilesetID", "VolumeName", "JournalID", "NextUSN", "ConfigHash") VALUES (875, "C:\", 131110814199265407, 96771819752, "410D0B5054C6796CE70A2CCC6B5191EF"); took 0:00:00:00.001
I’m thinking the source code might be below. You see a SELECT logged. You don’t see all its INSERT:
Ordinarily one can add the following option to have Duplicati spend time on frequent DB operations:
--profile-all-database-queries (Boolean): Activates logging of all database
queries
To improve performance of the backups, frequent database queries are not
logged by default. Enable this option to log all database queries, and
remember to set either --console-log-level=Profiling or
--log-file-log-level=Profiling to report the additional log data
* default value: false
I’m not sure ir someone forgot to pass in m_logQueries here (like in others) or if it meant to not log.
This backup is quite small though, and maybe a large backup spends a lot more time doing INSERT.
“Large” in this case probably means the number of source files. Got a log value for ExaminedFiles?
While FilesetEntry table always gets a row per file per backup, another place does all in one INSERT:
was the same worry about an INSERT loop (but in a different code spot, based on the stated context).
The reason USN is using the maybe-slower AppendFilesFromPreviousSetWithPredicate and not AppendFilesFromPreviousSet might be below.
EDIT 1:
Although it won’t directly show SQL activity, it might be possible to run Sysinternals Process Monitor during the slow spot to see whether the child Duplicati process is doing lots of work on an sqlite file. Sometimes filename might contain a backwards sqlite, i.e. etilqs instead of the ordinary sqlite which might not be the very end of the file, because suffixes are used for the temporary journal files.
EDIT 2:
supports the idea that a large number of files causes a slowdown when USN is in use. Experiments could also be done, e.g. to see if the “could take hours” hang scales up and down with file numbers.