Stuck on "Starting …"

A hash (in base64 + \0) is 44 bytes, and with 100kb blocks, you need to store at least 44 bytes pr. 100kb, or 450kb pr GB of source data.
On top of that you need to store all the paths, in a rather crude manner where each folder and file path is stored in its full length, taking up a considerate amount of space for large backups.

Yes, it can be moved freely. But from the Web-UI you need to use the “Database” option for moving the database as it ignores the --dbpath advanced option.

Yes, but the file that SQLite creates is a temporary transaction file, which it places in TMPDIR.

1 Like

Then it is possible that it is just spending all its time in database lookups, trying to see if the file has changed or not. You can use --check-filetime-only to have this lookup done faster, if you know that your programs do not fiddle with the timestamps.

1 Like

Thank you again for good answers @kenkendk, much appreciated.

A few follow up questions:

  • Why does the webui ignore the dbpath option?
  • Does the temporary SQL file get very large? Or is it safe to leave it there if my /tmp has 4GB to spare?
  • Could you please elaborate a bit on --check-filetime-only?

This flag instructs Duplicati to not look at metadata or filesize when deciding to scan a file for changes. Use this option if you have a large number of files and notice that the scanning takes a long time with unmodified files.

The files are on NAS that is shared in a small design studio (mac only), and used by a few people every day. As far as I know it’s no “fiddling” with timestamps, but files can change (as in any backup). But yes, it’s a lot of files – also a lot of duplicate files (typically images that is used in a lot of different projects).

(The NAS itself is run on OmniOS with ZFS, shared via CFS/SMB (mac clients) and NFS (ie. Ubuntu VM).)

And the current log file is full of:

Sep 14, 2017 11:30 PM: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
Sep 14, 2017 11:30 PM: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 00:00:00.015

Internally, the database path is stored in one place, and options in another. As many operations from the WebUI needs access to the database, it made sense to just hide the database things from the users.

I have been planning to fix this a bit by adding some logic that checks if the user has changed the --dbpath option and ask them how to handle it, but for now it is a bit obscure.

That really depends on how much data you put in there. It should not grow larger than the size of the database itself (well, perhaps marginally if new data is added).

Duplicati compares: metadata, filesize, timestamp. If either of these values have changed, the file blocks will be scanned. The rationale is that hashing is an expensive operation, and can be avoided.

To get the previous values for this, it looks in the database and finds the previous values for the current file. Some users report that this lookup is slow. The --check-filetime-only makes a faster lookup, by only loading the previous timestamp, and ignoring the other values.

Some people are using programs that fiddle with the timestamps (i.e. TrueCrypt) and these files stay the same size and the same timestamp. You can use --disable-filetime-check to force scanning all the files regardless of their attributes.

That is block lookups, it checks if it already knows the data that it found.

1 Like

Thank you.

I’ve now moved the DB (not the /tmp as of now). I also enabled “–check-filetime-only”.

So far it’s much faster starting up, but it looks like it spends a lot of time “Verifying backend data …”. Not sure if it’s possible to optimize any further?

The initial check is just a listing of the remote files, and should be pretty fast.

There is another verification at the end, where it downloads a random volume and checks it for consistency, which can be slow due to the network transfer.

There is more on how to fiddle with this here:

1 Like

And I should add: you can disable all remote checks completely with --no-backend-verification.

1 Like

Thank you!

