Full backup takes an hour and a half when run by the scheduler and only 5 minutes when run...


Author
Message
rlcronin
rlcronin
Talented Member
Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)
Group: Forum Members
Posts: 94, Visits: 359
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
jphughan
jphughan
Macrium Evangelist
Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)
Group: Forum Members
Posts: 14K, Visits: 84K
Please post the text of the logs generated by each job, making sure to omit your Reflect license key that’s at the bottom.
rlcronin
rlcronin
Talented Member
Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)
Group: Forum Members
Posts: 94, Visits: 359
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 (FSmile - 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> (CSmile
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - Local Disk (DSmile
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 (FSmile - 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> (CSmile
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - Local Disk (DSmile
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
jphughan
jphughan
Macrium Evangelist
Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)
Group: Forum Members
Posts: 14K, Visits: 84K
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.?
Edited 12 November 2023 8:35 PM by jphughan
rlcronin
rlcronin
Talented Member
Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)
Group: Forum Members
Posts: 94, Visits: 359
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
Edited 12 November 2023 9:41 PM by rlcronin
jphughan
jphughan
Macrium Evangelist
Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)
Group: Forum Members
Posts: 14K, Visits: 84K
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.
Edited 12 November 2023 9:53 PM by jphughan
rlcronin
rlcronin
Talented Member
Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)
Group: Forum Members
Posts: 94, Visits: 359
It performs fine when I run the job interactively. Also it's connected via usb-c, not usb-a. 

--
bc
Dan Danz
Dan Danz
Macrium Hero
Macrium Hero (2.7K reputation)Macrium Hero (2.7K reputation)Macrium Hero (2.7K reputation)Macrium Hero (2.7K reputation)Macrium Hero (2.7K reputation)Macrium Hero (2.7K reputation)Macrium Hero (2.7K reputation)Macrium Hero (2.7K reputation)Macrium Hero (2.7K reputation)Macrium Hero (2.7K reputation)
Group: Forum Members
Posts: 1.2K, Visits: 9.5K
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
Reflect v8.1.7847+ on Windows 11 Home 23H2 22631.3085+ | Reflect v8.1.7853+ on Windows 10 Pro 22H2 19045.3996+
Reflect v8.1.7784+ on 2 systems Windows 10 Home 22H2 19045.3803+

jphughan
jphughan
Macrium Evangelist
Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)Macrium Evangelist (22K reputation)
Group: Forum Members
Posts: 14K, Visits: 84K
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.
rlcronin
rlcronin
Talented Member
Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)Talented Member (129 reputation)
Group: Forum Members
Posts: 94, Visits: 359
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
GO

Merge Selected

Merge into selected topic...



Merge into merge target...



Merge into a specific topic ID...




Reading This Topic

Login

Explore
Messages
Mentions
Search