Slow Initializing

[wxfpdc]

Hello,

I have 2 same laptops, Dell i7, same machines, same RAM, same HDDs 500GB SSD NVME
Backups running on both, Veeam Agent
First laptop, backup starts, says Initializing takes like 8-12 minutes, then continues backup
Second laptop, backup starts, says Initializing takes almost always 21s

How can I debug whats cousing this slowdown ?
What takes place during Initializing phase ?

Regards

[HannesK]

Hello,
That sounds like a technical issue. Please provide a support case ID for this issue, as requested when you click New Topic.

Without case number, the topic will eventually be
deleted by moderators.

20 seconds sounds normal also on my machine. C:\ProgramData\Veeam\Endpoint has the logs, but not sure how much that helps.

Best regards,
Hannes

[wxfpdc]

Thank you, Ive checked logs

Backup starts

Code: Select all

[31.03.2021 14:33:34] <01> Info     Starting job mode: 'Normal'

then most of the time is spend doing some keys decrypting

Code: Select all

[31.03.2021 14:36:09] <01> Info     [CryptoKeyCryptor] Decrypting encrypted key using recovery recs: CryptoKey

7 minutes, and later

Code: Select all

[31.03.2021 14:43:00] <01> Info     [AgentMngr] Starting agent with normal priority, Host '...', 

(...)

Code: Select all

[31.03.2021 14:43:23] <01> Info     Need to recrypt result: [IsNeed2Recypt: False, IsNeed2CreateNewArchiveKey: False, IsNeed2CreatePolicyKeysOnTarget: False]
[31.03.2021 14:45:34] <01> Info     [BackupMetaConsistencyChecker] Checking encryption consistency for backup meta
[31.03.2021 14:45:34] <01> Info     [BackupMeta] Saving backup meta to

and probably later it starts the rest of the backup

The most time is spend on CryptoKeyCryptor, Decrypting encrypted key, many many commands like that
So encryption keys related stuff

Maybe I will recreate whole backup from scratch, and will see then how long it takes to Initialize

[wxfpdc]

To clarify, I use increments daily, every 8 hours + full backup every month, keep last 14 days
Ok, here are conclusions after tests, hope they make sense
This is my opinion, my limited undestanding

I had backup on NAS, say on \\192.168.0.10\Backup
Old Backup job had name Backup_old, so it was in \\192.168.0.10\Backup\Backup_old
When I created new backup, say Backup_new it was in \\192.168.0.10\Backup\Backup_new
initialization process was still slow 8-10 minutes as before, but in logs, it was scanning \\192.168.0.10\Backup for all backup folders/files (check logs below how it enumerates items in shared dir),
and doing "[CryptoKeyCryptor] Decrypting encrypted key using recovery recs: CryptoKey" and other key related stuff on Backup_old files too !
So when I moved Backup_old up, so that in \\192.168.0.10\Backup only Backup_new was left and stopped Veeam service and removed old Endpoint dir (from Veeam directory, clearing logs etc)
then Initializing in new backup took only 6s

TLDR: To sum up, slow Initialize has something to do with how Veeam handles, encryption/decryption keys from old backups, old increments
When using the same shared directory, Veeam scans all directories for backups/keys inside shared folder, even if they don't match current backup directory, and does a lot of time taking things with those old keys

Long story:

I run couple of tests, from logs:

From logs:
new log - 4 minutes
this one shows logs where Initialize was over 4 minutes on new backup, where old dir existed on same NAS in same dir
But backup name was changed, so also different dir was created

Code: Select all

