Decline in performance after update to 2.1.0.2_beta?

redusr · February 5, 2025, 11:04am

Thanks again for your help!

Okay, so one try might be to completely whitelist Duplicati and see how the run time changes.

kenkendk:

I had another idea while tracking down an unrelated issue. Duplicati 2.0.8.1 uses an integer to decide how many test samples it makes at the end of the backup. This value is called --backup-test-samples and has a default value of 1, meaning that it will test 1 of each (dlist, dindex, dblock).

Duplicati 2.1.0.3 has a new setting called --backup-test-percentage with a default value of 0.1, meaning it will sample 0.1% of the remote data after running a backup. If you have a lot of remote files, this could explain a large increase in the processing time, as many additional files are downloaded and tested.

If this is the case, you should see the main part of the backup complete as normal, but then spend a long time with the status Verifying remote data ….

If this is the case, you can revert to the previous way of testing by setting --backup-test-percentage=0.

I ran job 1 yesterday (no modifications yet) and watched the progress bar status text as well as the live log. According to that, about 10 minutes passed between the initial verification and the check for changes. After another 67 minutes it started putting (e.g., dblock.zip.aes) files and after 6 more minutes VerifyConsistency was logged and took a bit more than a minute.
There may be potential to improve performance by setting the parameter --backup-test-percentage=0 but it seems that the largest amount of time by far is spent during checking the source for changes (messages such as the ones below):

Including path as no filters matched
Skipped checking file, because no metadata was updated

