backup on c drive taking a long time - hours between 2 lines in the log

we're out of support on this license. hoping someone can let me know if this is normal or what to do about this.

Backing up C drive on a pretty new dell optiplex. The C drive incremental can take hours. The data drive takes minutes or seconds.

All the logs for the C drive show a long time between 2 entries in the same place. Anyone able to explain what's happening at that point? Amount of time varies. This one is what, more than 12 hours!

14-May-2017 05:00:00 service 100 service (build 59) started job by incremental trigger
14-May-2017 05:00:00 service 104 5.2.7.38915 >>>>> license info removed.
14-May-2017 05:00:06 service 100 backup volume C:\ (NTFS)
14-May-2017 05:00:06 service 102 creating snapshot for \\?\Volume{a1877de9-c49c-4be2-918c-37641e8e853b}
14-May-2017 05:00:06 service 199 try snapshot by VSS API by STC provider
14-May-2017 05:00:19 service 150 retrieving snapshot name.
14-May-2017 05:00:19 service 103 snapshot was created by VSS API by STC provider. It took 13 seconds
14-May-2017 05:00:19 service 104 image will be created by VDIFF
14-May-2017 05:00:19 sptask 111 sbrun -mdn ( sbvol -fi \\?\STC_SnapShot_Volume_21_0 \\?\Volume{a1877de9-c49c-4be2-918c-37641e8e853b} : sbcrypt -54 : sbfile -wd Z:\sp\Office1 C_VOL-b002-i008.spi )
14-May-2017 05:00:19 sptask 110 Worker thread has started
14-May-2017 05:00:20 (loader) 112 corelogic version: 5.0.239.38915
14-May-2017 05:00:20 (loader) 195 5.0.239.38915 5.2.7.38915
14-May-2017 05:00:20 sbvol 107 throttled to 10% of the maximum speed
14-May-2017 05:00:20 sbvol 109 free space exclusion on
14-May-2017 05:00:20 sbvol 107 incremental tracking is on, generation count: 8
14-May-2017 05:00:20 sbvol 117 incremental tracking is on, 18509902 of 473694200 (3%) updated sectors
14-May-2017 05:00:20 sbvol 101 successfully opened volume \\?\Volume{a1877de9-c49c-4be2-918c-37641e8e853b}
14-May-2017 05:00:20 sbvol 107 FAT system area sectors: 0
14-May-2017 05:00:20 sbvol 112 file \\?\STC_SnapShot_Volume_21_0\hiberfil.sys excluded OK
14-May-2017 05:00:20 sbcrypt 109 filter started
14-May-2017 05:00:20 sbfile 101 successfully opened file Z:\sp\Office1 C_VOL-b002-i008.spi
14-May-2017 05:00:20 sbvol 108 Image will not have Disk ID and partition info (-1392 Invalid data format.)
14-May-2017 05:05:30 sbcrypt 107 compression mode: 5
14-May-2017 05:05:30 sbcrypt 107 encryption mode: 4
14-May-2017 05:05:30 sbcrypt 600 Please enter the encryption password
>>>>14-May-2017 05:05:30 sptask 101 Answer was sent as UNICODE string
>>>>14-May-2017 23:53:21 sbvol 109 last volume read done
14-May-2017 23:53:21 sbcrypt 109 tail started
14-May-2017 23:53:21 sbcrypt 109 fini done
14-May-2017 23:53:22 sbfile 193 MD5:f4cbd66e4a2ece32c825d4669c261093 Z:\sp\Office1 C_VOL-b002-i008.spi
14-May-2017 23:53:22 sbfile 200 OK Z:\sp\Office1 C_VOL-b002-i008.spi
14-May-2017 23:53:22 sbfile 109 fini done
14-May-2017 23:53:22 sbvol 109 incremental tracker reset OK
14-May-2017 23:53:22 sbvol 109 fini done
14-May-2017 23:53:22 sptask 114 Process finished successfully
14-May-2017 23:53:23 service 105 snapshots were destroyed

what's going on from 5:05:30 and 23:53:21?!

Similar long gaps on different days, that one above is about the worst.

15-May-2017 05:05:30 sptask 101 Answer was sent as UNICODE string
15-May-2017 09:13:55 sbvol 109 last volume read done

16-May-2017 05:05:30 sptask 101 Answer was sent as UNICODE string
16-May-2017 09:08:38 sbvol 109 last volume read done

12-May-2017 05:05:18 sptask 101 Answer was sent as UNICODE string
12-May-2017 10:10:30 sbvol 109 last volume read done

08-May-2017 05:05:32 sptask 101 Answer was sent as UNICODE string
08-May-2017 10:57:02 sbvol 109 last volume read done

07-May-2017 05:21:46 sptask 101 Answer was sent as UNICODE string
07-May-2017 11:07:07 sbvol 109 last volume read done

05-May-2017 05:00:33 sptask 101 Answer was sent as UNICODE string
05-May-2017 05:21:31 sbvol 109 last volume read done

But sometimes, not a big gap:

11-May-2017 05:00:30 sptask 101 Answer was sent as UNICODE string
11-May-2017 05:03:17 sbvol 109 last volume read done

09-May-2017 05:00:28 sptask 101 Answer was sent as UNICODE string
09-May-2017 05:15:08 sbvol 109 last volume read done

And this time I notice an extra line:

10-May-2017 05:02:57 sptask 101 Answer was sent as UNICODE string
10-May-2017 07:29:42 sbfile 109 probing the target media for > 4GB files support
10-May-2017 07:31:07 sbvol 109 last volume read done

Thoughts?

Comments

lumacor

Destination?

What is the destination for the backup job? (USB, NAS, Network Share?)

The probe to media seemed to take a long time.

What power settings do you have set on the endpoint? - If backing up to USB, I've sometimes found the need to ensure the endpoint is set to use High Performance power settings, with things like selective suspend disabled. If you're on a Balanced power policy, you might want to play around with the settings to suit your needs a bit.

Control Panel > Power Options > Change Plan Settings > Change Advanced Power Settings > USB settings > USB selective suspend setting > (set to disabled)

https://msdn.microsoft.com/en-gb/library/windows/hardware/ff540144(v=vs.85).aspx

 

__________________

StorageCraft Certified Master Engineer

Veeam Technical Sales Professional (v9)

Awilliams

Thanks for the reply! The

Thanks for the reply!

The target is an external 2TB WD hard drive. Same one that the data drive is backing up to and those back ups go quick (true, there's not as much changed data as on the OS / C drive), but the drive is awake / the data drive imaging doesn't have a similar time lag to wake up the external drive.

Probe to media takes a long time - I'm thinking it's the source media that's taking a while, right? not target.

I have the C drive backed up 1x a day (as a continuous incremental) at 5AM.

And the data drive gets backed up at 6AM, 10AM, 2PM, 6PM, 10PM and those go quick, so that would rule out the power settings / target drive issues, right?

 

lumacor

WD 2 TB

I often use those as well. I've seen similar things before, but often it's been anything out of a number of issues.

Still worth checking the selective suspend settings and confirming.

 

Are both / all volumes included in the same backup job?

If not, do you get the same issue if you include them in the same job together?

Do you have any other backup software installed on the endpoint?

How fragmented is the C: volume vs. the Data volume?

Are there any Event Viewer error relating to the C: volume?

Are there any VSS writer issues?

__________________

StorageCraft Certified Master Engineer

Veeam Technical Sales Professional (v9)

Terms and Conditions of Use - Privacy Policy - Cookies