Info     [UNKNOWN] [FC] Enumerating items in directory '\\192.168.0.10\Backup', searchMask '*.*', recursive 'False'
(...)
[01.04.2021 09:38:00] <01> Info     [UNKNOWN] [FC] Directory [\\192.168.0.10\Backup\] contains 2 items
(...)
Info     [UNKNOWN] [FC] Directory [\\192.168.0.10\BackupW\Backup_old\] contains 86 items
(...)
[01.04.2021 09:38:01] <01> Info     [EncryptedImport] EncryptImportProcessor started.
(...)
[01.04.2021 09:40:02] <01> Info     [CryptoKeyCryptor] Decrypting encrypted key using recovery recs: CryptoKey
(...)
[01.04.2021 09:42:32] <01> Info     [CryptoKeyCryptor] Encryption recovery rec: RecoveryRec (RecoveryKeyId='5a82de70-4bbc-4a24-8928-0e3190f7e3bc', EncryptedKeyId='54b8ff4d-0e66-4470-a0b6-a6dd3f697adb')
[01.04.2021 09:42:32] <01> Info     [CryptoKeyCryptor] Recovery key: CryptoKey (Id='', KeySetId=', Type='Password', ModificationDate='15.10.2019 14:07:21', Hint=', Value='<VALUE SET>')
[01.04.2021 09:42:32] <01> Info     [CRotatedDriveManager] Check backup meta [Version: 5996, MetaSchemaVersion: 2, BackupInfo: ... ]
[01.04.2021 09:42:32] <01> Info     [CRotatedDriveManager] ...different job id (... ), skip

You can see it's reading keys from old backup, and some keys even got date in 2019 ! ModificationDate='15.10.2019 14:07:21' when no longer increments from that date exists
And AFTER doing that it skips it, since its not that backup [CRotatedDriveManager] ...different job id (... ), skip
I guess it should somehow check if its matching backup before doing decrypting of keys

Then creates new dir for new backup and does the backup

Code: Select all

[01.04.2021 09:42:33] <01> Info     [UNKNOWN] [FC] Creating directory '\\192.168.0.10\Backup\Backup_new'

Old log - 9 minutes
Run that took 9 minutes Initialize, most of the time spend on dealing with keys, it was also scanning keys from \\192.168.0.10\Backup\Backup_old
So bascially when selecting shared folder, Veeam scans all folders inside shared dir, even ones that doesnt match backup name, and does something with keys related to that old folders
And there seems to be some archive of keys of all (?) increments, and all of them are decrypted etc.

Code: Select all

[01.04.2021 09:15:28] <01> Info     Initializing CCliCryptoLogging completed
[01.04.2021 09:15:28] <01> Info     [EncryptedImport] KeySet for import. Chain = '...', KeySetId = '...', KeyType = 'SymmetricRndMeta'
[01.04.2021 09:15:28] <01> Info     [EncryptedImport] Existing KeySet found, data imported.
(...)
[01.04.2021 09:15:29] <01> Info     [EncryptedImport] KeySet for import. Chain = '...', KeySetId = 'oAT/cpVKVEeMGlTe5bjMTA==', KeyType = 'Password'
[01.04.2021 09:17:19] <01> Info     [EncryptedImport] IsKeySetsFilled = 'True'.
[01.04.2021 09:17:20] <01> Info     [CryptoKeyCryptor] Decrypting encrypted key using recovery recs: CryptoKey (Id='...', KeyType='SymmetricRndMeta', ModificationDate='31.03.2021 13:40:01', Hint='Storage [Id: ..., Name: \\192.168.0.10\Backup\Backup_old\... 2021-03-16T190240.vib]', Value='<VALUE NOT SET>')
[01.04.2021 09:17:20] <01> Info     Trying to find recovery key
[01.04.2021 09:17:20] <01> Info     [CryptoKeyCryptor] Encryption recovery rec: RecoveryRec (RecoveryKeyId='...')
[01.04.2021 09:17:20] <01> Info     [CryptoKeyCryptor] Recovery key: CryptoKey (Id='...', Type='Password', ModificationDate='15.10.2019 14:07:21', Hint='...', Value='<VALUE SET>')
(...) this takes almost 3,5 minutes

[01.04.2021 09:18:57] <01> Info     [CRotatedDriveManager] Check backup meta [Version: 5993, MetaSchemaVersion: 2, BackupInfo: ...]
[01.04.2021 09:18:57] <01> Info     [EncryptedImport] Clear Encrypted Backup Id = '...7'
[01.04.2021 09:18:57] <01> Info     [BackupMeta] Loading backup meta from '\\192.168.0.10\Backup\Backup_old\....vbm'
(...)
[01.04.2021 09:18:57] <01> Info     [EncryptedImport] Encrypted backup created
[01.04.2021 09:18:57] <01> Info     [EncryptedImport] Encrypted backup Id = '...'
[01.04.2021 09:18:58] <01> Info     [EncryptedImport] KeySet for import. Chain = '...', KeySetId = '...', KeyType = 'SymmetricRndMeta'
[01.04.2021 09:18:58] <01> Info     [EncryptedImport] Existing KeySet found, data imported.
(...) and again 3,5 minutes