Here is the log summary:

            {
  "DeletedFiles": 14944,
  "DeletedFolders": 5,
  "ModifiedFiles": 3875,
  "ExaminedFiles": 2272695,
  "OpenedFiles": 19803,
  "AddedFiles": 15928,
  "SizeOfModifiedFiles": 8332688304,
  "SizeOfAddedFiles": 1715457719,
  "SizeOfExaminedFiles": 326485205366,
  "SizeOfOpenedFiles": 10158136125,
  "NotProcessedFiles": 0,
  "AddedFolders": 1099,
  "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,
    "VacuumResults": null,
    "MainOperation": "Compact",
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
    "EndTime": "2025-02-04T15:10:28.7168682Z",
    "BeginTime": "2025-02-04T15:06:29.7155228Z",
    "Duration": "00:03:59.0013454",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 71,
      "BytesUploaded": 2913810571,
      "BytesDownloaded": 1113444396,
      "FilesUploaded": 55,
      "FilesDownloaded": 12,
      "FilesDeleted": 2,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 3666,
      "KnownFileSize": 192173271914,
      "LastBackupDate": "2025-02-04T14:32:18+01:00",
      "BackupListCount": 9,
      "TotalQuotaSpace": 536870645760,
      "FreeQuotaSpace": 254643855360,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Interrupted": false,
      "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2025-02-04T13:32:18.1436606Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "VacuumResults": null,
  "DeleteResults": {
    "DeletedSetsActualLength": 2,
    "DeletedSets": [
      {
        "Item1": 1,
        "Item2": "2025-01-14T17:32:32+01:00"
      },
      {
        "Item1": 10,
        "Item2": "2024-01-31T18:35:25+01: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",
      "Interrupted": false,
      "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
      "EndTime": "2025-02-04T15:10:28.7168682Z",
      "BeginTime": "2025-02-04T15:06:29.7155228Z",
      "Duration": "00:03:59.0013454",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null,
      "BackendStatistics": {
        "RemoteCalls": 71,
        "BytesUploaded": 2913810571,
        "BytesDownloaded": 1113444396,
        "FilesUploaded": 55,
        "FilesDownloaded": 12,
        "FilesDeleted": 2,
        "FoldersCreated": 0,
        "RetryAttempts": 0,
        "UnknownFileSize": 0,
        "UnknownFileCount": 0,
        "KnownFileCount": 3666,
        "KnownFileSize": 192173271914,
        "LastBackupDate": "2025-02-04T14:32:18+01:00",
        "BackupListCount": 9,
        "TotalQuotaSpace": 536870645760,
        "FreeQuotaSpace": 254643855360,
        "AssignedQuotaSpace": -1,
        "ReportedQuotaError": false,
        "ReportedQuotaWarning": false,
        "MainOperation": "Backup",
        "ParsedResult": "Success",
        "Interrupted": false,
        "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
        "EndTime": "0001-01-01T00:00:00",
        "BeginTime": "2025-02-04T13:32:18.1436606Z",
        "Duration": "00:00:00",
        "MessagesActualLength": 0,
        "WarningsActualLength": 0,
        "ErrorsActualLength": 0,
        "Messages": null,
        "Warnings": null,
        "Errors": null
      }
    },
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
    "EndTime": "2025-02-04T15:10:28.7173202Z",
    "BeginTime": "2025-02-04T15:03:46.5885239Z",
    "Duration": "00:06:42.1287963",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 71,
      "BytesUploaded": 2913810571,
      "BytesDownloaded": 1113444396,
      "FilesUploaded": 55,
      "FilesDownloaded": 12,
      "FilesDeleted": 2,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 3666,
      "KnownFileSize": 192173271914,
      "LastBackupDate": "2025-02-04T14:32:18+01:00",
      "BackupListCount": 9,
      "TotalQuotaSpace": 536870645760,
      "FreeQuotaSpace": 254643855360,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Interrupted": false,
      "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2025-02-04T13:32:18.1436606Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "RepairResults": null,
  "TestResults": {
    "MainOperation": "Test",
    "VerificationsActualLength": 12,
    "Verifications": [
      {
        "Key": "duplicati-20250204T133218Z.dlist.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-20241120T120144Z.dlist.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-20240709T131059Z.dlist.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-20250114T142202Z.dlist.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-i002aa1fce9a4476aad721b7d679e45a7.dindex.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-ifca5979c29b44fe190e5965060ec73fd.dindex.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-idb7ae29fbb09464482405bc993480b6c.dindex.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-i4c9ad38101454e28ad3a0a1cf6e9b16a.dindex.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-be6cccd1a66364d179b70d69880f4561c.dblock.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-bb5f3d4aab9014d238053505502012233.dblock.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-b0c3bff41d1ad4a3683eb896e87243829.dblock.zip.aes",
        "Value": []
      },
      {
        "Key": "duplicati-b26ecd2db4ffd4e38a914c88345d8d0d7.dblock.zip.aes",
        "Value": []
      }
    ],
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
    "EndTime": "2025-02-04T15:10:42.5494373Z",
    "BeginTime": "2025-02-04T15:10:32.7813976Z",
    "Duration": "00:00:09.7680397",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 71,
      "BytesUploaded": 2913810571,
      "BytesDownloaded": 1113444396,
      "FilesUploaded": 55,
      "FilesDownloaded": 12,
      "FilesDeleted": 2,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 3666,
      "KnownFileSize": 192173271914,
      "LastBackupDate": "2025-02-04T14:32:18+01:00",
      "BackupListCount": 9,
      "TotalQuotaSpace": 536870645760,
      "FreeQuotaSpace": 254643855360,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Interrupted": false,
      "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2025-02-04T13:32:18.1436606Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "ParsedResult": "Success",
  "Interrupted": false,
  "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
  "EndTime": "2025-02-04T15:10:42.6414866Z",
  "BeginTime": "2025-02-04T13:32:18.1429166Z",
  "Duration": "01:38:24.4985700",
  "MessagesActualLength": 153,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 0,
  "Messages": [
    "2025-02-04 14:32:18 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
    "2025-02-04 14:41:36 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2025-02-04 14:41:40 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (3.528 KB)",
    "2025-02-04 14:41:40 +01 - [Information-Duplicati.Library.Main.Operation.BackupHandler-SkipUsnForVolume]: Performing full scan for volume \"C:\\\": USN journal entries were purged since last scan",
    "2025-02-04 15:48:58 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc62bede6c55d434795caa0e2d570d564.dblock.zip.aes (100.178 MB)",
    "2025-02-04 15:48:58 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc4570e2b4c1c467295fe81b21eddcb41.dblock.zip.aes (100.175 MB)",
    "2025-02-04 15:48:58 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bec9411d9233b4e49809c1a7badcc99a6.dblock.zip.aes (100.401 MB)",
    "2025-02-04 15:48:58 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bd324ae27eb7a4740aac8bb277cbfaab2.dblock.zip.aes (100.335 MB)",
    "2025-02-04 15:49:07 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc62bede6c55d434795caa0e2d570d564.dblock.zip.aes (100.178 MB)",
    "2025-02-04 15:49:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bec9411d9233b4e49809c1a7badcc99a6.dblock.zip.aes (100.401 MB)",
    "2025-02-04 15:49:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc4570e2b4c1c467295fe81b21eddcb41.dblock.zip.aes (100.175 MB)",
    "2025-02-04 15:49:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bd324ae27eb7a4740aac8bb277cbfaab2.dblock.zip.aes (100.335 MB)",
    "2025-02-04 15:49:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ie9bb806ee65844b2a84c248238f78fa5.dindex.zip.aes (196.106 KB)",
    "2025-02-04 15:49:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i45a06cc33f6a439ab9c13c3186a319ec.dindex.zip.aes (195.528 KB)",
    "2025-02-04 15:49:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i40f4d07a73ad4a75bcb9201d6b36d715.dindex.zip.aes (536.653 KB)",
    "2025-02-04 15:49:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i4fae1ae6565a4992bfe6e6772a5b3afe.dindex.zip.aes (202.981 KB)",
    "2025-02-04 15:49:09 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ie9bb806ee65844b2a84c248238f78fa5.dindex.zip.aes (196.106 KB)",
    "2025-02-04 15:49:09 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b96f864ce1b4a49c9ad14348ecba10742.dblock.zip.aes (100.158 MB)",
    "2025-02-04 15:49:09 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i45a06cc33f6a439ab9c13c3186a319ec.dindex.zip.aes (195.528 KB)",
    "2025-02-04 15:49:09 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b466cbf785c22402aa23cd54ecd0cc335.dblock.zip.aes (100.323 MB)"
  ],
  "Warnings": [],
  "Errors": [],
  "BackendStatistics": {
    "RemoteCalls": 71,
    "BytesUploaded": 2913810571,
    "BytesDownloaded": 1113444396,
    "FilesUploaded": 55,
    "FilesDownloaded": 12,
    "FilesDeleted": 2,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 3666,
    "KnownFileSize": 192173271914,
    "LastBackupDate": "2025-02-04T14:32:18+01:00",
    "BackupListCount": 9,
    "TotalQuotaSpace": 536870645760,
    "FreeQuotaSpace": 254643855360,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Backup",
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.1.0.2 (2.1.0.2_beta_2024-11-29)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2025-02-04T13:32:18.1436606Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}

Is the log metric "FilesDownloaded" indicating the number of verified files (in the UI also visible as formatted text in the Job → Reporting → Show Log → General → Test Phase → Verifications section)? It says "FilesDownloaded": 12, / Verifications 12 which sounds like a well managable number of files.

That is why I would suspect the process of checking for changes in source to account for the decrease in performance.

In another thread, ts678 mentioned the possibility of an SQLite cache bottleneck:

Even though I would not tend to blame SQLite for the sudden decrease in performance, would you recommend testing a larger cache size?

Could the full scan message in the log have to do with the long processing times? I think it should not because it was also present in the last log prior to updating, but “full scan” sounds like a lot work to do…

"2025-02-04 14:41:40 +01 - [Information-Duplicati.Library.Main.Operation.BackupHandler-SkipUsnForVolume]: Performing full scan for volume \"C:\\\": USN journal entries were purged since last scan",

PS: This may be unrelated because I never documented the processing time for that action in the old Duplicati version but maybe it is also relevant for you: The UI control Operations → Restore files also seems to take lots of time to retrieve the data necessary to show the file explorer-alike restore interface. The verbose log shows the start time of each list operation:

2025-02-05 11:43:17 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2025-02-05 11:43:17 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2025-02-05 11:48:47 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started

The waiting time is about 5 minutes until this loading screen appears (time between message 2 and 3):

Afterwards, it takes another 4 minutes to build up the first hierarchy level within the root directory C:\ (this unfortunately is not visible in the log because Duplicati then waits for user interaction before doing anything else).