I guess the checks are there for a reason? I’m a bit skeptical to disable all of the verifications, but I think something is off since it’s been “stuck” on “Verifying backend data …” for quite a while now.

 [B2017-09-15 12:47:34Z - Profiling: Starting - Running Backup
2017-09-15 12:47:34Z - Profiling: Starting - ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES (?, ?); SELECT last_insert_rowid();
2017-09-15 12:47:35Z - Profiling: ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES (?, ?); SELECT last_insert_rowid(); took 00:00:00.274
2017-09-15 12:47:35Z - Profiling: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"
2017-09-15 12:47:35Z - Profiling: ExecuteReader: SELECT "Key", "Value" FROM "Configuration"  took 00:00:00.059
2017-09-15 12:47:35Z - Profiling: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"
2017-09-15 12:47:35Z - Profiling: ExecuteReader: SELECT "Key", "Value" FROM "Configuration"  took 00:00:00.000
2017-09-15 12:47:35Z - Profiling: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Block" WHERE "Size" > ?
2017-09-15 12:51:43Z - Profiling: ExecuteScalarInt64: SELECT COUNT(*) FROM "Block" WHERE "Size" > ? took 00:04:08.522
2017-09-15 12:51:50Z - Profiling: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"
2017-09-15 12:51:50Z - Profiling: ExecuteReader: SELECT "Key", "Value" FROM "Configuration"  took 00:00:00.000
2017-09-15 12:51:50Z - Profiling: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"
2017-09-15 12:51:50Z - Profiling: ExecuteReader: SELECT "Key", "Value" FROM "Configuration"  took 00:00:00.000
2017-09-15 12:51:50Z - Profiling: 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"
2017-09-15 12:52:38Z - Profiling: 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 00:00:48.508
2017-09-15 12:52:38Z - Profiling: Starting - ExecuteScalarInt64: SELECT Count(*) FROM "BlocklistHash"
2017-09-15 12:52:39Z - Profiling: ExecuteScalarInt64: SELECT Count(*) FROM "BlocklistHash" took 00:00:00.229
2017-09-15 12:52:39Z - Profiling: Starting - ExecuteScalarInt64: SELECT Count(*) FROM (SELECT DISTINCT "BlocksetID", "Index" FROM "BlocklistHash")
2017-09-15 12:52:39Z - Profiling: ExecuteScalarInt64: SELECT Count(*) FROM (SELECT DISTINCT "BlocksetID", "Index" FROM "BlocklistHash") took 00:00:00.013
2017-09-15 12:52:39Z - Profiling: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM (SELECT * FROM (SELECT "N"."BlocksetID", (("N"."BlockCount" + 3200 - 1) / 3200) AS "BlocklistHashCountExpected", CASE WHEN "G"."BlocklistHashCount" IS NULL THEN 0 ELSE "G"."BlocklistHashCount" END AS "BlocklistHashCountActual" FROM (SELECT "BlocksetID", COUNT(*) AS "BlockCount" FROM "BlocksetEntry" GROUP BY "BlocksetID") "N" LEFT OUTER JOIN (SELECT "BlocksetID", COUNT(*) AS "BlocklistHashCount" FROM "BlocklistHash" GROUP BY "BlocksetID") "G" ON "N"."BlocksetID" = "G"."BlocksetID" WHERE "N"."BlockCount" > 1) WHERE "BlocklistHashCountExpected" != "BlocklistHashCountActual")
2017-09-15 12:52:54Z - Profiling: ExecuteScalarInt64: SELECT COUNT(*) FROM (SELECT * FROM (SELECT "N"."BlocksetID", (("N"."BlockCount" + 3200 - 1) / 3200) AS "BlocklistHashCountExpected", CASE WHEN "G"."BlocklistHashCount" IS NULL THEN 0 ELSE "G"."BlocklistHashCount" END AS "BlocklistHashCountActual" FROM (SELECT "BlocksetID", COUNT(*) AS "BlockCount" FROM "BlocksetEntry" GROUP BY "BlocksetID") "N" LEFT OUTER JOIN (SELECT "BlocksetID", COUNT(*) AS "BlocklistHashCount" FROM "BlocklistHash" GROUP BY "BlocksetID") "G" ON "N"."BlocksetID" = "G"."BlocksetID" WHERE "N"."BlockCount" > 1) WHERE "BlocklistHashCountExpected" != "BlocklistHashCountActual") took 00:00:15.465
2017-09-15 12:52:54Z - Profiling: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "File" WHERE "BlocksetID" != ? AND "BlocksetID" != ? AND NOT "BlocksetID" IN (SELECT "BlocksetID" FROM "BlocksetEntry")
2017-09-15 12:52:57Z - Profiling: ExecuteScalarInt64: SELECT COUNT(*) FROM "File" WHERE "BlocksetID" != ? AND "BlocksetID" != ? AND NOT "BlocksetID" IN (SELECT "BlocksetID" FROM "BlocksetEntry") took 00:00:02.694
2017-09-15 12:52:57Z - Profiling: Starting - ExecuteReader: SELECT DISTINCT "Fileset"."ID", "Fileset"."Timestamp" FROM "Fileset", "RemoteVolume" WHERE "RemoteVolume"."ID" = "Fileset"."VolumeID" AND "Fileset"."ID" IN (SELECT "FilesetID" FROM "FilesetEntry")  AND ("RemoteVolume"."State" = "Uploading" OR "RemoteVolume"."State" = "Temporary")
2017-09-15 12:52:57Z - Profiling: ExecuteReader: SELECT DISTINCT "Fileset"."ID", "Fileset"."Timestamp" FROM "Fileset", "RemoteVolume" WHERE "RemoteVolume"."ID" = "Fileset"."VolumeID" AND "Fileset"."ID" IN (SELECT "FilesetID" FROM "FilesetEntry")  AND ("RemoteVolume"."State" = "Uploading" OR "RemoteVolume"."State" = "Temporary") took 00:00:00.163
2017-09-15 12:52:57Z - Profiling: Starting - ExecuteReader: SELECT "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume" WHERE "ID" = ?
2017-09-15 12:52:57Z - Profiling: ExecuteReader: SELECT "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume" WHERE "ID" = ? took 00:00:00.000
2017-09-15 12:52:57Z - Profiling: Starting - PreBackupVerify
2017-09-15 12:52:57Z - Profiling: Starting - RemoteOperationList
2017-09-15 12:52:57Z - Information: Backend event: List - Started:  ()
2017-09-15 13:00:56Z - Profiling: RemoteOperationList took 00:07:59.364
2017-09-15 13:00:56Z - Warning: Operation List with file  attempt 1 of 5 failed with message: The remote server returned an error: (403) Forbidden.
System.Net.WebException: The remote server returned an error: (403) Forbidden.
  at Duplicati.Library.Utility.AsyncHttpRequest+AsyncWrapper.GetResponseOrStream () <0x40d6b310 + 0x0010b> in <filename unknown>:0
  at Duplicati.Library.Utility.AsyncHttpRequest.GetResponse () <0x40da19a0 + 0x00163> in <filename unknown>:0
  at Duplicati.Library.JSONWebHelper.GetResponse (Duplicati.Library.Utility.AsyncHttpRequest req, System.Object requestdata) <0x40dcde70 + 0x0040f> in <filename unknown>:0
2017-09-15 13:00:56Z - Information: Backend event: List - Retrying:  ()
2017-09-15 13:01:06Z - Profiling: Starting - RemoteOperationList
2017-09-15 13:01:06Z - Information: Backend event: List - Started:  ()
2017-09-15 13:11:43Z - Information: Backend event: List - Completed:  (62.22 KB)
2017-09-15 13:11:43Z - Profiling: RemoteOperationList took 00:10:36.123
2017-09-15 13:11:45Z - Profiling: Starting - ExecuteReader: SELECT DISTINCT "Name", "State" FROM "Remotevolume" WHERE "Name" IN (SELECT "Name" FROM "Remotevolume" WHERE "State" IN ("Deleted", "Deleting")) AND NOT "State" IN ("Deleted", "Deleting")
2017-09-15 13:11:46Z - Profiling: ExecuteReader: SELECT DISTINCT "Name", "State" FROM "Remotevolume" WHERE "Name" IN (SELECT "Name" FROM "Remotevolume" WHERE "State" IN ("Deleted", "Deleting")) AND NOT "State" IN ("Deleted", "Deleting") took 00:00:00.911
2017-09-15 13:11:50Z - Information: removing file listed as Temporary: duplicati-20170914T221359Z.dlist.zip.aes
2017-09-15 13:11:51Z - Information: promoting uploaded complete file from Uploading to Uploaded: duplicati-b0ec2147ae2a34830a0ac6a2d7f629c67.dblock.zip.aes
2017-09-15 13:11:51Z - Information: removing incomplete remote file listed as Uploading: duplicati-i3c41e9488f6f408f9abd1102ca9c8d7c.dindex.zip.aes
2017-09-15 13:11:51Z - Profiling: Starting - RemoteOperationDelete
2017-09-15 13:11:51Z - Information: Backend event: Delete - Started: duplicati-i3c41e9488f6f408f9abd1102ca9c8d7c.dindex.zip.aes ()
2017-09-15 13:11:52Z - Information: Backend event: Delete - Completed: duplicati-i3c41e9488f6f408f9abd1102ca9c8d7c.dindex.zip.aes ()
2017-09-15 13:11:52Z - Profiling: RemoteOperationDelete took 00:00:00.526
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ("ID" INTEGER PRIMARY KEY) took 00:00:00.041
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:11:52Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.000
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.108
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ))
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )) took 00:00:00.000
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:11:52Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:11:52Z - Profiling: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ))
2017-09-15 13:11:54Z - Profiling: ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )) took 00:00:01.937
2017-09-15 13:11:54Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:09.066
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ))
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )) took 00:00:00.019
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" )
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66" ) took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66"
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66"  took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66"
2017-09-15 13:12:03Z - Profiling: ExecuteNonQuery: DELETE FROM "DelVolSetIds-AD833B287D0085479428FDAAA779BA66"  took 00:00:00.000
2017-09-15 13:12:03Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66"
2017-09-15 13:12:05Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-AD833B287D0085479428FDAAA779BA66"  took 00:00:02.048
2017-09-15 13:12:05Z - Information: promoting uploaded complete file from Uploading to Uploaded: duplicati-bd2594082e8a24fb2abc6501ab015f1dd.dblock.zip.aes
2017-09-15 13:12:05Z - Information: removing incomplete remote file listed as Uploading: duplicati-if7a1207ad0f146c38f8b18a4ec8de45a.dindex.zip.aes
2017-09-15 13:12:05Z - Profiling: Starting - RemoteOperationDelete
2017-09-15 13:12:05Z - Information: Backend event: Delete - Started: duplicati-if7a1207ad0f146c38f8b18a4ec8de45a.dindex.zip.aes ()
2017-09-15 13:12:06Z - Information: Backend event: Delete - Completed: duplicati-if7a1207ad0f146c38f8b18a4ec8de45a.dindex.zip.aes ()
2017-09-15 13:12:06Z - Profiling: RemoteOperationDelete took 00:00:00.594
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:12:06Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.000
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.107
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ))
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )) took 00:00:00.000

