Jump to content

Slow backups. Excessive time "idle/loading/preparing"


1sae

Recommended Posts

Hi, I've been using Retrospect 7.5 for about a year now, and have recently run into problems with backups not finishing cause of lack of time. Below is the most recent log file:

 

 

+ Normal backup using Tuesday / Thursday at 8/2/2007 8:00 PM (Execution unit 1)

* Resolved container Exchange Server on DC3 to 1 volumes:

First Storage Group on DC3

To Backup Set Tuesday - Thursday...

 

- 8/2/2007 8:00:25 PM: Copying Local Disk (C:)

8/2/2007 9:32:08 PM: Snapshot stored, 318.9 MB

8/2/2007 10:13:07 PM: Comparing Local Disk (C:)

File "C:\WINDOWS\repair\software": didn't compare

8/2/2007 10:23:56 PM: 1 execution errors

Completed: 1152 files, 3.1 GB

Performance: 357.7 MB/minute (464.6 copy, 290.8 compare)

Duration: 02:23:30 (02:05:57 idle/loading/preparing)

 

 

- 8/2/2007 10:23:56 PM: Copying Local Disk (C:) on DC3

8/2/2007 10:33:28 PM: Grooming Backup Set Tuesday - Thursday...

8/2/2007 10:52:37 PM: Groomed 12.0 GB from Backup Set Tuesday - Thursday.

8/2/2007 11:08:37 PM: Snapshot stored, 248.2 MB

8/2/2007 11:49:30 PM: Comparing Local Disk (C:) on DC3

8/3/2007 12:15:51 AM: Execution completed successfully

Completed: 1539 files, 8.9 GB

Performance: 413.8 MB/minute (519.9 copy, 343.6 compare)

Duration: 01:51:54 (01:08:13 idle/loading/preparing)

 

 

- 8/3/2007 12:15:53 AM: Copying First Storage Group on DC3

Backup type: Full

8/3/2007 7:00:00 AM: Script execution terminated at specified stop time.

8/3/2007 7:00:00 AM: Execution incomplete

Remaining: 3 files, 959.1 MB

Completed: 1 files, 6.1 GB

Performance: 59.4 MB/minute

Duration: 06:44:07 (04:59:52 idle/loading/preparing)

 

8/3/2007 7:00:40 AM: Execution incomplete

Total performance: 184.5 MB/minute

Total duration: 10:59:34 (08:14:03 idle/loading/preparing)

 

 

You'll notice the total time is almost 11 hours and the idle/loading/preparing time is over 8 hours of that.

 

I've run some immediate backups and noticed that it starts the file backup very quickly but takes forever at the end copying the snapshot.

 

I don't know what else to do.

Link to comment
Share on other sites

How many files are there in the backup set, in total?

What is the size of the catalog file?

Is the catalog file compressed? (Compression takes time.)

How much free space is there on the hard drive with the catalog files?

Is the hard drive with the catalog files a local drive or a networked drive?

 

You also have half an hour of grooming. It seems as your backup set is too small or you don't schedule groom scripts at idle time (weekends, perhaps?).

Link to comment
Share on other sites

ow many files are there in the backup set, in total?

The file server has 94,920 files (25.4 GB). The Exchange server has 59,468 files (20.1 GB)

 

What is the size of the catalog file?

Catalog file is about 110 MB

 

Is the catalog file compressed? (Compression takes time.)

Yes it is. I'll try it without.

 

How much free space is there on the hard drive with the catalog files?

The catalog file is on the same hard drive as the backup, so it fluctuates but currently 50gb free

 

Is the hard drive with the catalog files a local drive or a networked drive?

It is a removable usb hard drive.

 

You also have half an hour of grooming. It seems as your backup set is too small or you don't schedule groom scripts at idle time (weekends, perhaps?).

Grooming is set to "Groom to Retrospect defined policy"

 

 

Aside from turning off catalog compression what else could I try? I'm not sure about the best method for grooming if I should turn off the "Groom to Retrospect defined policy" check box.

 

Thanks!

Link to comment
Share on other sites

Quote:

ow many files are there in the backup set, in total?

The file server has 94,920 files (25.4 GB). The Exchange server has 59,468 files (20.1 GB)

You also have half an hour of grooming. It seems as your backup set is too small or you don't schedule groom scripts at idle time (weekends, perhaps?).

Grooming is set to "Groom to Retrospect defined policy"

 

 


OK, the two servers has roughly 150000 files in total. Suppose you have 20 backups (snapshots) each in the backup set, the backup set contains 3 million files.

You should check the "properties" of the backup set and look at the "summary" pane to see the number of files.

 

You should schedule a "groom" script once a week. "Retrospect defined policy" saves many snapshots and may be your problem (along with compression of the catalog file). How about saving the last 20 backups instead?

Link to comment
Share on other sites

Quote:

Thanks I'll give it a shot. Looks like it said 80 snapshots, but only 200000 files.

 


