Incredibly long 'closing times 2.25 hrs for a simple backup - HELP

[robfol 0]

Can anyone help with suggestions please ???

 

I duplicate my main volume to external drives daily, rarely more than 2Gb incremental data every time, yet every backup takes from 1hr 30 mins to over two hours. Basic data transfer & compare takes 15 to 20 minutes but between them Retrospect stays in 'closing' mode for 40 mins to 1hr 30 mins.

 

Today 32433 files 2.3Gb of data - started at 17.48 finished 'closing' at 20.02 finished compare at 20.15 - that's almost 2.25 hrs !! for a simple backup

 

This is a totally clean PowerMac G5 with latest 10.48 system and fast clean drives

 

retrospect 6.1.126 and driver 6.1.9.102

 

? Retrospect version 6.1.126

launched at 30/1/2007 17:47

+ Retrospect Driver Update, version 6.1.9.102

+ Duplicate using G5 Back TOUGH at 30/1/2007 17:48

- 30/1/2007 17:48:12: Copying RFA PowerMac G5…

30/1/2007 20:02:48: Comparing RFA G5 Back Tough…

30/1/2007 20:15:28: 138 execution errors.

Completed: 32431 files, 2.4 GB

Performance: 33.3 MB/minute (18.3 copy, 188.3 compare)

Duration: 02:27:16 (00:03:42 idle/loading/preparing)

[rhwalker 2]

How big is your catalog? How far back does the backup set go? Do you have catalog compression enabled? What is the speed (GHz/Mhz) rating of your PowerMac G5? How much RAM does your PowerMac G5 have?

 