(1/2)

(2/2)

2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:06Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:06Z - Profiling: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ))
2017-09-15 13:12:08Z - Profiling: ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )) took 00:00:01.347
2017-09-15 13:12:08Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:09.088
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ))
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )) took 00:00:00.020
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" )
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B" ) took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B"
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B"  took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B"
2017-09-15 13:12:17Z - Profiling: ExecuteNonQuery: DELETE FROM "DelVolSetIds-4349C270295FF540B7A759FBCD1CFA3B"  took 00:00:00.000
2017-09-15 13:12:17Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B"
2017-09-15 13:12:19Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-4349C270295FF540B7A759FBCD1CFA3B"  took 00:00:02.001
2017-09-15 13:12:19Z - Information: promoting uploaded complete file from Uploading to Uploaded: duplicati-b0206c2cc5365435f9579ab25682846ac.dblock.zip.aes
2017-09-15 13:12:19Z - Information: removing incomplete remote file listed as Uploading: duplicati-iff08a32994df4288a13e9bd440aa50e0.dindex.zip.aes
2017-09-15 13:12:19Z - Profiling: Starting - RemoteOperationDelete
2017-09-15 13:12:19Z - Information: Backend event: Delete - Started: duplicati-iff08a32994df4288a13e9bd440aa50e0.dindex.zip.aes ()
2017-09-15 13:12:20Z - Information: Backend event: Delete - Completed: duplicati-iff08a32994df4288a13e9bd440aa50e0.dindex.zip.aes ()
2017-09-15 13:12:20Z - Profiling: RemoteOperationDelete took 00:00:00.522
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-31787F989488844C8D115D04E0064C62" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-31787F989488844C8D115D04E0064C62" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:12:20Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.107
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ))
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )) took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:20Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:20Z - Profiling: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ))
2017-09-15 13:12:22Z - Profiling: ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )) took 00:00:01.781
2017-09-15 13:12:22Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:07.901
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ))
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )) took 00:00:00.020
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" )
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62" ) took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62"
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-31787F989488844C8D115D04E0064C62"  took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62"
2017-09-15 13:12:30Z - Profiling: ExecuteNonQuery: DELETE FROM "DelVolSetIds-31787F989488844C8D115D04E0064C62"  took 00:00:00.000
2017-09-15 13:12:30Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-31787F989488844C8D115D04E0064C62"
2017-09-15 13:12:32Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-31787F989488844C8D115D04E0064C62"  took 00:00:02.035
2017-09-15 13:12:32Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:32Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ("ID" INTEGER PRIMARY KEY) took 00:00:00.009
2017-09-15 13:12:32Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:12:32Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.001
2017-09-15 13:12:32Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:32Z - Profiling: ExecuteNonQuery: DELETE FROM "IndexBlockLink" WHERE "BlockVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) OR "IndexVolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.096
2017-09-15 13:12:32Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ))
2017-09-15 13:12:35Z - Profiling: ExecuteNonQuery: DELETE FROM "FilesetEntry" WHERE "FilesetID" IN (SELECT "ID" FROM "Fileset" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )) took 00:00:02.838
2017-09-15 13:12:35Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:35Z - Profiling: ExecuteNonQuery: DELETE FROM "Fileset" WHERE "VolumeID"  IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:35Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ("ID" INTEGER PRIMARY KEY)
2017-09-15 13:12:35Z - Profiling: ExecuteNonQuery: CREATE TEMP TABLE "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ("ID" INTEGER PRIMARY KEY) took 00:00:00.000
2017-09-15 13:12:35Z - Profiling: Starting - ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ))
2017-09-15 13:12:36Z - Profiling: ExecuteNonQuery: INSERT OR IGNORE INTO "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ("ID") SELECT "BlocksetEntry"."BlocksetID" FROM "BlocksetEntry", "Block"  WHERE "BlocksetEntry"."BlockID" = "Block"."ID" AND "Block"."VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) UNION ALL SELECT "BlocksetID" FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )) took 00:00:01.717
2017-09-15 13:12:36Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:45Z - Profiling: ExecuteNonQuery: DELETE FROM "File" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) OR "MetadataID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:08.556
2017-09-15 13:12:45Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:45Z - Profiling: ExecuteNonQuery: DELETE FROM "Metadataset" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:45Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:45Z - Profiling: ExecuteNonQuery: DELETE FROM "Blockset" WHERE "ID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:45Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:45Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocksetEntry" WHERE "BlocksetID" IN (SELECT "ID" FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:45Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ))
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "BlocklistHash" WHERE "Hash" IN (SELECT "Hash" FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )) took 00:00:02.139
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "Block" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.003
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" )
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "DeletedBlock" WHERE "VolumeID" IN (SELECT "ID" FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A" ) took 00:00:00.000
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A"
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A"  took 00:00:00.000
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A"
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DELETE FROM "DelVolSetIds-D05227618E2F5647A5557F7CC779799A"  took 00:00:00.000
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A"
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelBlockSetIds-D05227618E2F5647A5557F7CC779799A"  took 00:00:00.000
2017-09-15 13:12:47Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "DelVolSetIds-D05227618E2F5647A5557F7CC779799A"
2017-09-15 13:12:47Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "DelVolSetIds-D05227618E2F5647A5557F7CC779799A"  took 00:00:00.007
2017-09-15 13:12:49Z - Profiling: PreBackupVerify took 00:19:52.382
2017-09-15 13:12:49Z - Profiling: Starting - ExecuteReader: SELECT "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume" WHERE "ID" = ?
2017-09-15 13:12:49Z - Profiling: ExecuteReader: SELECT "Name", "Type", "Size", "Hash", "State", "DeleteGraceTime" FROM "RemoteVolume" WHERE "ID" = ? took 00:00:00.005
2017-09-15 13:12:49Z - Warning: Expected there to be a temporary fileset for synthetic filelist (3, duplicati-idfccf4b6966d401eb353cd093f91c8f6.dindex.zip.aes), but none was found?
2017-09-15 13:12:49Z - Profiling: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC
2017-09-15 13:12:49Z - Profiling: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 00:00:00.000
2017-09-15 13:12:49Z - Profiling: Starting - ExecuteReader: SELECT "Name" FROM "RemoteVolume" WHERE "Type" = ? AND NOT "ID" IN (SELECT "BlockVolumeID" FROM "IndexBlockLink") AND "State" IN (?,?)
2017-09-15 13:12:52Z - Profiling: ExecuteReader: SELECT "Name" FROM "RemoteVolume" WHERE "Type" = ? AND NOT "ID" IN (SELECT "BlockVolumeID" FROM "IndexBlockLink") AND "State" IN (?,?) took 00:00:02.527
2017-09-15 13:12:52Z - Information: Re-creating missing index file for duplicati-b0ec2147ae2a34830a0ac6a2d7f629c67.dblock.zip.aes
2017-09-15 13:12:52Z - Profiling: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (?, ?, ?, ?, ?, ?, ?); SELECT last_insert_rowid();
2017-09-15 13:12:52Z - Profiling: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (?, ?, ?, ?, ?, ?, ?); SELECT last_insert_rowid(); took 00:00:00.026
2017-09-15 13:12:52Z - Profiling: Starting - ExecuteReader: SELECT "Name", "Hash", "Size" FROM "RemoteVolume" WHERE "Name" = ?
2017-09-15 13:12:52Z - Profiling: ExecuteReader: SELECT "Name", "Hash", "Size" FROM "RemoteVolume" WHERE "Name" = ? took 00:00:00.004
2017-09-15 13:12:52Z - Profiling: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ?
2017-09-15 13:12:52Z - Profiling: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = ? took 00:00:00.000
2017-09-15 13:12:52Z - Profiling: Starting - ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = ?
2017-09-15 13:12:52Z - Profiling: ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = ? took 00:00:00.002
2017-09-15 13:12:52Z - Profiling: 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" * 3200) AND "B"."Index" < (("A"."Index" + 1) * 3200) AND "C"."ID" = "B"."BlockID"  ORDER BY "A"."BlocksetID", "B"."Index"

(This is the current log, the time is now 14:27)

Please let me know if there is any more data needed, or a better way to debug.

If it’s not costing you money, keeping veifications in is indeed good idea. (Well, it’s a good idea if it costs money, but…) :slight_smile:

I’m not proficient in reading the log stuff so this may not apply to you, but possible reasons for verifications taking “quite a while” could be due to settings such as:

  • how fast downloads are allowed --throttle-download (because the archives to be tested have to be downloaded the slowness could be just waiting for the archive file to be downloaded for testing)
  • archive (dblock) size --dblock-size (big archives means lots of data to test)
  • the number of samples being tested --backup-test-samples (lots of archives to test could take a while)

Thank you. I agree, I can live with it taking some time, but if it’s not supposed to, I would like to figure out why and fix it. :slight_smile:

Regarding your suggestions:

  • –throttle-download is not enabled.
  • –dblock-size is default, 50 mb.
  • –backup-test-samples is set to 3

So I don’t think that should influense this?

Agreed - those settings (might even be the defaults) shouldn’t be having this effect.

BTW: A good way of showing your appreciation for a post is to like it: just press the :heart: button under the post.

If you asked the original question, you can also mark an answer as the accepted answer which solved your problem using the tick-box button you see under each reply.

All of this also helps the forum software distinguish interesting from less interesting posts when compiling summary emails.

I also edited some of your posts to improve the formating. (Just added ~~~ before and after the output you pasted, see here for details).

1 Like

I don’t want to wander too much off topic, but I did the :heart: button too, and I genuinely say thank you to people who help me. Is that a bad thing here?

Anyhow, thank you (hope that’s okay saying that) for the editing (& tips for next time), I will try to use them from now on.

I thought I didn’t see any likes but I may have missed them. In that case my hint was of course superfluous. In any case, it was not meant as a criticism of saying thank you. So:

No, not at all. It’s much appreciated! Thank you for participating!

Great! :slight_smile:

I had :heart:'ed the few first posts from yesterday, but not todays (until you mentioned it). :slight_smile:

So, back to the topic, if anyone has the slightest idea of why “Verifying backend data …” is taking so long on a Ubuntu VM with G Suite/GDrive as backend, all input is greatly appreciated!

Thanks for the :heart:s!

NoLooseEnds, am I correct in thinking it the original “Stuck on starting” issue was actually related to the slow verification times? If so, maybe changing the Topic title would make sense.

It sounds like you’re using a cloud provider for the backend (sorry - kinda skimming here). If that’s the case do you have the time/space to try bring the backup files to a local machine or LAN destination and trying the verification process pointing at that local destination? That would help remove cloud and internet (and potentially LAN) bottlenecks from the scenario.

Alternatively, you could try setting up a pair of smaller test backups to the same cloud provider as your primary AND to somewhere local and seeing if the “verify backend data” step takes about the same time regardless of the “distance” to the destination.

1 Like

This looks like the source of the problems. Duplicati has detected that this file was not uploaded completely for some reason. It is then deleting the remote file and rebuilding it.

Did you kill the backup last it ran, or is there some issue with files going broken on the remote end?

1 Like

@JonMikelV
I do not have the HDD space to do a local backup to another machine on the LAN, but I could try with a smaller backup set.

@kenkendk
The backup was stopped, not killed. But I selected not to wait on the upload to complete. Does the "removing incomplete file … take such long time?

Anyhow. The VM ran out of space due to the logfile and maybe tmp over the weekend, so now I have set the log-file location and TMPDIR variable to an NFS share. So hopefully, this will remove all the space issues.

After setting --check-filetime-only the speed Duplicati to start Verifying backend data …, is much faster. The remaining problems is:

  • Using a long time (2 hours +) to verify the backend
  • Pretty slow going through existing files.

I made a video of the web interface when it’s processing files, and would appreciate if you could take a look and tell me if this is “normal” or extremely slow.

That operation should only delete the remote file(s) and as such be quite fast. It may take some time if one of the files to delete references local data. In such a case there are some collateral in the database that needs cleaning up.

That looks very slow, but it seems to “stop” so I am assuming it just keeps at it, but the message is the same.

I have uploaded a new canary build: Releases · duplicati/duplicati · GitHub

This new version has a new advanced option --use-block-cache, which can be used to speed up the lookups that are slow in your case. This does require some memory (>300mb of RAM pr. TB of data), but if you have a non-SSD disk, I think it could give some results.

1 Like