[01.04.2021 09:18:59] <01> Info     [EncryptedImport] KeySet for import. Chain = '...', KeySetId = '...', KeyType = 'Password'
[01.04.2021 09:20:37] <01> Info     [EncryptedImport] IsKeySetsFilled = 'True'.
[01.04.2021 09:20:38] <01> Info     [CryptoKeyCryptor] Decrypting encrypted key using recovery recs: CryptoKey (Id='...', KeyType='SymmetricRndMeta', ModificationDate='31.03.2021 13:40:01', Hint='Storage [Id: ..., Name: \\192.168.0.10\Backup\Backup_old\....vib]', Value='<VALUE NOT SET>')
[01.04.2021 09:20:38] <01> Info     Trying to find recovery key
[01.04.2021 09:20:38] <01> Info     [CryptoKeyCryptor] Encryption recovery rec: RecoveryRec (RecoveryKeyId='...', EncryptedKeyId='...')
[01.04.2021 09:20:38] <01> Info     [CryptoKeyCryptor] Recovery key: CryptoKey (Id='...', KeySetId='.', Type='Password', ModificationDate='15.10.2019 14:07:21', Hint='...', Value='<VALUE SET>')
(...)
[01.04.2021 09:22:16] <01> Info     [EncryptedImport] Clear Encrypted Backup Id = '...'
[01.04.2021 09:22:16] <01> Info         Product version is 5.0.0.4301, transport version on repository server is 5.0.0.4301
(...)
[01.04.2021 09:22:18] <01> Info     [Import] Using new meta sync alg, backup id ..., backup was Updated
[01.04.2021 09:22:18] <01> Info     [Import] Synchronizing keys
[01.04.2021 09:22:18] <01> Info     [Import] Recovery key already exists: CryptoKey (Id='...', KeySetId='...', Type='Password', ModificationDate='15.10.2019 14:07:21', Hint='..', Value='<VALUE SET>')
[01.04.2021 09:22:18] <01> Info     [Import] Sync key KeyInfo: [CryptoKey (Id='...', KeyType='SymmetricRndMeta', ModificationDate='31.03.2021 13:40:01', Hint='Storage [Id: ..., Name: \\192.168.0.10\Backup\Backup_old\....vib]', Value='<VALUE SET>')], RecoveryRecs: [RecoveryKeyId: ..., EncryptedKeyId: ...]
[01.04.2021 09:22:18] <01> Info     [Import] Updating key KeyInfo: [CryptoKey (Id='...', KeySetId='...', KeyType='SymmetricRndMeta', ModificationDate='31.03.2021 13:40:01', Hint='Storage [Id: ..., Name: \\192.168.0.10\Backup\Backup_old\....vib]', Value='<VALUE SET>')], RecoveryRecs: [RecoveryKeyId: ...d]
[01.04.2021 09:22:18] <01> Info     [DbAccessor] Start transaction.
[01.04.2021 09:22:18] <01> Info     [DbAccessor] Commit transaction.
[01.04.2021 09:22:18] <01> Info     [DbAccessor] Dispose transaction.
(...)
next 1,5 minute jump
[01.04.2021 09:22:30] <01> Info     Need to recrypt result: [IsNeed2Recypt: False, IsNeed2CreateNewArchiveKey: False, IsNeed2CreatePolicyKeysOnTarget: False]
[01.04.2021 09:24:03] <01> Info     [BackupMetaConsistencyChecker] Checking encryption consistency for backup meta
[01.04.2021 09:24:03] <01> Info     [BackupMeta] Saving backup meta to '\\192.168.0.10\Backup\...\....vbm'

and later it starts finally

[HannesK]

Hello,
wow, I cannot remember anyone new in this forum who was able to find a solution from the logfiles that quickly.

Thanks for sharing your findings.

Would it be possible that you create a support case, upload your logs and post the case number? You can even do that with the free version.

Thanks,
Hannes

[wxfpdc]

Support case ID: 04732304

Incremental backup, Initializing now takes 19s, amazing

[HannesK]

thank you, we will have a look at them!