An example of a profiling log to read a dlist
of a backup of C:\backup source\A.txt looks is below.
2023-03-15 18:40:14 -04 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingFilelistVolumes]: Processing filelist volume 1 of 2
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Fileset" ("OperationID", "Timestamp", "VolumeID", "IsFullBackup") VALUES (1, 1678919836, 1, 0); SELECT last_insert_rowid();
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Fileset" ("OperationID", "Timestamp", "VolumeID", "IsFullBackup") VALUES (1, 1678919836, 1, 0); SELECT last_insert_rowid(); took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "Fileset" SET "IsFullBackup" = True WHERE "ID" = 1;
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "Fileset" SET "IsFullBackup" = True WHERE "ID" = 1; took 0:00:00:00.001
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "PathPrefix" WHERE "Prefix" = "C:\backup source\"
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "PathPrefix" WHERE "Prefix" = "C:\backup source\" took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "PathPrefix" ("Prefix") VALUES ("C:\backup source\"); SELECT last_insert_rowid();
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "PathPrefix" ("Prefix") VALUES ("C:\backup source\"); SELECT last_insert_rowid(); took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Blockset" WHERE "Length" = 1 AND "FullHash" = "VZrq0IJk1XldOQlxjN0Fq9SVcuhP5VWQ7vMaiKCP3/0="
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "Blockset" WHERE "Length" = 1 AND "FullHash" = "VZrq0IJk1XldOQlxjN0Fq9SVcuhP5VWQ7vMaiKCP3/0=" took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Blockset" ("Length", "FullHash") VALUES (1,"VZrq0IJk1XldOQlxjN0Fq9SVcuhP5VWQ7vMaiKCP3/0="); SELECT last_insert_rowid();
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Blockset" ("Length", "FullHash") VALUES (1,"VZrq0IJk1XldOQlxjN0Fq9SVcuhP5VWQ7vMaiKCP3/0="); SELECT last_insert_rowid(); took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "Metadataset"."ID" FROM "Metadataset","Blockset" WHERE "Metadataset"."BlocksetID" = "Blockset"."ID" AND "Blockset"."FullHash" = "UW7CCxtLGw1gqSW6qxiGU8Xd/arQWsoW55bRZeAeQug=" AND "Blockset"."Length" = 137
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "Metadataset"."ID" FROM "Metadataset","Blockset" WHERE "Metadataset"."BlocksetID" = "Blockset"."ID" AND "Blockset"."FullHash" = "UW7CCxtLGw1gqSW6qxiGU8Xd/arQWsoW55bRZeAeQug=" AND "Blockset"."Length" = 137 took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Blockset" WHERE "Length" = 137 AND "FullHash" = "UW7CCxtLGw1gqSW6qxiGU8Xd/arQWsoW55bRZeAeQug="
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "Blockset" WHERE "Length" = 137 AND "FullHash" = "UW7CCxtLGw1gqSW6qxiGU8Xd/arQWsoW55bRZeAeQug=" took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Blockset" ("Length", "FullHash") VALUES (137,"UW7CCxtLGw1gqSW6qxiGU8Xd/arQWsoW55bRZeAeQug="); SELECT last_insert_rowid();
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Blockset" ("Length", "FullHash") VALUES (137,"UW7CCxtLGw1gqSW6qxiGU8Xd/arQWsoW55bRZeAeQug="); SELECT last_insert_rowid(); took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Metadataset" ("BlocksetID") VALUES (2); SELECT last_insert_rowid();
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Metadataset" ("BlocksetID") VALUES (2); SELECT last_insert_rowid(); took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "FileLookup" WHERE "PrefixID" = 1 AND "Path" = "A.txt" AND "BlocksetID" = 1 AND "MetadataID" = 1
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "FileLookup" WHERE "PrefixID" = 1 AND "Path" = "A.txt" AND "BlocksetID" = 1 AND "MetadataID" = 1 took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "FileLookup" ("PrefixID", "Path", "BlocksetID", "MetadataID") VALUES (1,"A.txt",1,1); SELECT last_insert_rowid();
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "FileLookup" ("PrefixID", "Path", "BlocksetID", "MetadataID") VALUES (1,"A.txt",1,1); SELECT last_insert_rowid(); took 0:00:00:00.000
The “Fileset” work at the top is probably once per dlist
, but each file probably deals with “Blockset” (file data), “MetadataSet” (file attributes), “PathPrefix”, and “FileLookup”. The latter two form a space-efficient way to store the file path. Previously it stored full path intact. Now it stores the path’s prefix separately…
Looking at a second backup where file B.txt was added, one can see it finishing similarly and moving on.
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "FileLookup" ("PrefixID", "Path", "BlocksetID", "MetadataID") VALUES (1,"B.txt",3,2); SELECT last_insert_rowid(); took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "Key", "Value" FROM "Configuration" took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Block" WHERE "Size" > 102400
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT COUNT(*) FROM "Block" WHERE "Size" > 102400 took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Configuration"
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Configuration" took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("blocksize", "102400")
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("blocksize", "102400") took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("blockhash", "SHA256")
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("blockhash", "SHA256") took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("filehash", "SHA256")
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("filehash", "SHA256") took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("passphrase", "no-encryption")
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("passphrase", "no-encryption") took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("repair-in-progress", "true")
2023-03-15 18:40:14 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Configuration" ("Key", "Value") VALUES ("repair-in-progress", "true") took 0:00:00:00.000
2023-03-15 18:40:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-CommitUpdateFilesetFromRemote]: Starting - CommitUpdateFilesetFromRemote
2023-03-15 18:40:15 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-CommitUpdateFilesetFromRemote]: CommitUpdateFilesetFromRemote took 0:00:00:00.141
2023-03-15 18:40:15 -04 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-FilelistsRestored]: Filelists restored, downloading 2 index files
For testing (because system is slow and there are lots of versions), add --version=0
to just do latest.
This might also prove or disprove a wild guess that you ran out of /tmp space by doing so many dlist
.
Unable to recreate database, fails with “SQLite error cannot rollback - no transaction is active”
has a similar-looking stack, found by Google search on a couple of the things you had. Thanks for that.