Hello, this problem started just after updating to Duplicati - 2.0.3.6_canary_20…18-04-23
- **Duplicati version**: Duplicati - 2.0.3.6_canary_2018-04-23
- **Operating system**: Windows 7
- **Backend**: SMB
Source:164.11 GB
Backup:118.73 GB / 40 Versions
## Description
On Canary 2.0.3.5 backup was working fine, backup size is 160GB and backup time was 30 -90 min
On 2.0.3.6 backup took **11 hours** and it was stuck on Verifying backend data ...
This query was ran **six times** and it always took 1 to 2 hours
_
> Line 21089: 2018-04-26 13:33:20 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExcuteReader]: 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" took **0:02:13:26.624**_
--
## Debug log
Occurrence of this long query in log (took time is at end of line)
`Line 21089: 2018-04-26 13:33:20 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExcuteReader]: 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" took 0:02:13:26.624
Line 371167: 2018-04-26 15:33:11 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExcuteReader]: 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" took 0:01:44:38.428
Line 484220: 2018-04-26 17:56:10 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExcuteReader]: 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" took 0:02:14:46.368
Line 484436: 2018-04-26 19:07:36 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExcuteReader]: 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" took 0:01:11:21.798
Line 497246: 2018-04-26 21:10:58 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExcuteReader]: 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" took 0:01:58:34.964
Line 498851: 2018-04-26 23:03:58 +02 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExcuteReader]: 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" took 0:01:52:02.663
`
**This is log from log page**
```
DeletedFiles: 7
DeletedFolders: 0
ModifiedFiles: 32
ExaminedFiles: 2491
OpenedFiles: 38
AddedFiles: 6
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 0
SizeOfExaminedFiles: 176208452248
SizeOfOpenedFiles: 23401607077
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults:
DeletedFileCount: 0
DownloadedFileCount: 0
UploadedFileCount: 0
DeletedFileSize: 0
DownloadedFileSize: 0
UploadedFileSize: 0
Dryrun: False
MainOperation: Compact
ParsedResult: Success
EndTime: 26.4.2018 23:08:46 (1524776926)
BeginTime: 26.4.2018 23:07:33 (1524776853)
Duration: 00:01:13.1766892
Messages: [
2018-04-26 11:19:21 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-04-26 11:19:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (4.83 KB),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-b84733bd4fc52468c890cd9954498e5de.dblock.zip,
2018-04-26 13:33:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ib46e4cab519b4b2eb050b9adcf7c7ef9.dindex.zip (35.59 KB),
...
]
Warnings: []
Errors: []
TaskReader: null
BackendStatistics:
RemoteCalls: 18
BytesUploaded: 254463608
BytesDownloaded: 52719985
FilesUploaded: 12
FilesDownloaded: 3
FilesDeleted: 1
FoldersCreated: 0
RetryAttempts: 0
UnknownFileSize: 0
UnknownFileCount: 0
KnownFileCount: 4962
KnownFileSize: 127489279138
LastBackupDate: 26.4.2018 11:19:22 (1524734362)
BackupListCount: 40
TotalQuotaSpace: 3000591446016
FreeQuotaSpace: 14693453824
AssignedQuotaSpace: -1
ReportedQuotaError: False
ReportedQuotaWarning: False
ParsedResult: Success
Messages: [
2018-04-26 11:19:21 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-04-26 11:19:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (4.83 KB),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-b84733bd4fc52468c890cd9954498e5de.dblock.zip,
2018-04-26 13:33:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ib46e4cab519b4b2eb050b9adcf7c7ef9.dindex.zip (35.59 KB),
...
]
Warnings: []
Errors: []
TaskReader: null
DeleteResults:
DeletedSets: [
Item1: 40
Item2: 22.2.2018 0:00:03 (1519254003)
]
Dryrun: False
MainOperation: Delete
ParsedResult: Success
EndTime: 26.4.2018 23:08:46 (1524776926)
BeginTime: 26.4.2018 23:03:59 (1524776639)
Duration: 00:04:47.8055660
Messages: [
2018-04-26 11:19:21 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-04-26 11:19:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (4.83 KB),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-b84733bd4fc52468c890cd9954498e5de.dblock.zip,
2018-04-26 13:33:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ib46e4cab519b4b2eb050b9adcf7c7ef9.dindex.zip (35.59 KB),
...
]
Warnings: []
Errors: []
TaskReader: null
RepairResults: null
TestResults:
MainOperation: Test
Verifications: [
Key: duplicati-20180426T091922Z.dlist.zip
Value: [],
Key: duplicati-i77b5b957730840fc874d65fabf048f8c.dindex.zip
Value: [],
Key: duplicati-bd91d6d1699884bf086fd4a13a381fd49.dblock.zip
Value: []
]
ParsedResult: Success
EndTime: 26.4.2018 23:08:57 (1524776937)
BeginTime: 26.4.2018 23:08:53 (1524776933)
Duration: 00:00:03.7838309
Messages: [
2018-04-26 11:19:21 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-04-26 11:19:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (4.83 KB),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-b84733bd4fc52468c890cd9954498e5de.dblock.zip,
2018-04-26 13:33:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ib46e4cab519b4b2eb050b9adcf7c7ef9.dindex.zip (35.59 KB),
...
]
Warnings: []
Errors: []
TaskReader: null
ParsedResult: Success
EndTime: 26.4.2018 23:08:57 (1524776937)
BeginTime: 26.4.2018 11:19:21 (1524734361)
Duration: 11:49:35.4379851
Messages: [
2018-04-26 11:19:21 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-04-26 11:19:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (4.83 KB),
2018-04-26 11:19:53 +02 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-b84733bd4fc52468c890cd9954498e5de.dblock.zip,
2018-04-26 13:33:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ib46e4cab519b4b2eb050b9adcf7c7ef9.dindex.zip (35.59 KB),
...
]
Warnings: []
Errors: []
TaskReader:
ProgressAsync:
Result: True
Factory:
CancellationToken:
IsCancellationRequested: False
CanBeCanceled: False
WaitHandle:
Handle: 668
SafeWaitHandle:
IsInvalid: False
IsClosed: False
Scheduler: null
CreationOptions: None
ContinuationOptions: None
Id: 38
Exception: null
Status: RanToCompletion
IsCanceled: False
IsCompleted: True
CreationOptions: None
AsyncState: null
IsFaulted: False
TransferProgressAsync:
Result: True
Id: 39
Exception: null
Status: RanToCompletion
IsCanceled: False
IsCompleted: True
CreationOptions: None
AsyncState: null
IsFaulted: False
```