nezster Posted October 21, 2003 Report Share Posted October 21, 2003 Hello, We are currently running Retrospect version 5.0.238 on our OSX server. There are two users of this server, both of which log out of their workstations at the end of the day. Each night we run a scheduled full backup to tape. This backup begins at 7pm. However, when the two members of staff start their shift at 6:30am the backup is still running. I have to manually stop the backup. As a result the only successful backup we get is on a friday. The friday backup begins at 7pm and completes at 5:30am on the following sunday! We have looked into the scheduling of the backup jobs and cannot find anything wrong. However, we have found a solution albeit impracticle. At the end of the day if we reboot the server the backup executes at 7pm as scheduled and finishes before 6am the following day. Any advice / ideas you guys have would be greatly appreciated. Why would rebooting the server allow us to do a successful backup within 12 hours? I need a solution to this as I cannot keep rebooting the server every night. If you need me to post any further information then please reply and I will supply whatever is needed. Thanks in advance guys. Link to comment Share on other sites More sharing options...
CallMeDave Posted October 21, 2003 Report Share Posted October 21, 2003 Quote: If you need me to post any further information then please reply and I will supply whatever is needed. Relevant portions of the Operations Log, showing a comparason between the long and short Executions would certainly be helpful... Dave Link to comment Share on other sites More sharing options...
nezster Posted October 22, 2003 Author Report Share Posted October 22, 2003 Hello, This is a copy of the Log from last night. I rebboted the server before I went home and the backup started at 6pm and successfully completed at 6:30am. I will post the log from ther day before in a seperate reply. The day before I had to stop the backup as it was taking too long. Hopefully this log will reveal the problem... -------------------------------------------------------------------------------------------------------- ∆ Retrospect version 5.0.238 launched at 10/21/2003 5:28 PM + Retrospect Driver Update, version 3.1.105 Quit at 10/21/2003 5:28 PM ∆ Retrospect version 5.0.238 launched at 10/21/2003 5:49 PM + Retrospect Driver Update, version 3.1.105 Quit at 10/21/2003 5:49 PM ∆ Retrospect version 5.0.238 automatically launched at 10/21/2003 6:00 PM + Retrospect Driver Update, version 3.1.105 + Normal backup using 2 - Tuesday at 10/21/2003 6:00 PM To backup set Tuesday/05/03… - 10/21/2003 6:00:20 PM: Copying Mirror1… 10/21/2003 6:13:39 PM: Comparing Mirror1… File “WindowsFileService.log”: different data size (set: 150,675, vol: 151,466), path: “Mirror1/Library/Logs/WindowsServices/WindowsFileService.log”. File “Operations Log”: different data size (set: 852,857, vol: 852,916), path: “Mirror1/Library/Preferences/Retrospect/Operations Log”. File “secrets.tdb”: miscompare at data offset 737, path: “Mirror1/private/var/db/samba/secrets.tdb”. File “system.log”: different data size (set: 27,241, vol: 27,350), path: “Mirror1/private/var/log/system.log”. File “access_log”: different data size (set: 834,692, vol: 853,736), path: “Mirror1/private/var/log/cups/access_log”. File “servermgr_afp.lock”: different data size (set: 107,457, vol: 107,514), path: “Mirror1/private/var/servermgrd/servermgr_afp.lock”. File “servermgr_info.lock”: different data size (set: 111,092, vol: 111,151), path: “Mirror1/private/var/servermgrd/servermgr_info.lock”. File “servermgr_qtss.lock”: different data size (set: 107,812, vol: 105,644), path: “Mirror1/private/var/servermgrd/servermgr_qtss.lock”. File “servermgr_smb.lock”: different data size (set: 107,378, vol: 107,436), path: “Mirror1/private/var/servermgrd/servermgr_smb.lock”. File “servermgr_web.lock”: different data size (set: 189,983, vol: 190,072), path: “Mirror1/private/var/servermgrd/servermgr_web.lock”. File “browse.dat”: different creation date/time (set: 10/21/2003 6:06:04 PM, vol: 10/21/2003 6:13:48 PM), path: “Mirror1/private/var/spool/lock/browse.dat”. File “connections.tdb”: miscompare at data offset 170, path: “Mirror1/private/var/spool/lock/connections.tdb”. File “unexpected.tdb”: miscompare at data offset 170, path: “Mirror1/private/var/spool/lock/unexpected.tdb”. 10/21/2003 6:19:53 PM: 13 execution errors. Completed: 53301 files, 1.5 GB Performance: 163.1 MB/minute (120.9 copy, 250.2 compare) Duration: 00:19:33 (00:01:33 idle/loading/preparing) - 10/21/2003 6:19:55 PM: Copying Mirror2… 10/21/2003 7:30:38 PM: Comparing Mirror2… 10/21/2003 8:56:15 PM: Execution completed successfully. Completed: 19338 files, 70.9 GB Performance: 34.5 MB/minute (38.1 copy, 31.4 compare) Duration: 02:36:20 (00:01:46 idle/loading/preparing) 10/21/2003 8:56:16 PM: 13 execution errors. Total performance: 47.9 MB/minute Total duration: 02:55:55 (00:03:19 idle/loading/preparing) + Duplicate using Sets at 10/22/2003 6:30 AM - 10/22/2003 6:30:10 AM: Copying Sets on Mirror1… 10/22/2003 6:30:19 AM: Comparing Retrospect Sets on Mirror2… 10/22/2003 6:30:22 AM: Execution completed successfully. Completed: 2 files, 60.2 MB Performance: 601.8 MB/minute (401.2 copy, 1203.6 compare) Duration: 00:00:12 Quit at 10/22/2003 6:31 AM ∆ Retrospect version 5.0.238 launched at 10/22/2003 9:45 AM + Retrospect Driver Update, version 3.1.105 Quit at 10/22/2003 9:47 AM ∆ Retrospect version 5.0.238 launched at 10/22/2003 9:53 AM + Retrospect Driver Update, version 3.1.105 Link to comment Share on other sites More sharing options...
nezster Posted October 22, 2003 Author Report Share Posted October 22, 2003 This is a copy of the log where the backup took too long and ran into the next day. Unlike the log above, no server reboot was performed before backup execution. ---------------------------------------------------------------------------------------------------------- ∆ Retrospect version 5.0.238 launched at 10/20/2003 9:34 AM + Retrospect Driver Update, version 3.1.105 Quit at 10/20/2003 9:37 AM ∆ Retrospect version 5.0.238 launched at 10/20/2003 10:58 AM + Retrospect Driver Update, version 3.1.105 ! 10/20/2003 10:58 AM: Manual Recycle of backup set Monday/05/03 Quit at 10/20/2003 10:58 AM ∆ Retrospect version 5.0.238 automatically launched at 10/20/2003 7:00 PM + Retrospect Driver Update, version 3.1.105 + Normal backup using 1 - Monday at 10/20/2003 7:00 PM To backup set Monday/05/03… - 10/20/2003 7:00:24 PM: Copying Mirror1… 10/20/2003 7:10:49 PM: Comparing Mirror1… File “WindowsFileService.log”: different data size (set: 142,234, vol: 142,394), path: “Mirror1/Library/Logs/WindowsServices/WindowsFileService.log”. File “Operations Log”: different data size (set: 849,273, vol: 849,332), path: “Mirror1/Library/Preferences/Retrospect/Operations Log”. File “hwmond.log”: different data size (set: 5472, vol: 5586), path: “Mirror1/private/var/log/hwmond.log”. File “system.log”: different data size (set: 3693, vol: 3803), path: “Mirror1/private/var/log/system.log”. File “access_log”: different data size (set: 988,701, vol: 1,008,780), path: “Mirror1/private/var/log/cups/access_log”. File “servermgr_afp.lock”: different data size (set: 107,810, vol: 107,924), path: “Mirror1/private/var/servermgrd/servermgr_afp.lock”. File “servermgr_info.lock”: different data size (set: 111,664, vol: 109,656), path: “Mirror1/private/var/servermgrd/servermgr_info.lock”. File “servermgr_qtss.lock”: different data size (set: 106,670, vol: 106,784), path: “Mirror1/private/var/servermgrd/servermgr_qtss.lock”. File “servermgr_smb.lock”: different data size (set: 108,190, vol: 108,306), path: “Mirror1/private/var/servermgrd/servermgr_smb.lock”. File “servermgr_web.lock”: different data size (set: 191,140, vol: 191,318), path: “Mirror1/private/var/servermgrd/servermgr_web.lock”. File “browse.dat”: different creation date/time (set: 10/20/2003 7:05:10 PM, vol: 10/20/2003 7:13:50 PM), path: “Mirror1/private/var/spool/lock/browse.dat”. File “connections.tdb”: miscompare at data offset 294, path: “Mirror1/private/var/spool/lock/connections.tdb”. File “unexpected.tdb”: miscompare at data offset 170, path: “Mirror1/private/var/spool/lock/unexpected.tdb”. 10/20/2003 7:17:19 PM: 13 execution errors. Completed: 53307 files, 1.5 GB Performance: 193.1 MB/minute (161.9 copy, 239.3 compare) Duration: 00:16:55 (00:01:43 idle/loading/preparing) - 10/20/2003 7:17:22 PM: Copying Mirror2… 10/21/2003 9:22:43 AM: Execution stopped by operator. Remaining: 5717 files, 14.7 GB Completed: 13245 files, 55.2 GB Performance: 66.8 MB/minute Duration: 14:05:21 (00:01:12 idle/loading/preparing) 10/21/2003 9:22:43 AM: Execution stopped by operator. Total performance: 69.1 MB/minute Total duration: 14:22:19 (00:02:55 idle/loading/preparing) You should clean your tape drive. It has been used for 17 hours since the previous cleaning reminder. Quit at 10/21/2003 9:24 AM Link to comment Share on other sites More sharing options...
nezster Posted October 24, 2003 Author Report Share Posted October 24, 2003 Anyone got any ideas? Link to comment Share on other sites More sharing options...
CallMeDave Posted October 24, 2003 Report Share Posted October 24, 2003 In both cases, the first Execution of your script, "Mirror1," completes 1.5 GB of data in about 16 minutes: Completed: 53307 files, 1.5 GB Performance: 193.1 MB/minute (161.9 copy, 239.3 compare) Duration: 00:16:55 (00:01:43 idle/loading/preparing) The second Execution of your script, "Mirror2" completes the first night, but at substantually slower speeds: Completed: 19338 files, 70.9 GB Performance: 34.5 MB/minute (38.1 copy, 31.4 compare) Duration: 02:36:20 (00:01:46 idle/loading/preparing) And this same volume takes 14 hours to get finish only about three quarters of the data. So the question becomes, what sort of drive is "Mirror2?" Dave Link to comment Share on other sites More sharing options...
shadowspawn Posted October 25, 2003 Report Share Posted October 25, 2003 Quote: 10/21/2003 7:30:38 PM: Comparing Mirror2… 10/21/2003 8:56:15 PM: Execution completed successfully. Completed: 19338 files, 70.9 GB Performance: 34.5 MB/minute (38.1 copy, 31.4 compare) Duration: 02:36:20 (00:01:46 idle/loading/preparing) There is something odd going on with this backup, the numbers do not match up. With that performance it should have taken over 24 hours to back up 70 GB. The later backup that ran out of time shows a duration that matches the performance, and the total backup does not fit into 12 hours. I suggest taking a look at which files have been backed up using Reports > Contents. (Wild speculation, perhaps a very large and inappropriate file, like a virtual memory or cache backing file, is included in the backup. It might consist mostly of zeroes when the computer is first booted. I don't whether this explains the odd performance figures though!) Link to comment Share on other sites More sharing options...
Recommended Posts
Archived
This topic is now archived and is closed to further replies.