# Untraceable long operation (query?) during backup
**URL:** https://forum.duplicati.com/t/untraceable-long-operation-query-during-backup/9007
**Category:** Support
**Created:** [January 29, 2020, 2:23pm UTC](https://forum.duplicati.com/t/untraceable-long-operation-query-during-backup/9007 "2020-01-29T14:23:01Z")
**Posts on this page:** 1
**Showing post:** 19
### Author:  [@ts678](https://forum.duplicati.com/u/ts678)
#### Post date: [May 21, 2020, 11:27pm UTC](https://forum.duplicati.com/t/untraceable-long-operation-query-during-backup/9007/19 "2020-05-21T23:27:56Z")
> [@bramd](#):
>
> 21 mei 2020 20:11: ExecuteReader: SELECT f.“Path”, fs.“FileID”, fs.“Lastmodified”, COALESCE(bs.“Length”, -1) FROM ( SELECT DISTINCT “FileID”, “Lastmodified” FROM “FilesetEntry” WHERE “FilesetID” = 24 AND “FileID” NOT IN ( SELECT “FileID” FROM “FilesetEntry” WHERE “FilesetID” = 25 )) 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:05.455
> [@bramd](#):
>
> The last log entries show database activity, in previous instances where it got over this hang (could take hours), the next log entries would be for the queries to insert the USN data.
might be the same as where my log looks like below, except I don’t have the huge gap in between…
```plaintext
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:
```plaintext
--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:
>
> [@Ingmyv](#):
>
> one-at-a-time (foreach (var entry in data)) being inserted. That is a potential bottlneck
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](https://docs.microsoft.com/en-us/sysinternals/downloads/procmon) 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](https://www.sqlite.org/tempfiles.html) files.
EDIT 2:
> [@Usn-policy=on nearly doubles backup time](https://forum.duplicati.com/t/usn-policy-on-nearly-doubles-backup-time/9862/1):
>
> it includes hundreds of thousands of files
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.
---
_[View the full topic](https://forum.duplicati.com/t/untraceable-long-operation-query-during-backup/9007)._