Hmmm?

That doesn't seem right. Neither 80 snapshots nor 200000 files is large enough to cause the "delays" you see. Maybe the backup set is bad (in some regard)?

 

If you don't see any improvement, I recommend you create a new backup set and use that instead. When you have sufficient number of backups then (and only then) you can delete the old backup set you have now.

Link to comment
Share on other sites

I have developed exactly the same issue. We Retrospect attempts to store the snapshot, it takes forever. I cannot pin down the cause of the delay. On one server for example there are 10 or volumes defined, and they all reside on the same RAID subsystem. 9 of these volumes backup ok, but one volume always take about 4 hours to store the snapshot. It does not have the largest file count (66,000 files on the problem volume @ 4 hours to store snapshot vs 167,000 files on another volume @ 8 mins to store snapshot).

 

This occurs across two different backup sets, both tape based.

 

This case is the extreme, but I have begun to notice other "problem" snapshots on other backup schedules. I have one exchange mail box that takes 50 minutes to create the snapshot, while the average is 1-2 minutes. Again this behavior is replicated across two separate backup sets.

 

I have try to breakout the bad volume to a separate script, but get the same result. My catalogues are not compressed, and reside on their own partition with plenty of space. However, as this behavior varies from volume to volume, I don't believe it is backup set, or catalogue related. There is plenty of available RAM on the backup server.

 

Can anybody suggest another approach to this problem. It is having a major impact on our backups.

 

Thanks

 

Sean

Link to comment
Share on other sites

So after trying some of the suggestions with no success, I tried wiping one of the hard drives and setting it up as a new backup set. Still no success. Below is the newest report.

 

 

 

+ Normal backup using Tueday / Thursday at 8/9/2007 8:00 PM (Execution unit 1)

To Backup Set Tuesday - Thursday...

 

- 8/9/2007 8:00:15 PM: Copying Local Disk (C:)

8/9/2007 10:09:57 PM: Snapshot stored, 315.5 MB

8/9/2007 10:51:01 PM: Comparing Local Disk (C:)

8/9/2007 11:57:28 PM: Execution completed successfully

Completed: 97294 files, 25.9 GB

Performance: 477.7 MB/minute (596.5 copy, 398.4 compare)

Duration: 03:57:12 (02:06:33 idle/loading/preparing)

 

8/9/2007 11:57:29 PM: Connected to DC3

* Resolved container DC3 to 17 volumes:

Local Disk (C:) on DC3

First Storage Group on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

****** on DC3

 

- 8/9/2007 11:57:28 PM: Copying Local Disk (C:) on DC3

8/10/2007 1:03:02 AM: Snapshot stored, 248.7 MB

8/10/2007 1:43:46 AM: Comparing Local Disk (C:) on DC3

8/10/2007 2:50:02 AM: Execution completed successfully

Completed: 49077 files, 27.1 GB

Performance: 452.5 MB/minute (491.3 copy, 419.4 compare)

Duration: 02:52:33 (00:49:58 idle/loading/preparing)

 

 

- 8/10/2007 2:50:04 AM: Copying First Storage Group on DC3

Backup type: Full

8/10/2007 4:57:04 AM: Comparing First Storage Group on DC3

8/10/2007 5:10:42 AM: Execution completed successfully

Completed: 4 files, 7.6 GB

Performance: 109.4 MB/minute (60.5 copy, 564.8 compare)

Duration: 02:20:37 (00:00:12 idle/loading/preparing)

 

 

- 8/10/2007 5:10:42 AM: Copying ****** on DC3

File "****** 0000000051ae88ed2cfba24cbf184fa6afdbbd460700bcd76c22742d434c94e1d51ad7927de9000000024a6e0000bcd76c22742d434c94e1d51ad7927de900000002a8380000": can't read, error -1101 (file/directory not found)

File "****** \0000000051ae88ed2cfba24cbf184fa6afdbbd460700bcd76c22742d434c94e1d51ad7927de9000000049bec0000bcd76c22742d434c94e1d51ad7927de900000004b3320000": can't read, error -1101 (file/directory not found)

File "****** \0000000051ae88ed2cfba24cbf184fa6afdbbd4607005e36acc0c6c305438588217d99685cae00000001d19a00005e36acc0c6c305438588217d99685cae00000002888e0000": can't read, error -1101 (file/directory not found)

8/10/2007 5:18:06 AM: Snapshot stored, 3,507 KB

8/10/2007 5:58:30 AM: Execution completed successfully

Remaining: 3 files, 1,052 KB

Completed: 5878 files, 932.8 MB

Performance: 137.4 MB/minute

Duration: 00:47:47 (00:41:00 idle/loading/preparing)

 

 

- 8/10/2007 5:58:32 AM: Copying ****** on DC3

File "****** \Deleted Items\00000000f2eda0aaa0a97b40a08783240aa2fd1f0700bcd76c22742d434c94e1d51ad7927de9000000005b8200009cbd87cbc68e10468f9f97d4cae2aeb40000005930370000": can't read, error -1101 (file/directory not found)

