What makes a test phase run slow?

Support
1

Anything I can do to improve it? Backup runs fast, all other phases seem to run fast, test phase is very slow.

{
  "DeletedFiles": 2439,
  "DeletedFolders": 5,
  "ModifiedFiles": 951,
  "ExaminedFiles": 84112,
  "OpenedFiles": 3404,
  "AddedFiles": 2453,
  "SizeOfModifiedFiles": 608878775,
  "SizeOfAddedFiles": 63141704,
  "SizeOfExaminedFiles": 25348071811,
  "SizeOfOpenedFiles": 782168046,
  "NotProcessedFiles": 0,
  "AddedFolders": 5,
  "TooLargeFiles": 0,
  "FilesWithError": 0,
  "ModifiedFolders": 0,
  "ModifiedSymlinks": 0,
  "AddedSymlinks": 2,
  "DeletedSymlinks": 2,
  "PartialBackup": false,
  "Dryrun": false,
  "MainOperation": "Backup",
  "CompactResults": {
    "DeletedFileCount": 0,
    "DownloadedFileCount": 0,
    "UploadedFileCount": 0,
    "DeletedFileSize": 0,
    "DownloadedFileSize": 0,
    "UploadedFileSize": 0,
    "Dryrun": false,
    "VacuumResults": null,
    "MainOperation": "Compact",
    "ParsedResult": "Success",
    "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
    "EndTime": "2021-07-14T10:51:19.339696Z",
    "BeginTime": "2021-07-14T10:51:17.129306Z",
    "Duration": "00:00:02.2103900",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 10,
      "BytesUploaded": 64910391,
      "BytesDownloaded": 531149735,
      "FilesUploaded": 3,
      "FilesDownloaded": 3,
      "FilesDeleted": 2,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 160,
      "KnownFileSize": 25886103008,
      "LastBackupDate": "2021-07-14T05:46:07-05:00",
      "BackupListCount": 21,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2021-07-14T10:46:07.639905Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "VacuumResults": null,
  "DeleteResults": {
    "DeletedSetsActualLength": 2,
    "DeletedSets": [
      {
        "Item1": 8,
        "Item2": "2021-07-06T11:59:11-05:00"
      },
      {
        "Item1": 7,
        "Item2": "2021-07-07T05:10:00-05:00"
      }
    ],
    "Dryrun": false,
    "MainOperation": "Delete",
    "CompactResults": {
      "DeletedFileCount": 0,
      "DownloadedFileCount": 0,
      "UploadedFileCount": 0,
      "DeletedFileSize": 0,
      "DownloadedFileSize": 0,
      "UploadedFileSize": 0,
      "Dryrun": false,
      "VacuumResults": null,
      "MainOperation": "Compact",
      "ParsedResult": "Success",
      "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
      "EndTime": "2021-07-14T10:51:19.339696Z",
      "BeginTime": "2021-07-14T10:51:17.129306Z",
      "Duration": "00:00:02.2103900",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null,
      "BackendStatistics": {
        "RemoteCalls": 10,
        "BytesUploaded": 64910391,
        "BytesDownloaded": 531149735,
        "FilesUploaded": 3,
        "FilesDownloaded": 3,
        "FilesDeleted": 2,
        "FoldersCreated": 0,
        "RetryAttempts": 0,
        "UnknownFileSize": 0,
        "UnknownFileCount": 0,
        "KnownFileCount": 160,
        "KnownFileSize": 25886103008,
        "LastBackupDate": "2021-07-14T05:46:07-05:00",
        "BackupListCount": 21,
        "TotalQuotaSpace": 0,
        "FreeQuotaSpace": 0,
        "AssignedQuotaSpace": -1,
        "ReportedQuotaError": false,
        "ReportedQuotaWarning": false,
        "MainOperation": "Backup",
        "ParsedResult": "Success",
        "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
        "EndTime": "0001-01-01T00:00:00",
        "BeginTime": "2021-07-14T10:46:07.639905Z",
        "Duration": "00:00:00",
        "MessagesActualLength": 0,
        "WarningsActualLength": 0,
        "ErrorsActualLength": 0,
        "Messages": null,
        "Warnings": null,
        "Errors": null
      }
    },
    "ParsedResult": "Success",
    "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
    "EndTime": "2021-07-14T10:51:19.339698Z",
    "BeginTime": "2021-07-14T10:51:14.71892Z",
    "Duration": "00:00:04.6207780",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 10,
      "BytesUploaded": 64910391,
      "BytesDownloaded": 531149735,
      "FilesUploaded": 3,
      "FilesDownloaded": 3,
      "FilesDeleted": 2,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 160,
      "KnownFileSize": 25886103008,
      "LastBackupDate": "2021-07-14T05:46:07-05:00",
      "BackupListCount": 21,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2021-07-14T10:46:07.639905Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "RepairResults": null,
  "TestResults": {
    "MainOperation": "Test",
    "VerificationsActualLength": 3,
    "Verifications": [
      {
        "Key": "duplicati-20210711T111417Z.dlist.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-i0af0b2bf794d47e49840e11b7dae9df5.dindex.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-b36ff1eab37e9445db40615a63ee19db2.dblock.zip.aes",
        "Value": []
      }
    ],
    "ParsedResult": "Success",
    "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
    "EndTime": "2021-07-14T12:30:03.545956Z",
    "BeginTime": "2021-07-14T10:51:20.841401Z",
    "Duration": "01:38:42.7045550",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 10,
      "BytesUploaded": 64910391,
      "BytesDownloaded": 531149735,
      "FilesUploaded": 3,
      "FilesDownloaded": 3,
      "FilesDeleted": 2,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 160,
      "KnownFileSize": 25886103008,
      "LastBackupDate": "2021-07-14T05:46:07-05:00",
      "BackupListCount": 21,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2021-07-14T10:46:07.639905Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "ParsedResult": "Success",
  "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
  "EndTime": "2021-07-14T12:30:03.677812Z",
  "BeginTime": "2021-07-14T10:46:07.639902Z",
  "Duration": "01:43:56.0379100",
  "MessagesActualLength": 29,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 0,
  "Messages": [
    "2021-07-14 05:46:07 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
    "2021-07-14 05:46:14 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2021-07-14 05:46:16 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (159 bytes)",
    "2021-07-14 05:47:59 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ba1faffdcdf3342789c02321dd3d6cdce.dblock.zip.aes (55.63 MB)",
    "2021-07-14 05:50:51 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ba1faffdcdf3342789c02321dd3d6cdce.dblock.zip.aes (55.63 MB)",
    "2021-07-14 05:50:51 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i8333bb4d17684e259144e1f9d94fadcd.dindex.zip.aes (270.20 KB)",
    "2021-07-14 05:50:53 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i8333bb4d17684e259144e1f9d94fadcd.dindex.zip.aes (270.20 KB)",
    "2021-07-14 05:50:53 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20210714T104607Z.dlist.zip.aes (6.01 MB)",
    "2021-07-14 05:51:14 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20210714T104607Z.dlist.zip.aes (6.01 MB)",
    "2021-07-14 05:51:14 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed",
    "2021-07-14 05:51:14 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / Keep all, 90.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00",
    "2021-07-14 05:51:14 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 7/13/2021 5:25:21 AM, 7/12/2021 5:28:44 AM, 7/11/2021 6:14:17 AM, 7/10/2021 6:19:14 AM, 7/9/2021 6:48:08 AM, 7/8/2021 6:50:01 AM, 7/7/2021 5:10:00 AM, 7/6/2021 11:59:11 AM, 7/4/2021 4:19:38 PM, 6/26/2021 1:36:27 PM, 6/18/2021 5:29:41 AM, 6/11/2021 5:23:07 AM, 6/4/2021 5:21:11 AM, 5/27/2021 5:45:56 AM, 5/20/2021 5:23:43 AM, 5/12/2021 5:47:31 AM, 5/4/2021 3:14:34 PM, 4/27/2021 5:42:49 AM, 4/20/2021 5:11:01 AM, 3/21/2021 5:21:26 AM, 3/13/2021 4:33:47 AM, 2/11/2021 10:42:21 AM",
    "2021-07-14 05:51:14 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: ",
    "2021-07-14 05:51:14 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: 7/7/2021 5:10:00 AM, 7/6/2021 11:59:11 AM",
    "2021-07-14 05:51:14 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 2 remote fileset(s) ...",
    "2021-07-14 05:51:16 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20210706T165911Z.dlist.zip.aes (6.03 MB)",
    "2021-07-14 05:51:16 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-20210706T165911Z.dlist.zip.aes (6.03 MB)",
    "2021-07-14 05:51:16 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20210707T101000Z.dlist.zip.aes (6.03 MB)",
    "2021-07-14 05:51:16 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-20210707T101000Z.dlist.zip.aes (6.03 MB)",
    "2021-07-14 05:51:17 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: Deleted 2 remote fileset(s)"
  ],
  "Warnings": [],
  "Errors": [],
  "BackendStatistics": {
    "RemoteCalls": 10,
    "BytesUploaded": 64910391,
    "BytesDownloaded": 531149735,
    "FilesUploaded": 3,
    "FilesDownloaded": 3,
    "FilesDeleted": 2,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 160,
    "KnownFileSize": 25886103008,
    "LastBackupDate": "2021-07-14T05:46:07-05:00",
    "BackupListCount": 21,
    "TotalQuotaSpace": 0,
    "FreeQuotaSpace": 0,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Backup",
    "ParsedResult": "Success",
    "Version": "2.0.5.114 (2.0.5.114_canary_2021-03-10)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2021-07-14T10:46:07.639905Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}
2

It depends on what’s making it slow. What’s the destination, and is it pretty fast? Is all of the network fast?
The test is downloads and a hash run of the files. Unless source system is slow, transfer might be cause.
Your transfer rate is below 1 Megabit per second, which is very slow, but ADSL transfers are in that range.

It looks like the screen 5 Options Remote volume size is set higher than the default of 50 MB. How high?
Generally the test download size is dominated the the dblock file (remote volume). Is yours 500 MB or up?

"BytesDownloaded": 531149735,
...
"FilesDownloaded": 3,

is 1 set of 3 files usually downloaded by Verifying backend files after backup, based on TEST command.
backup-test-samples can lower this, but setting it to 0 leaves you more blind to potential backup damage.
If you have slow downloads, you’ll also suffer if you ever have to download data to actually restore things.

You can get a rough time of download at About → Show log → Live → Information and watch downloads.

3

I think something is wrong with the server, I am seeing 50 KB/s at times (download), super slow. Internet here is fast and reliable, not the issue. Connection is sftp. Server at provider was moved a month or so ago and likely something is wrong from that.

So, I think you’re right in other words. Interestingly, I can send files to the external server at full speed, way faster than download. Opening ticket.

1 Like