My weekly full backup that runs at 6AM on Sunday morning via the Maacrium scheduler took an hour and a half to complete this morning. That seemed a bit excessive to me. I decided to try to troubleshoot it by deleting the backup that it had created and re-running the same full backup interactively while I watched. The interactive backup took a little over 5 minutes, which is much more reasonable. Where do I start trying to get to the bottom of why the scheduler-initiated jobs are so slow?

--
bc

Please post the text of the logs generated by each job, making sure to omit your Reflect license key that’s at the bottom.

+x

 

jphughan - 12 November 2023 6:37 PM

Please post the text of the logs generated by each job, making sure to omit your Reflect license key that’s at the bottom.

Here's the slow one:

Image ID - 353D541A624C6691

--------------------------------------------------------------------------------
Imaging Summary


--------------------------------------------------------------------------------
Backup Definition File: D:\Users\Bob\Google Drive\Documents\Reflect\bc17\My Backup.xml
Auto Verify: N
Verify File System: Y
Maximum File Size: Automatic
Compression: Medium
Password: N
Intelligent Copy: Y
Power Saving: N
Email On Success: N
Email On Warning: N
Email On Failure: N
Total Selected: 202.13 GB
Current Time: 11/12/2023 8:00:48 AM


--------------------------------------------------------------------------------
Destination
Backup Type: Full
File Name: F:\BC17\353D541A624C6691-00-00.mrimg


--------------------------------------------------------------------------------
Operation 1 of 5
Hard Disk: 1
Drive Letter: N/A
Volume: \??\Volume{2a1e6dd7-5942-460d-823c-d5ffbce1fa5c}
File System: FAT32 (LBA)
Label: NO NAME
Size: 96.0 MB
Free: 32.3 MB
Used: 63.7 MB


--------------------------------------------------------------------------------
Operation 2 of 5
Hard Disk: 1
Drive Letter: N/A
File System: Unformatted
Label:
Size: 16.0 MB
Free: 0 B
Used: 16.0 MB


--------------------------------------------------------------------------------
Operation 3 of 5
Hard Disk: 1
Drive Letter: C
Volume: \??\Volume{e76e021e-cae9-432a-bacb-d6c7787d5325}
File System: NTFS
CBT: Y
Label:
Size: 464.66 GB
Free: 355.22 GB
Used: 109.44 GB


--------------------------------------------------------------------------------
Operation 4 of 5
Hard Disk: 1
Drive Letter: D
Volume: \??\Volume{9a87a447-de53-4fc4-a2e6-ae3dcb84e1e9}
File System: NTFS
CBT: Y
Label: Local Disk
Size: 488.28 GB
Free: 396.40 GB
Used: 91.88 GB


--------------------------------------------------------------------------------
Operation 5 of 5
Hard Disk: 1
Drive Letter: N/A
Volume: \??\Volume{85bcf15e-a253-4acd-bff1-a459b858aa24}
File System: NTFS
Label:
Size: 834.0 MB
Free: 76.4 MB
Used: 757.6 MB