File "****** \Deleted Items\00000000f2eda0aaa0a97b40a08783240aa2fd1f0700bcd76c22742d434c94e1d51ad7927de9000000005b8200009cbd87cbc68e10468f9f97d4cae2aeb400000059320b0000": can't read, error -1101 (file/directory not found)

File "****** \Deleted Items\00000000f2eda0aaa0a97b40a08783240aa2fd1f0700bcd76c22742d434c94e1d51ad7927de9000000005b8200009cbd87cbc68e10468f9f97d4cae2aeb40000005932ce0000": can't read, error -1101 (file/directory not found)

File "****** \Deleted Items\00000000f2eda0aaa0a97b40a08783240aa2fd1f0700bcd76c22742d434c94e1d51ad7927de9000000005b8200009cbd87cbc68e10468f9f97d4cae2aeb40000005934ee0000": can't read, error -1101 (file/directory not found)

8/10/2007 6:01:23 AM: Snapshot stored, 2,745 KB

8/10/2007 6:41:41 AM: Execution completed successfully

Remaining: 4 files, 585 KB

Completed: 4642 files, 477.8 MB

Performance: 188.5 MB/minute

Duration: 00:43:09 (00:40:36 idle/loading/preparing)

 

 

- 8/10/2007 6:41:43 AM: Copying ****** on DC3

File "****** \Deleted Items\000000004bc47e6105a250438b2a4b174de5435f0700bcd76c22742d434c94e1d51ad7927de9000000006cd300009cbd87cbc68e10468f9f97d4cae2aeb4000006b53f870000": can't read, error -1101 (file/directory not found)

8/10/2007 7:00:00 AM: Script execution terminated at specified stop time.

8/10/2007 7:00:01 AM: Execution incomplete

Remaining: 1 files, 648 KB

Completed: 4560 files, 966.2 MB

Performance: 182.8 MB/minute

Duration: 00:05:38 (00:00:22 idle/loading/preparing)

 

8/10/2007 7:00:30 AM: Execution incomplete

Total performance: 324.5 MB/minute

Total duration: 10:47:05 (04:31:20 idle/loading/preparing)

 

**** on DC3 is the name of the mailboxes on the exchange server for a brick by brick backup.

As you can see even with a new backup set, that's not compressed, it's still taking a long time "idle/loading/preparing"

Link to comment
Share on other sites

Sorry, similar setup to above -

Retrospect Multiserver 7.5.387; driver and hotfix 7.5.12.103 on an XP Pro sp2 host.

SCSI attached Quatum Superloader 3

Backing up W2k3 and Mac OSX.4 servers.

 

If version 7 took longer then 4 hours to store a snapshot, I think they should be renamed to snore-shots!

Link to comment
Share on other sites

How is this for a ridiculous situation? 10 hours to generate a snapshot? This is after turning off MD5 digests in case that was the issue.

 

Does anybody have experience restoring without a snapshot? How difficult is it to recreate the volume?

 

Thanks

--

 

+ Normal backup using Master Art test at 20/08/2007 7:24 PM (Execution unit 1)

To Backup Set MWF Studio E...

 

- 20/08/2007 7:24:20 PM: Copying MASTER ART on fileserver

21/08/2007 5:33:18 AM: Snapshot stored, 38.7 MB

21/08/2007 5:33:27 AM: Execution completed successfully

Completed: 484 files, 3.1 GB

Performance: 99.6 MB/minute

Duration: 10:09:07 (09:37:24 idle/loading/preparing)

Link to comment
Share on other sites

As a Retrospect backup admin for over 11 years I have never recreated a volume from snapshots. I don't use it. I suppose that it is enabled but I have never used it. I back up ONLY data and not OS stuff. If I have to rebuild a system I will build from ground up, recover "most recent" data and you are there. 99% of the time though I am recovering a single file or folder. Shadow Copy on Windows 2003 server works great here but is by no means a replacement for a backup regiment.

 

I can't imagine having a backup take as long as yours did. Well, yes I can. Look at my post at http://forums.dantz.com/ubbthreads/showflat.php/Cat/0/Number/91275/an/0/page/0#Post91275 to see if that helps out any.

 

By the way, yes, I have had an instance or two where I have not been able to recover something over these years because it was never backed up. A PST file comes to mind which is a can of worms in of itself.

 

 

Tim Berry

Scaled Composites, LLC

Link to comment
Share on other sites

Join the conversation

You can post now and register later. If you have an account, sign in now to post with your account.

Guest
Reply to this topic...

×   Pasted as rich text.   Paste as plain text instead

  Only 75 emoji are allowed.

×   Your link has been automatically embedded.   Display as a link instead

×   Your previous content has been restored.   Clear editor

×   You cannot paste images directly. Upload or insert images from URL.

Loading...
×
×
  • Create New...