duplicati/duplicati

Duplicati commandline list took hours

Open

#2,468 opened on May 9, 2017

View on GitHub
 (1 comment) (0 reactions) (0 assignees)C# (1,042 forks)batch import
enhancementhelp wantedperformance issue

Repository metrics

Stars
 (14,539 stars)
PR merge metrics
 (Avg merge 2d) (53 merged PRs in 30d)

Description

Hello, listing file in backup versions took nearly two hours, I don't know if is bug, but in log you can see query running 1,5 hours.

Helo: My backup: Source 800GB Backup 540GB 104 versions Sqlite DB have 3GB size Duplicati 2.0.1.53 Windows FTP

Running command:

duplicati.commandline list --dbpath="C:\Programy\Duplicati2_home\LBOUAFEXVG.sqlite" "ftp connections striing" "path/to/file/in/backup.doc" --tempdir=D:\Duplicati2_TEMP\commandlinetemp --log-file="D:\Duplicati2_TEMP\commandlinetemp\log.log" --debug-output --log-level=Profiling ---debug-retry-errors

This query took nearly two hours:

2017-05-04 21:39:38Z - Profiling: ExecuteReader: SELECT "C"."Path", "D"."Length", "C"."FilesetID" FROM (SELECT "A"."Path", "B"."FilesetID" FROM "Filenames-713E76757068BD4F929AFF7D55559DC5" A, (SELECT "FilesetID", "Timestamp" FROM "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" 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" ) D ON "C"."FilesetID" = "D"."FilesetID" AND "C"."Path" = "D"."Path" 
took 01:38:50.135

Full log:

2017-05-04 19:53:42Z - Profiling: Starting - Running List
2017-05-04 19:53:42Z - Profiling: Starting - ExecuteScalar: INSERT INTO "Operation" ("Description", "Timestamp") VALUES (?, ?); SELECT last_insert_rowid();
2017-05-04 19:53:42Z - Profiling: ExecuteScalar: INSERT INTO "Operation" ("Description", "Timestamp") VALUES (?, ?); SELECT last_insert_rowid(); took 00:00:00.031
2017-05-04 19:53:42Z - Profiling: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC
2017-05-04 19:53:42Z - Profiling: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 00:00:00.000
2017-05-04 19:53:42Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" AS SELECT DISTINCT "ID" AS "FilesetID", "Timestamp" AS "Timestamp" FROM "Fileset" 
2017-05-04 19:53:42Z - Profiling: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" AS SELECT DISTINCT "ID" AS "FilesetID", "Timestamp" AS "Timestamp" FROM "Fileset"  took 00:00:00.031
2017-05-04 19:53:42Z - Profiling: Starting - ExecuteNonQuery: CREATE INDEX "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2_FilesetIDTimestampIndex" ON "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" ("FilesetID", "Timestamp" DESC)
2017-05-04 19:53:42Z - Profiling: ExecuteNonQuery: CREATE INDEX "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2_FilesetIDTimestampIndex" ON "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" ("FilesetID", "Timestamp" DESC) took 00:00:00.000
2017-05-04 19:53:42Z - Profiling: Starting - ExecuteReader: SELECT DISTINCT "A"."FilesetID", "B"."FileCount", "B"."FileSizes" FROM "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" 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" GROUP BY "A"."FilesetID"  ) B ON "A"."FilesetID" = "B"."FilesetID" ORDER BY "A"."Timestamp" DESC 
2017-05-04 19:56:48Z - Profiling: ExecuteReader: SELECT DISTINCT "A"."FilesetID", "B"."FileCount", "B"."FileSizes" FROM "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" 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" GROUP BY "A"."FilesetID"  ) B ON "A"."FilesetID" = "B"."FilesetID" ORDER BY "A"."Timestamp" DESC  took 00:03:05.657
2017-05-04 19:56:48Z - Profiling: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-713E76757068BD4F929AFF7D55559DC5" ("Path" TEXT NOT NULL)
2017-05-04 19:56:48Z - Profiling: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-713E76757068BD4F929AFF7D55559DC5" ("Path" TEXT NOT NULL) took 00:00:00.000
2017-05-04 19:56:48Z - Profiling: Starting - ExecuteReader: SELECT DISTINCT "Path" FROM "File" 
2017-05-04 19:56:48Z - Profiling: ExecuteReader: SELECT DISTINCT "Path" FROM "File"  took 00:00:00.000
2017-05-04 19:56:51Z - Profiling: Starting - ExecuteNonQuery: DELETE FROM "Filenames-713E76757068BD4F929AFF7D55559DC5" WHERE "Path" NOT IN (SELECT DISTINCT "Path" FROM "File", "FilesetEntry" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" IN (SELECT "FilesetID" FROM "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2") ) 
2017-05-04 20:00:47Z - Profiling: ExecuteNonQuery: DELETE FROM "Filenames-713E76757068BD4F929AFF7D55559DC5" WHERE "Path" NOT IN (SELECT DISTINCT "Path" FROM "File", "FilesetEntry" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" IN (SELECT "FilesetID" FROM "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2") )  took 00:03:56.821
2017-05-04 20:00:47Z - Profiling: Starting - ExecuteReader: SELECT "C"."Path", "D"."Length", "C"."FilesetID" FROM (SELECT "A"."Path", "B"."FilesetID" FROM "Filenames-713E76757068BD4F929AFF7D55559DC5" A, (SELECT "FilesetID", "Timestamp" FROM "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" 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" ) D ON "C"."FilesetID" = "D"."FilesetID" AND "C"."Path" = "D"."Path"
2017-05-04 21:39:38Z - Profiling: ExecuteReader: SELECT "C"."Path", "D"."Length", "C"."FilesetID" FROM (SELECT "A"."Path", "B"."FilesetID" FROM "Filenames-713E76757068BD4F929AFF7D55559DC5" A, (SELECT "FilesetID", "Timestamp" FROM "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" 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" ) D ON "C"."FilesetID" = "D"."FilesetID" AND "C"."Path" = "D"."Path" took 01:38:50.135
2017-05-04 21:39:38Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-713E76757068BD4F929AFF7D55559DC5" 
2017-05-04 21:39:38Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-713E76757068BD4F929AFF7D55559DC5"  took 00:00:00.000
2017-05-04 21:39:38Z - Profiling: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2" 
2017-05-04 21:39:38Z - Profiling: ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-6EFDD08F79EE8546BA8B74889C9B10B2"  took 00:00:00.000
2017-05-04 21:39:38Z - Profiling: Running List took 01:45:55.786

Contributor guide

Research direction
Analyze the slow SQL query in the log, identify the bottleneck (e.g., Cartesian join, missing indexes on temp tables), and propose optimizations such as adding indexes, rewriting the query to reduce rows, or using more efficient queries.
Tech stack
csharpsqlite
Domain
backendcli
Issue type
Bug
DifficultyEstimated implementation difficulty for a new contributor, from 1 for very small changes to 5 for expert-level work.
3
Estimated timeA rough time range for an experienced contributor to investigate, implement, test, and prepare a pull request.
Half day
Activity statusHow available the issue appears right now: fresh, active, stale, blocked, or waiting on maintainer input.
Stale
ClarityHow clearly the issue explains the expected change, acceptance criteria, and next step.
Clear
Prerequisites
SQLC#
Newbie friendlinessA 1-100 score estimating how approachable this issue is for first-time contributors.
30