For comparison, on our Xserve G5, single processor, 2.0 GHz, 2 GB RAM, our backup sets span about a month for our server and all clients on our small network. If we store the catalog uncompressed, it takes about 5 to 10 minutes to do the closing. If we store the catalog uncompressed, it can take 20 to 30 minutes, I recall (we don't do that any more). There's also the rewind time for the VXA-2 drive in our autoloader, which takes a few minutes (we have to do rewind on close because of a Retrospect/Exabyte bug - finger pointing going on here - where a tape is unreadable by Retrospect on insertion if it is not inserted at BOT; other backup programs don't have this problem, but Retrospect does, so you have to rewind for the next backup).

 

What we do is store the catalog uncompressed and then, after we move to the next backup set (new media), we configure the now-closed backup set to have a compressed catalog (so it only gets compressed once) to conserve space. Our uncompressed catalogs are about 1 GB, our compressed catalogs are about 225 MB.

 

Russ

[CallMeDave 7]

Quote:

---

I duplicate my main volume to external drives daily, rarely more than 2Gb incremental data every time, yet every backup takes from 1hr 30 mins to over two hours.

 

---

 

A Duplicate is different from a Backup in Retrospect. So Russ' questions about Catalogs are not relevant for you.

 

If you're not going to take advantage of Retrospect's excellent backup capabilities you might want to try any of the other popular duplication tools on the market for OS X, such as SuperDuper! or Carbon Copy Cloner.

[rhwalker 2]

oops, missed the word "duplicate" in the original post and in the log. Sloppy reading. My bad. Sorry.

 

Dave is right. He must have had more sleep than I did. Ignore everything I posted above.

 

If you look at the log carefully, which I should have done, you see that the duplicate took almost 2 hours, 15 minutes, but the compare took only 13 minutes.

 

New set of questions:

 

Is it possible that you have a very complex selector for the duplicate?

How many files are on your source disk that the selector is rummaging through?

What is the speed (GHz/Mhz) rating of your PowerMac G5?

How much RAM does your PowerMac G5 have?

 

Either you are thrashing during the compare (would need more RAM), or your processor is very slow (need faster processor), or you have some huge amount of files and are just selecting a few with your selector (subvolumes might help for this so that the full disk wouldn't have to be scanned).

 

Russ

[Lennart_T 152]

How many files/folders are there in total on the hard drive?

 

During the "closing" phase, Retrospects sets up permissions on ALL files/folders, not only the ones that was just copied over.

 

I have seen very long "closing" times myself, but I have NO idea what's causing it. Most of the time it goes as fast as the scanning.

[robfol 0]

THANKS FOR HELP

 

The initial scan takes time due to 75Gb of data but is sensible

The actual data copy averaging 2.5Gb is fast as is the compare phase

It is the closing phase after data tranfer that takes forever often 1hr 30 mins

FYI cloning my data folder with 15Gb the closing takes 10 seconds or less

This has only been a problem with recent version of Retrospect

I think V6.0 was claimed to fix this as a known problem

 

So to dupe/copy 2.5Gb from a 15Gb folder takes about 15 mins

AND to dupe same data from 75Gb volme can take ove two hours. Not the right multiple (-:

 

>Is it possible that you have a very complex selector for the duplicate?

NO - just dupe complete main volume to clone volume

 

>How many files are on your source disk that the selector is rummaging through?

75Gb of data not sure of number, but must be many thousands. How do I find out?

FYI cloning my data folder with 15Gb the closing takes 10 seconds or less

 

> What is the speed (GHz/Mhz) rating of your PowerMac G5?

> How much RAM does your PowerMac G5 have?

This is a 2.5GHz Quad Core G5 with 2GB memory so no shortage of power or memory

 

>During the "closing" phase, Retrospects sets up permissions on ALL files/folders, not only the ones that was just copied > over. I have seen very long "closing" times myself, but I have NO idea what's causing it. Most of the time it goes as

> fast as the scanning.

The closing takes at 10 to 15 times longer than scan phase

[robfol 0]

BAD RUN

 

? Retrospect version 6.1.126

launched at 31/1/2007 18:58

+ Retrospect Driver Update, version 6.1.9.102

 

+ Duplicate using G5 Back at 31/1/2007 18:59

 

- 31/1/2007 18:59:36: Copying RFA PowerMac G5…

Can't write file “.journal”, error -48 (duplicate name), path: “RFA PowerMac G5/.journal”.

Can't write file “.journal_info_block”, error -48 (duplicate name), path: “RFA PowerMac G5/.journal_info_block”.

31/1/2007 20:04:57: Comparing RFA G5 BACK…

File “console.log”: different data size (src: 408,816, dest: 406,479), path: “RFA PowerMac G5/Library/Logs/Console/501/console.log”.

File “asl.log”: different data size (src: 335,960, dest: 335,642), path: “RFA PowerMac G5/private/var/log/asl.log”.

File “mail.log”: different data size (src: 464,714, dest: 459,071), path: “RFA PowerMac G5/private/var/log/mail.log”.

File “system.log”: different data size (src: 2659, dest: 2527), path: “RFA PowerMac G5/private/var/log/system.log”.

File “blued.plist”: different creation date/time (src: 31/1/2007 19:53:30, dest: 31/1/2007 17:06:28), path: “RFA PowerMac G5/private/var/root/Library/Preferences/blued.plist”.

File “hdiejectd.pid”: different modification date/time (src: 31/1/2007 20:02:53, dest: 31/1/2007 19:32:32), path: “RFA PowerMac G5/private/var/run/hdiejectd.pid”.

File “master.pid”: different modification date/time (src: 31/1/2007 20:08:52, dest: 31/1/2007 19:35:27), path: “RFA PowerMac G5/private/var/spool/postfix/pid/master.pid”.

File “.database.lockN”: different modification date/time (src: 31/1/2007 19:53:32, dest: 31/1/2007 19:23:25), path: “RFA PowerMac G5/Users/robfol/Library/Application Support/AddressBook/.database.lockN”.

File “io.log”: different data size (src: 2,130,268, dest: 2,095,150), path: “RFA PowerMac G5/Users/robfol/Library/Application Support/BluePhoneElite/Devices/00-15-2a-1f-95-e4/io.log”.

File “attributes.plist”: different creation date/time (src: 31/1/2007 19:53:32, dest: 31/1/2007 17:06:29), path: “RFA PowerMac G5/Users/robfol/Library/Application Support/BluePhoneElite/SMS Archive/Phones/00-15-2a-1f-95-e4/attributes.plist”.

File “Applications”: different modification date/time (src: 31/1/2007 20:00:08, dest: 31/1/2007 19:30:09), path: “RFA PowerMac G5/Users/robfol/Library/FruitMenu Items/Applications”.

File “Utilities”: different modification date/time (src: 31/1/2007 20:00:08, dest: 31/1/2007 19:30:09), path: “RFA PowerMac G5/Users/robfol/Library/FruitMenu Items/Utilities”.

File “com.apple.Bluetooth.plist”: different creation date/time (src: 31/1/2007 19:53:30, dest: 31/1/2007 17:06:28), path: “RFA PowerMac G5/Users/robfol/Library/Preferences/com.apple.Bluetooth.plist”.

File “com.apple.scheduler.plist”: different creation date/time (src: 31/1/2007 20:00:10, dest: 31/1/2007 19:30:12), path: “RFA PowerMac G5/Users/robfol/Library/Preferences/com.apple.scheduler.plist”.

31/1/2007 20:15:14: 16 execution errors.

Completed: 31892 files, 2.2 GB

Performance: 61.1 MB/minute (35.8 copy, 212.8 compare)

 

Duration: 01:15:38 (00:03:35 idle/loading/preparing)

 

Quit at 31/1/2007 22:51

 

GOO RUN

 

? Retrospect version 6.1.126

launched at 1/2/2007 15:54

+ Retrospect Driver Update, version 6.1.9.102

 

+ Duplicate using G5 TO PowerBook at 1/2/2007 15:54

 

- 1/2/2007 15:54:29: Copying Documents on RFA PowerMac G5…

1/2/2007 16:02:23: Comparing Documents on RFA TigerBook…

1/2/2007 16:10:59: Execution completed successfully.

Completed: 602 files, 3.2 GB

Performance: 392.6 MB/minute (414.2 copy, 373.2 compare)

Duration: 00:16:30 (00:00:09 idle/loading/preparing)

[Lennart_T 152]

Quote:

---

The closing takes at 10 to 15 times longer than scan phase

 

---

That's what I'm seeing from time to time. I don't know what causes it. I wish I knew...

[rhwalker 2]

Ok, I'm stumped. Simply as a comment, in the "BAD RUN", the errors are reasonable because these files would have changed during the duration of the backup. They are the types of files that are changing in the background.

 

Do you happen to have any cron or launchd jobs that would kick in during this time? (e.g., spotlight indexing; monthly or weekly find jobs to update the locate database, etc.)

 

Russ

[robfol 0]

Thanks Russ

 

>Do you happen to have any cron or launchd jobs that would kick in during this time? (e.g., spotlight indexing; monthly > weekly find jobs to update the locate database, etc.)

 

Not that I am aware of, there are some maintenace tasks but these are sporadic and the 'long closing' 'bad runs' are consitently bad with every backup two or three times a day

[CallMeDave 7]

Quote:

---

the 'long closing' 'bad runs' are consistently bad with every backup two or three times a day

 

---

 

It should be noted (again and again if necessary) that you are not performing backups.

 

With the exception of the first two entries (-48), all of the entries are the sort of Compare differences that would be expected. The only reason you're not seeing those errors at other times is because your system is quieter (for example, if you don't use Fruit Menu while the backup is running, it won't modify its files, and you won't get a compare error). The presence of log entries does not make an execution "bad."

 

However, I've never before seen Retrospect give an error on the journaling files. These files are part of the disk directory, and can't be deleted. This is likely a red herring, but you might want to look farther back in your log and see if there's any correlation between this specific error and the long closing times.

 

When you are Duplicating a Source with a large number of files to a Destination that also has a large number of files, Retrospect has to scan all the files on the Source, and all the files on the Destination, in order to know which files need to be copied. So it doesn't matter if there are only a few GB to copy, the whole process can take a long time. And if, as those of us who frequent this board suspect, Retrospect feels the need to "close" every file on the Destination, even if they were not just copied over, then you have a problem with duration.

 

Other Duplicate solutions, such as SuperDuper!, don't deal with inode information this way. But they also don't compare Source to Destination the way Retrospect does, so there's a trade off there (speed for safety).

 

Dave