locked
WHS backup stops at 17--19% RRS feed

  • Question

  • I have eight computers connected to my WHS.  Only one XP Pro computer is giving me problems. 
    The problem computer is XP Pro P4 fully patched 1GB RAM 2HDs Gigabit NIC and switch on LAN.  Latest NIC driver and it passes diagnositics.  WHS Toolkit finds no errors.  Latest Intel drivers.  I have run chkdsk /r/f on both drives numerous times.  I ran SeaTools as well.  Neither found any disk errors.  I removed the computer from WHS's  computer list.  I defragged both drives.  I ran cleanup on both drives.  I ran SFC /scannow.  The XP computer reports no errors I can find.    I reconnected the computer but it still stpos at 17% for no apparent reason.  What should I do next to overcome the stuck backups?  Please advise.  Thank you.
    Tuesday, November 10, 2009 12:56 AM

All replies

  • Please check this thread
    Tuesday, November 10, 2009 10:01 AM
    Moderator
  • Thank you the Volume Shadow Copy Service was indeed stopped. 

    I followed that thread and both registered and restarted the service.  On reboot, the service was started as it should have been.  I have a backup running presently.

    THANK YOU again from Alaska.
    Tuesday, November 10, 2009 7:48 PM
  • Well, let' hope it's fixed now.
    Tuesday, November 10, 2009 8:27 PM
    Moderator
  • Sadly, it is sitting at 17% with the harddisk LED flashing intermittently but that appears to be all.  Any other thoughts?  Thank you
    Tuesday, November 10, 2009 9:04 PM
  • How long does it stay at 17%? What's the Backup Status? If it's the first backup you may need to be a little patient. Also I guess my first answer is unlikely to be correct, if it's problem creating shadow copy I think the backup would fail sooner.

    If the backup stays at this percentage for more then one hour please check

    1. The eventlogs on the client and server (Start, Run type eventvwr.msc and Hit Enter) for any errors
    2. The backup logs on the client for errors;  C:\Documents and Settings\All Users\Application Data\Microsoft\Windows Home Server\logs\Backupengine.xxx.yyy.zzz.log
    3.  The backup logs on the server for errors; C:\Documents and Settings\All Users\Application Data\Microsoft\Windows Home Server\logs\backup-mmddyy.log
    Tuesday, November 10, 2009 11:45 PM
    Moderator
  • It has increased 1% to 18% since my last post 3h 20m ago.  If successful.  This would be the first backup.  I have used the tool to cleanup backups to delete numerous incomplete backups. 
    I will check the various logs and get back to you.
    Thank you again for the assistance.  It is appreciated.
    Tuesday, November 10, 2009 11:53 PM
  • Hmm, it does seem very slow to me. What's the Backup Status?

    Could be one of the client disk controllers is running in PIO mode (check in device management), or one of the disks is nearly full

    Other option would be problem with NIC or Nic driver or NIC settings on either server or client. You can check network utilisation in Task Manager (should be around 20% or more). Make sure you have the latest stable driver version on all systems. If you there's MS drivers available for your NIC these are generally preferred over the latest vendor drivers. Sometimes it helps to set the NIC at fixed speed instead of auto negotiate.

    Wednesday, November 11, 2009 12:18 AM
    Moderator
  • Second try, first reply failed

    I installed the latest drivers for  the client's NIC yesterday.  I also ran the NIC diagnostic that it passed.  I will check the server's NIC and the network utilization though the server is not having problems with the  7 other computers.

    Here are the logs

    Event Viewer Logs –

    1
    --Backup set 2 started on MUSTANG.

     

    For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.

     

    2 -- Backup of volume C: to MUSTANG failed: Operation cancelled by client

     

    For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.

     

    3 -- Backup set 2 on MUSTANG failed: Microsoft.HomeServer.Common.Client.OperationCancelledException: The backup operation has been cancelled.

       at Microsoft.HomeServer.Backup.BackupOp.BackupControl.StepProgress()

       at Microsoft.HomeServer.Backup.BackupOp.BackupOperation.DoClusterPass2()

       at Microsoft.HomeServer.Backup.BackupOp.BackupOperation.RunWithoutCatch()

       at Microsoft.HomeServer.Backup.BackupOp.BackupOperation.Run()

       at Microsoft.HomeServer.Backup.BackupOp.BackupSetOperation.RunWithoutCatch()

       at Microsoft.HomeServer.Backup.BackupOp.BackupSetOperation.Run()

     

    1For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.

     

    Backupengine logs on client

     

     

    Created at 10/11/2009 10:35:38 AM

    ***** Started at 10/11/2009 10:35:38 AM ***

    ***** Started at 10/11/2009 10:35:38 AM ***

    [1]091110.103539.0000: Status: Start

    [1]091110.103539.7656: Status: Connect to server MUSTANG, session 4418e58f-7c34-413e-b642-630f1a647a6c, protocol 20

    [1]091110.103540.2968: Status: Volume b183d366-9c0f-11da-89bf-806d6172696f = C:

    [1]091110.103540.2968: Status: Volume b183d364-9c0f-11da-89bf-806d6172696f = D:

    [1]091110.103624.5156: Status: Acquire volume shadows

    [1]091110.103646.0781: Status: Volume 1 of 2 is C: size 164686523904 used 112703704576

    [1]091110.103646.2968: Status: Start volume C: using \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy1

    [1]091110.103647.1406: Status: Volume (shadow) size 164686520320 used 112804798464

    [1]091110.103709.9843: Status: File records: 152530 sent, 152515 changed, 15 metadata, 0 received (bytes sent=3030938 received=1)

    [1]091110.103710.0468: Status: Prepare fixups: total restore size 158895296512

    [1]091110.103710.7656: Status: Determine changed: scan 26254282 size 107537539072

    [1]091110.113332.0937: Status: Determine changed: scanned 26254282 of 26254282 total with 4 fixups (bytes sent=550681683 received=0)

    [1]091110.113602.9218: Status: Server phase Reorganize1 complete

    [1]091110.113602.9218: Status: Send changed: 16527241 requested of 26254282 total

    [1]091110.153603.0156: Status: Exception: Cancel

    [1]091110.153603.5312: Status: Bytes sent=2771766761, bytes received=81920, 0 reconnects

     

    Created at 09/11/2009 2:00:41 PM

    ***** Started at 09/11/2009 2:00:41 PM ***

    ***** Started at 09/11/2009 2:00:41 PM ***

    [1]091109.140041.6093: Status: Start

    [1]091109.140042.3437: Status: Connect to server MUSTANG, session 4cb1609a-d878-4d1c-bc0a-5f3b8b0d42c9, protocol 20

    [1]091109.140042.8750: Status: Volume b183d366-9c0f-11da-89bf-806d6172696f = C:

    [1]091109.140042.8750: Status: Volume b183d364-9c0f-11da-89bf-806d6172696f = D:

    [1]091109.140117.9531: Status: Acquire volume shadows

    [1]091109.140132.0781: Status: Volume 1 of 2 is C: size 164686523904 used 112614030848

    [1]091109.140132.2968: Status: Start volume C: using \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy1

    [1]091109.140133.1718: Status: Volume (shadow) size 164686520320 used 112714215424

    [1]091109.140154.7031: Status: File records: 152490 sent, 152475 changed, 15 metadata, 0 received (bytes sent=3030938 received=1)

    [1]091109.140154.7812: Status: Prepare fixups: total restore size 158895296512

    [1]091109.140155.5000: Status: Determine changed: scan 26253422 size 107534016512

    [1]091109.150057.5468: Status: Determine changed: scanned 26253422 of 26253422 total with 4 fixups (bytes sent=550662806 received=0)

    [1]091109.150321.7500: Status: Server phase Reorganize1 complete

    [1]091109.150321.7500: Status: Send changed: 16559428 requested of 26253422 total

    [1]091109.202147.5625: Status: Exception: Cancel

    [1]091109.202147.7968: Status: Bytes sent=3510275873, bytes received=81920, 0 reconnects

     

    Created at 08/11/2009 3:03:19 PM

    ***** Started at 08/11/2009 3:03:19 PM ***

    ***** Started at 08/11/2009 3:03:19 PM ***

    [1]091108.150319.0312: Status: Start

    [1]091108.150319.2968: Status: Connect to server MUSTANG, session e420a6bb-84e9-48d4-9b23-2326914b6c77, protocol 20

    [1]091108.150319.7968: Status: Volume b183d366-9c0f-11da-89bf-806d6172696f = C:

    [1]091108.150319.7968: Status: Volume b183d364-9c0f-11da-89bf-806d6172696f = D:

    [1]091108.150332.4375: Status: Acquire volume shadows

    [1]091108.150342.1718: Status: Volume 1 of 2 is C: size 164686523904 used 112753794560

    [1]091108.150342.3593: Status: Start volume C: using \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy1

    [1]091108.150343.3125: Status: Volume (shadow) size 164686520320 used 112960364544

    [1]091108.150404.2031: Status: File records: 152558 sent, 152543 changed, 15 metadata, 0 received (bytes sent=3030938 received=1)

    [1]091108.150404.2500: Status: Prepare fixups: total restore size 162293043200

    [1]091108.150404.9687: Status: Determine changed: scan 26261788 size 107568283648

    [1]091108.160130.3593: Status: Determine changed: scanned 26261788 of 26261788 total with 4 fixups (bytes sent=550926324 received=0)

    [1]091108.160359.1875: Status: Server phase Reorganize1 complete

    [1]091108.160359.1875: Status: Send changed: 16562225 requested of 26261788 total

    [1]091108.183458.5625: Error: ReconnectableStream: Write catch IOException Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host., generation 1, reconnect

    [1]091108.183752.6250: Status: Exception: Cancel

    [1]091108.183752.6406: Status: Bytes sent=1998572895, bytes received=65536, 1 reconnects

     

    Created at 08/11/2009 3:03:19 PM

    ***** Started at 08/11/2009 3:03:19 PM ***

    ***** Started at 08/11/2009 3:03:19 PM ***

    [1]091108.150319.0312: Status: Start

    [1]091108.150319.2968: Status: Connect to server MUSTANG, session e420a6bb-84e9-48d4-9b23-2326914b6c77, protocol 20

    [1]091108.150319.7968: Status: Volume b183d366-9c0f-11da-89bf-806d6172696f = C:

    [1]091108.150319.7968: Status: Volume b183d364-9c0f-11da-89bf-806d6172696f = D:

    [1]091108.150332.4375: Status: Acquire volume shadows

    [1]091108.150342.1718: Status: Volume 1 of 2 is C: size 164686523904 used 112753794560

    [1]091108.150342.3593: Status: Start volume C: using \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy1

    [1]091108.150343.3125: Status: Volume (shadow) size 164686520320 used 112960364544

    [1]091108.150404.2031: Status: File records: 152558 sent, 152543 changed, 15 metadata, 0 received (bytes sent=3030938 received=1)

    [1]091108.150404.2500: Status: Prepare fixups: total restore size 162293043200

    [1]091108.150404.9687: Status: Determine changed: scan 26261788 size 107568283648

    [1]091108.160130.3593: Status: Determine changed: scanned 26261788 of 26261788 total with 4 fixups (bytes sent=550926324 received=0)

    [1]091108.160359.1875: Status: Server phase Reorganize1 complete

    [1]091108.160359.1875: Status: Send changed: 16562225 requested of 26261788 total

    [1]091108.183458.5625: Error: ReconnectableStream: Write catch IOException Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host., generation 1, reconnect

    [1]091108.183752.6250: Status: Exception: Cancel

    [1]091108.183752.6406: Status: Bytes sent=1998572895, bytes received=65536, 1 reconnects

     

    Created at 08/11/2009 3:03:19 PM

    ***** Started at 08/11/2009 3:03:19 PM ***

    ***** Started at 08/11/2009 3:03:19 PM ***

    [1]091108.150319.0312: Status: Start

    [1]091108.150319.2968: Status: Connect to server MUSTANG, session e420a6bb-84e9-48d4-9b23-2326914b6c77, protocol 20

    [1]091108.150319.7968: Status: Volume b183d366-9c0f-11da-89bf-806d6172696f = C:

    [1]091108.150319.7968: Status: Volume b183d364-9c0f-11da-89bf-806d6172696f = D:

    [1]091108.150332.4375: Status: Acquire volume shadows

    [1]091108.150342.1718: Status: Volume 1 of 2 is C: size 164686523904 used 112753794560

    [1]091108.150342.3593: Status: Start volume C: using \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy1

    [1]091108.150343.3125: Status: Volume (shadow) size 164686520320 used 112960364544

    [1]091108.150404.2031: Status: File records: 152558 sent, 152543 changed, 15 metadata, 0 received (bytes sent=3030938 received=1)

    [1]091108.150404.2500: Status: Prepare fixups: total restore size 162293043200

    [1]091108.150404.9687: Status: Determine changed: scan 26261788 size 107568283648

    [1]091108.160130.3593: Status: Determine changed: scanned 26261788 of 26261788 total with 4 fixups (bytes sent=550926324 received=0)

    [1]091108.160359.1875: Status: Server phase Reorganize1 complete

    [1]091108.160359.1875: Status: Send changed: 16562225 requested of 26261788 total

    [1]091108.183458.5625: Error: ReconnectableStream: Write catch IOException Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host., generation 1, reconnect

    [1]091108.183752.6250: Status: Exception: Cancel

    [1]091108.183752.6406: Status: Bytes sent=1998572895, bytes received=65536, 1 reconnects

     

    Created at 07/11/2009 4:00:19 PM

    ***** Started at 07/11/2009 4:00:19 PM ***

    ***** Started at 07/11/2009 4:00:19 PM ***

    [1]091107.160019.2343: Status: Start

    [1]091107.160040.5468: Status: Exception: ClientException

    [1]091107.160040.5468: Status:          : SocketException

    [1]091107.160040.5468: Status:          : A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 192.168.0.138:8912

    [1]091107.160040.5468: Status:          :    at System.Net.Sockets.TcpClient..ctor(String hostname, Int32 port)

       at Microsoft.HomeServer.Backup.Protocol.BackupProtocol.OpenServer()

       at Microsoft.HomeServer.Backup.Protocol.BackupProtocol..ctor(String serverName, Int32 LowestVersion)

       at Microsoft.HomeServer.Backup.BackupOp.BackupSetOperation.RunWithoutCatch()

       at Microsoft.HomeServer.Backup.BackupOp.BackupSetOperation.Run()

     

    Backup logs on server

     

    Created at 11/9/2009 1:51:14 PM

    ***** Started at 11/9/2009 1:51:14 PM ***

    ***** Closed at 11/9/2009 1:51:14 PM ***

     

    Created at 11/9/2009 1:45:08 PM

    ***** Started at 11/9/2009 1:45:08 PM ***

    ***** Closed at 11/9/2009 1:45:08 PM ***

     

     

    Wednesday, November 11, 2009 1:45 AM
  • The client IDE controller is set to Ultra DMA mode 6, Intell driver. The server IDE controller is set to Auto Detect DMA if available, MS driver. I set the client Marvel Yuknon NIC to fixed 1G, Marvel's driver. Both the server and the client report their NICs are each running at 1G The network utilization though is between 0 and .6% spikes. What would be choking the link? I will let you know if it tanks again at 17%
    Wednesday, November 11, 2009 2:11 AM
  • ...Other option would be problem with NIC or Nic driver or NIC settings on either server or client....


    I had a similar problem caused by client NIC settings...as soon as the client went from Reorganizing Data to Sending Data on the backup dialog box, the NIC would lose connection.  The Atheros NIC had a driver setting called Task Offload that was set to "On" by default.  Switching that option off solved the problem.
    Wednesday, November 11, 2009 3:05 AM
  • I played with all the advanced settings for the client's NIC.  Nothing showed a significant increase in bandwidth. It has been at 17% now for quite a long time with no change.  The netork monitor shows low level activitiy.
    Wednesday, November 11, 2009 4:35 AM
  • Guys, I tried tweaking XPPro client's LAN registry setting to increase caches and such, per this site http://www.speedguide.net/read_articles.php?id=1607 It appears to have made a significant improvement in smoothlng out the flow of data.  The client's Task Manager Network Performance graph is fairly flat now at ~.25% without the wild swings, dropping to zero, as before.  I will report back if this backup completes successfully.  If so, I will likely make the same changes to the server's registry to smooth out the flow rates. 
    Wednesday, November 11, 2009 11:10 PM
  • So far so good.  I am up to 27% complete, first time ever with that computer.  Network Utilization has also increased to 10% on the client XP Pro. Both good signs, maybe its going to make it to completion?
    Wednesday, November 11, 2009 11:57 PM
  • Yippee.  Completed successfully. 

    The Network utilization dropped to a flat 10% but it worked.  I am going to tweak some of the other TCPIP setting on that computer to see if I can get the utilization number up.
    Thursday, November 12, 2009 3:23 AM
  • A second backup completed in 20 minutes. 
    Thursday, November 12, 2009 5:28 AM
  • Yippee.  Completed successfully. 

    The Network utilization dropped to a flat 10% but it worked.  I am going to tweak some of the other TCPIP setting on that computer to see if I can get the utilization number up.

    Glad it's fixed now!
    Thursday, November 12, 2009 7:31 AM
    Moderator
  • Thanks,
    Since optimizing the client was so successful.  I would like to do the same to the server for a 1G Lan.  Do you know of any sites with similar information for WHS or Server 2003?
    Thursday, November 12, 2009 4:01 PM
  • Guys, I have no direct comparison stats, however, these suggested 1G NIC tweaks do appear to provide a boost --  http://www.enterprisenetworkingplanet.com/nethub/article.php/10950_3485486_2 
    Saturday, November 14, 2009 5:31 AM