Tell me what you need to do these tests, and I will gladly provide it. I am a newbie to Duplicati, and if getting profiles would help then please tell me how to do it. Also, I experienced long delays in restoring from via the CLI, so I don’t think it is solely a browser issue. Rich
Thank you. Here are some directions. Please also check to see if this is like the test you’re doing.
For a live log at profiling level, set this up (perhaps in another tab) before expanding the subfolder.
You might also see different speeds at different spots, but you say subfolders do it, so get to one.
That’s the test I just set up, and I’m going to expand subfolder 000000, but first set up the logging:
Click About
Click Show log
Click Live
Pick Profiling
Expand the subfolder in the other tab. Go back to the log, browser-search for took, find slow ones:
Mar 10, 2021 5:04 PM: ExecuteReader: SELECT “C”.“Path”, “D”.“Length”, “C”.“FilesetID” FROM (SELECT “A”.“Path”, “B”.“FilesetID” FROM “Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A” A, (SELECT “FilesetID”, “Timestamp” FROM “Filesets-53BD631CFE8F3D43B4058F28E5822F2C” ORDER BY “Timestamp” DESC) B ORDER BY “A”.“Path” ASC, “B”.“Timestamp” DESC) C LEFT OUTER JOIN (SELECT “Length”, “FilesetEntry”.“FilesetID”, “File”.“Path” FROM “Blockset”, “FilesetEntry”, “File” WHERE “File”.“BlocksetID” = “Blockset”.“ID” AND “FilesetEntry”.“FileID” = “File”.“ID” AND FilesetEntry.“FilesetID” IN (SELECT DISTINCT “FilesetID” FROM “Filesets-53BD631CFE8F3D43B4058F28E5822F2C”) ) D ON “C”.“FilesetID” = “D”.“FilesetID” AND “C”.“Path” = “D”.“Path” took 0:00:00:04.849
Mar 10, 2021 5:04 PM: ExecuteNonQuery: DELETE FROM “Filenames-79C7F442264FA045953CB56D10A8CA7C” WHERE “Path” NOT IN (SELECT DISTINCT “Path” FROM “File”, “FilesetEntry” WHERE “FilesetEntry”.“FileID” = “File”.“ID” AND “FilesetEntry”.“FilesetID” IN (SELECT “FilesetID” FROM “Filesets-53BD631CFE8F3D43B4058F28E5822F2C”) ) took 0:00:00:08.663
The live log is reverse-chronological. The top item is the SQL I pointed to before, but there’s a new slow one that hpapened before it. Expand was done at 5:04:00, and the UI subfolder list came in 17 seconds:
Live log doesn’t show seconds, but if you go to the Options screen 5, and use the Advanced options:
log-file and set the value to a place you can write the log file to.
log-file-log-level and pick Profiling.
that will make a rapidly-growing log when action starts (so maybe uncheck log-file when not testing) and
expand that I did before wound up putting the same information (with seconds) in chronological log lines:
2021-03-10 17:04:00 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2021-03-10 17:04:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Controller-RunList]: Starting - Running List
2021-03-10 17:04:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("List", 1615413840); SELECT last_insert_rowid();
2021-03-10 17:04:00 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("List", 1615413840); SELECT last_insert_rowid(); took 0:00:00:00.083
2021-03-10 17:04:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC
2021-03-10 17:04:00 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 0:00:00:00.000
2021-03-10 17:04:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" AS SELECT DISTINCT "ID" AS "FilesetID", "IsFullBackup" AS "IsFullBackup" , "Timestamp" AS "Timestamp" FROM "Fileset" WHERE "Timestamp" <= 1615400983
2021-03-10 17:04:00 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" AS SELECT DISTINCT "ID" AS "FilesetID", "IsFullBackup" AS "IsFullBackup" , "Timestamp" AS "Timestamp" FROM "Fileset" WHERE "Timestamp" <= 1615400983 took 0:00:00:00.000
2021-03-10 17:04:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE INDEX "Filesets-53BD631CFE8F3D43B4058F28E5822F2C_FilesetIDTimestampIndex" ON "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" ("FilesetID", "Timestamp" DESC)
2021-03-10 17:04:00 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE INDEX "Filesets-53BD631CFE8F3D43B4058F28E5822F2C_FilesetIDTimestampIndex" ON "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" ("FilesetID", "Timestamp" DESC) took 0:00:00:00.000
2021-03-10 17:04:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" WHERE "FilesetID" NOT IN (SELECT "FilesetID" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" ORDER BY "Timestamp" DESC LIMIT 1 )
2021-03-10 17:04:00 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" WHERE "FilesetID" NOT IN (SELECT "FilesetID" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" ORDER BY "Timestamp" DESC LIMIT 1 ) took 0:00:00:00.000
2021-03-10 17:04:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT DISTINCT "A"."FilesetID", "A"."IsFullBackup", "B"."FileCount", "B"."FileSizes" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" A LEFT OUTER JOIN ( SELECT "A"."FilesetID" AS "FilesetID", COUNT(*) AS "FileCount", SUM("C"."Length") AS "FileSizes" FROM "FilesetEntry" A, "File" B, "Blockset" C WHERE "A"."FileID" = "B"."ID" AND "B"."BlocksetID" = "C"."ID" AND "A"."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C") GROUP BY "A"."FilesetID" ) B ON "A"."FilesetID" = "B"."FilesetID" ORDER BY "A"."Timestamp" DESC
2021-03-10 17:04:01 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT DISTINCT "A"."FilesetID", "A"."IsFullBackup", "B"."FileCount", "B"."FileSizes" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" A LEFT OUTER JOIN ( SELECT "A"."FilesetID" AS "FilesetID", COUNT(*) AS "FileCount", SUM("C"."Length") AS "FileSizes" FROM "FilesetEntry" A, "File" B, "Blockset" C WHERE "A"."FileID" = "B"."ID" AND "B"."BlocksetID" = "C"."ID" AND "A"."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C") GROUP BY "A"."FilesetID" ) B ON "A"."FilesetID" = "B"."FilesetID" ORDER BY "A"."Timestamp" DESC took 0:00:00:00.617
2021-03-10 17:04:01 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-79C7F442264FA045953CB56D10A8CA7C" ("Path" TEXT NOT NULL)
2021-03-10 17:04:01 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-79C7F442264FA045953CB56D10A8CA7C" ("Path" TEXT NOT NULL) took 0:00:00:00.000
2021-03-10 17:04:01 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "Filenames-79C7F442264FA045953CB56D10A8CA7C" SELECT DISTINCT "Path" FROM "File" WHERE "Path" LIKE "C:\TMP\TREE\000000\%"
2021-03-10 17:04:02 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Filenames-79C7F442264FA045953CB56D10A8CA7C" SELECT DISTINCT "Path" FROM "File" WHERE "Path" LIKE "C:\TMP\TREE\000000\%" took 0:00:00:00.775
2021-03-10 17:04:02 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Filenames-79C7F442264FA045953CB56D10A8CA7C" WHERE "Path" NOT IN (SELECT DISTINCT "Path" FROM "File", "FilesetEntry" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" IN (SELECT "FilesetID" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C") )
2021-03-10 17:04:10 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Filenames-79C7F442264FA045953CB56D10A8CA7C" WHERE "Path" NOT IN (SELECT DISTINCT "Path" FROM "File", "FilesetEntry" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" IN (SELECT "FilesetID" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C") ) took 0:00:00:08.663
2021-03-10 17:04:10 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A" ("Path" TEXT NOT NULL)
2021-03-10 17:04:10 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A" ("Path" TEXT NOT NULL) took 0:00:00:00.000
2021-03-10 17:04:10 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT DISTINCT "Path" FROM "Filenames-79C7F442264FA045953CB56D10A8CA7C"
2021-03-10 17:04:10 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT DISTINCT "Path" FROM "Filenames-79C7F442264FA045953CB56D10A8CA7C" took 0:00:00:00.000
2021-03-10 17:04:11 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE INDEX "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A_PathIndex" ON "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A" ("Path")
2021-03-10 17:04:11 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE INDEX "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A_PathIndex" ON "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A" ("Path") took 0:00:00:00.000
2021-03-10 17:04:11 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "C"."Path", "D"."Length", "C"."FilesetID" FROM (SELECT "A"."Path", "B"."FilesetID" FROM "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A" A, (SELECT "FilesetID", "Timestamp" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" ORDER BY "Timestamp" DESC) B ORDER BY "A"."Path" ASC, "B"."Timestamp" DESC) C LEFT OUTER JOIN (SELECT "Length", "FilesetEntry"."FilesetID", "File"."Path" FROM "Blockset", "FilesetEntry", "File" WHERE "File"."BlocksetID" = "Blockset"."ID" AND "FilesetEntry"."FileID" = "File"."ID" AND FilesetEntry."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C") ) D ON "C"."FilesetID" = "D"."FilesetID" AND "C"."Path" = "D"."Path"
2021-03-10 17:04:16 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "C"."Path", "D"."Length", "C"."FilesetID" FROM (SELECT "A"."Path", "B"."FilesetID" FROM "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A" A, (SELECT "FilesetID", "Timestamp" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" ORDER BY "Timestamp" DESC) B ORDER BY "A"."Path" ASC, "B"."Timestamp" DESC) C LEFT OUTER JOIN (SELECT "Length", "FilesetEntry"."FilesetID", "File"."Path" FROM "Blockset", "FilesetEntry", "File" WHERE "File"."BlocksetID" = "Blockset"."ID" AND "FilesetEntry"."FileID" = "File"."ID" AND FilesetEntry."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-53BD631CFE8F3D43B4058F28E5822F2C") ) D ON "C"."FilesetID" = "D"."FilesetID" AND "C"."Path" = "D"."Path" took 0:00:00:04.849
2021-03-10 17:04:16 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-79C7F442264FA045953CB56D10A8CA7C"
2021-03-10 17:04:16 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-79C7F442264FA045953CB56D10A8CA7C" took 0:00:00:00.010
2021-03-10 17:04:16 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A"
2021-03-10 17:04:16 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-27EE6D2AFEDB184D9AAD16F86B6DC17A" took 0:00:00:00.000
2021-03-10 17:04:16 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-53BD631CFE8F3D43B4058F28E5822F2C"
2021-03-10 17:04:16 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-53BD631CFE8F3D43B4058F28E5822F2C" took 0:00:00:00.000
2021-03-10 17:04:16 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: PRAGMA optimize
2021-03-10 17:04:16 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.000
2021-03-10 17:04:16 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunList]: Running List took 0:00:00:15.975
2021-03-10 17:04:16 -05 - [Information-Duplicati.Library.Main.Controller-CompletedOperation]: The operation List has completed
Although I’m not watching the network this time, it looks like the time here was in making a short subfolder listing, and the browser didn’t need much time to display the short list. I still don’t know how long yours are.
Could you give any sort of estimate of how many items are in the testing folders that you’ve been naming?
The test file maker I just wrote lets me say how many folders and files to put at a given subfolder level, and also to control how many levels I do. Test setup was 6 levels 10 subfolders and 10 files, resulting in a total 1,111,167 Files, 111,129 Folders. The files are empty. I don’t know if that matters, but my expands are fast.
Having to create a 400 GB area would fill up all the remaining space on my computer, so I’m not doing that.
FWIW, this desktop has a 1 TB mechanical drive, 32 GB of memory (but needs more), and an old Core i5.
Thanks for your interest in this. It may take a day or two to set this up, so I will have to get back to you. In the meantime, if you are interested in seeing the database, I set up a read-only phpLiteAdmin view for it, for which I could send you the password privately. Rich.