--------------------------------------------------------------------------------
Starting Image - Sunday, November 12, 2023 8:00 AM
Initializing
Write Method: Using Direct Disk I/O
Destination Drive: Backups (F - Free Space 519.06 GB
Image Guardian: Protected
Free space threshold: Delete oldest backup sets when free space is less than 5.00 GB

Creating Volume Snapshot - Please Wait
Volume Snapshots Created


--------------------------------------------------------------------------------
Verifying File System
\??\Volume{2a1e6dd7-5942-460d-823c-d5ffbce1fa5c}
C:\ \??\Volume{e76e021e-cae9-432a-bacb-d6c7787d5325}
D:\ \??\Volume{9a87a447-de53-4fc4-a2e6-ae3dcb84e1e9}
\??\Volume{85bcf15e-a253-4acd-bff1-a459b858aa24}


--------------------------------------------------------------------------------
Saving Partition - NO NAME
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - <NO NAME>
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - <NO NAME> (C
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - Local Disk (D
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - <NO NAME>
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Index
New File: 161.72 GB 353D541A624C6691-00-00.mrimg


--------------------------------------------------------------------------------
Retention Rules
Rules will be applied to all matching backup sets in the destination folder

Full: Retain 2 full backups
Linked incremental and differential backups will also be deleted

Backup Sets: 3 sets found
Delete File: F:\BC17\FBC7611906FA7BBC-00-00.mrimg
Delete File: F:\BC17\FBC7611906FA7BBC-01-01.mrimg
Delete File: F:\BC17\FBC7611906FA7BBC-02-02.mrimg
Delete File: F:\BC17\FBC7611906FA7BBC-03-03.mrimg
Delete File: F:\BC17\FBC7611906FA7BBC-04-04.mrimg
Delete File: F:\BC17\FBC7611906FA7BBC-05-05.mrimg
Delete File: F:\BC17\FBC7611906FA7BBC-06-06.mrimg



--------------------------------------------------------------------------------
I/O Performance: Read 534.7 Mb/s - Write 356.7 Mb/s


--------------------------------------------------------------------------------
Image Completed Successfully in 01:24:23

... and here's the fast one:

Image ID - C69CF86097B97AA2

--------------------------------------------------------------------------------
Imaging Summary


--------------------------------------------------------------------------------
Backup Definition File: D:\Users\Bob\Google Drive\Documents\Reflect\bc17\My Backup.xml
Auto Verify: N
Verify File System: Y
Maximum File Size: Automatic
Compression: Medium
Password: N
Intelligent Copy: Y
Power Saving: N
Email On Success: N
Email On Warning: N
Email On Failure: N
Total Selected: 202.14 GB
Current Time: 11/12/2023 9:43:37 AM


--------------------------------------------------------------------------------
Destination
Backup Type: Full
File Name: F:\BC17\C69CF86097B97AA2-00-00.mrimg


--------------------------------------------------------------------------------
Operation 1 of 5
Hard Disk: 1
Drive Letter: N/A
Volume: \??\Volume{2a1e6dd7-5942-460d-823c-d5ffbce1fa5c}
File System: FAT32 (LBA)
Label: NO NAME
Size: 96.0 MB
Free: 32.3 MB
Used: 63.7 MB


--------------------------------------------------------------------------------
Operation 2 of 5
Hard Disk: 1
Drive Letter: N/A
File System: Unformatted
Label:
Size: 16.0 MB
Free: 0 B
Used: 16.0 MB


--------------------------------------------------------------------------------
Operation 3 of 5
Hard Disk: 1
Drive Letter: C
Volume: \??\Volume{e76e021e-cae9-432a-bacb-d6c7787d5325}
File System: NTFS
CBT: Y
Label:
Size: 464.66 GB
Free: 355.21 GB
Used: 109.45 GB


--------------------------------------------------------------------------------
Operation 4 of 5
Hard Disk: 1
Drive Letter: D
Volume: \??\Volume{9a87a447-de53-4fc4-a2e6-ae3dcb84e1e9}
File System: NTFS
CBT: Y
Label: Local Disk
Size: 488.28 GB
Free: 396.40 GB
Used: 91.88 GB


--------------------------------------------------------------------------------
Operation 5 of 5
Hard Disk: 1
Drive Letter: N/A
Volume: \??\Volume{85bcf15e-a253-4acd-bff1-a459b858aa24}
File System: NTFS
Label:
Size: 834.0 MB
Free: 76.4 MB
Used: 757.6 MB


--------------------------------------------------------------------------------
Starting Image - Sunday, November 12, 2023 9:43 AM
Initializing
Write Method: Using Direct Disk I/O
Destination Drive: Backups (F - Free Space 696.17 GB
Image Guardian: Protected
Free space threshold: Delete oldest backup sets when free space is less than 5.00 GB

Creating Volume Snapshot - Please Wait
Volume Snapshots Created


--------------------------------------------------------------------------------
Verifying File System
\??\Volume{2a1e6dd7-5942-460d-823c-d5ffbce1fa5c}
C:\ \??\Volume{e76e021e-cae9-432a-bacb-d6c7787d5325}
D:\ \??\Volume{9a87a447-de53-4fc4-a2e6-ae3dcb84e1e9}
\??\Volume{85bcf15e-a253-4acd-bff1-a459b858aa24}


--------------------------------------------------------------------------------
Saving Partition - NO NAME
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - <NO NAME>
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - <NO NAME> (C
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - Local Disk (D
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - <NO NAME>
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Index
New File: 161.72 GB C69CF86097B97AA2-00-00.mrimg


--------------------------------------------------------------------------------
Retention Rules
Rules will be applied to all matching backup sets in the destination folder

Full: Retain 2 full backups
Linked incremental and differential backups will also be deleted

Backup Sets: 2 sets found
Nothing to delete



--------------------------------------------------------------------------------
I/O Performance: Read 9.7 Gb/s - Write 4.3 Gb/s


--------------------------------------------------------------------------------
Image Completed Successfully in 00:05:59



--
bc

Ok, so no consolidation occurred, and the source data set and destination file size are nearly identical across the two jobs. But both the read and write performance are unexpectedly low on the slow job. That makes me think that something else may have been running on your system at the same time during the scheduled backup.

Also, what is your F drive, meaning is it a USB 3.x HDD, an internal NVMe SSD, etc.?

Hm, well, at 6AM on Sunday there wouldn't be anything else running, as least anything that I initiated.

The F drive shows up in device manager as "Samsung PSSD T7 SCSI Disk Device". Here's how its connected:



Looking at the most recent Reflect logs there does seem to be a trend. Before November 9 when I did a restore, why I can't recall, all the backup jobs completed reasonably quickly. Since, they've been taking way longer. I've not got a clue why.



Perhaps I ought to restore an image from last Sunday and see if that helps.

--
bc

Is that external SSD performing poorly outside of Reflect? Try simply copying a large file onto it. I remember one case here where someone found that their USB 3.x external drive had negotiated a USB 2.0 data speed. In that case, simply disconnecting and reconnecting the cable might work, or trying another port or cable. The pins that enable USB 3.x connectivity are recessed within USB-A connectors, whereas the USB 2.0 pins are at the tip, so a loose connection can result in USB 2.0 performance.

It performs fine when I run the job interactively. Also it's connected via usb-c, not usb-a. 

--
bc

FWIW - the slow one had less free space available when running..  When it finished it deleted an extra 3rd set, and the OP deleted the set the first created.  So the fast run had 2 full backup sets worth of free space to use. 

Just an observation,  not sure it could be cause of slowdown.  I just wanted to point out the comparison is not under the same conditions


L.W. (Dan) Danz, Overland Park KS

Hmm, if the available space hadn’t been TRIMed beforehand, that could account for lower write performance than if the target were writing to trimmed capacity. But even the read speed was slow according to the performance stats, which makes me wonder if some app had a background task running at that time, even if it’s not a daily or even weekly occurrence.

It's difficult to imagine that the free space situation could explain it. It's a terabyte drive and was only half full. 

I'm still bothered by the fact that the slowdowns seem to have started on a particular day and it's been bad since. My daily backups are incremental and not a lot changes on this machine from day to day. There's no way an incremental would take nearly a half hour.

I'm also confused why the same job would run fast when it is run interactively. Could the USB be being forced into some slow mode on account the machine is unattended? This is a laptop that only supports modern standby and I'm still confused about all the possible ramifications of that.

As a test I reverted the machine to the oldest backup I have for it (from October 31) to see if perhaps some update that happened between then and the 9th triggered the problem. There's an incremental scheduled for tomorrow morning at 6. I'm hoping it will be fast but if the problem persists I will be looking for more help.

--
bc