Skip to main content

Restoring an less than 30gb image from an 8TB HDD to a sata ssd is taking forever

Thread needs solution
Beginner
Posts: 1
Comments: 5

A backup of less than 30GB is already taking more than one hour to restore and it still states 38 minutes remaining. It started with something like 30min left and then the estimated time went up and up at some time it estimated several hours.
I have only ~6% CPU load and lots of free memory, so I can't see why it would take that long. It should be done in a few minutes max. And so far I cant even tell if it's really restoring or just wasting my time. At least the progressbar is now at 3/4, but I still fear not much is happening. It cant be right that is is restoring only with ~4mb/sec. That's the write-speed of some of the slowest usb-sticks. The image comes from a 8TB HDD, restored to a blank SATA SSD. Both drives show a fine SMART-status, so there is for sure nothing wrong with them. 
Why is this that slow?
 

0 Users found this helpful
Legend
Posts: 105
Comments: 24712

Daniel, welcome to these public User Forums.

Sorry but impossible to say why your restore was being so slow with just the information given?

How are you performing the restore here?  Is this from within Windows using the ATI application or have you booted from the Acronis rescue media to do this?

Where is the image being restored from?  Is this from an internal, an external or a network drive?   If external, what type of USB connection / port is used?  USB 2.0, USB 3.0 etc?

Has the restore finished now and if so, was it successful or not?

Beginner
Posts: 1
Comments: 5

I was restoring from an installed ATI version on win10. Both drives are directly attached internally to the onboard SATA of the mainboard, no USB- or network-drives involved. 
The restoring was successful, but it took more than 2 hours for the only ~29GB small .TIB file.

Legend
Posts: 105
Comments: 24712

Daniel, download a copy of either the MVP Log Viewer or the newer MVP Assistant tool - link below via the Acronis Community Tools option.

Look at the ti_demon / Demon log for the restore to see if the log holds any clues as to why it took so long to complete?

Beginner
Posts: 1
Comments: 5

Hi Steve, thank you, here is my log-file:

log uuid=7E1948FE-4782-4324-AD5C-BE1605D155EF;  product=True Image;  version=19.0;  build=5128;  task=DAE28578-E4A3-46FE-8F6F-EACE8D67E474;  task_name=win7 (C)
Start= 03.01.2021 16:07:10
id=1;  date/time=03.01.2021 16:07:10;  message=Operation win7 (C) started manually.
id=2;  date/time=03.01.2021 16:07:10;  message=Operation description: Stage Description.
id=3;  date/time=03.01.2021 16:07:11;  message=Aktion: Recovery
id=4;  date/time=03.01.2021 16:07:11;  message=Priority changed to Low.
id=5;  date/time=03.01.2021 16:07:11;  message=Backup-Archiv wiederherstellen Von Datei:  X:\backupdata\eröndersystem\win7 (C)_inc_b1_s2_v1.tib Recovery von:  Disks  
id=6;  date/time=03.01.2021 16:07:11;  message=Pending operation 52 started: 'Laufwerk löschen'.
id=7;  date/time=03.01.2021 16:07:11;  message=Pending operation 14 started: 'Volume wiederherstellen'.
id=8;  date/time=03.01.2021 16:07:12;  message=Pending operation 14 started: 'Volume wiederherstellen'.
id=9;  date/time=03.01.2021 18:27:01;  message=Pending operation 61 started: 'MBR wiederherstellen'.
id=10;  date/time=03.01.2021 18:27:04;  message=Aktion zur Wiederherstellung der Bootfähigkeit wurde gestartet.
id=11;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==
id=12;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==
id=13;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==
id=14;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==
id=15;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==
id=16;  date/time=03.01.2021 18:27:04;  message=Aktion zur Wiederherstellung der Bootfähigkeit wurde beendet.
id=17;  date/time=03.01.2021 18:27:56;  message=Operation has succeeded.
Start= 03.01.2021 16:07:10
Finish= 03.01.2021 18:27:56
Total Time= 02:20:46

Legend
Posts: 105
Comments: 24712

Daniel, the truncated error entries suggest that further error information was in the log (in coded Base64 format).

id=11;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==
id=12;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==
id=13;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==
id=14;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==
id=15;  date/time=03.01.2021 18:27:04;  message= ;  line_tag=0x0
Error_Code=AQ==

Beginner
Posts: 1
Comments: 5

Hi Steve, I did post the full log, but saw now the default option was "short log view". But the regular view doesn't show much more info regarding the error codes. Here it is:

...
id=6;  level=2;  module=1;  code=504;  date/time=03.01.2021 16:07:11
          message=Pending operation 52 started: 'Laufwerk löschen'.
id=7;  level=2;  module=1;  code=504;  date/time=03.01.2021 16:07:11
          message=Pending operation 14 started: 'Volume wiederherstellen'.
id=8;  level=2;  module=1;  code=504;  date/time=03.01.2021 16:07:12
          message=Pending operation 14 started: 'Volume wiederherstellen'.
id=9;  level=2;  module=1;  code=504;  date/time=03.01.2021 18:27:01
          message=Pending operation 61 started: 'MBR wiederherstellen'.
id=10;  level=2;  module=29;  code=0;  date/time=03.01.2021 18:27:04
          message=Aktion zur Wiederherstellung der Bootfähigkeit wurde gestartet.
id=11;  level=2;  module=0;  code=0;  date/time=03.01.2021 18:27:04
          message= ;  line_tag=0x0
Error_Code=AQ==
id=12;  level=2;  module=0;  code=0;  date/time=03.01.2021 18:27:04
          message= ;  line_tag=0x0
Error_Code=AQ==
id=13;  level=2;  module=0;  code=0;  date/time=03.01.2021 18:27:04
          message= ;  line_tag=0x0
Error_Code=AQ==
id=14;  level=2;  module=0;  code=0;  date/time=03.01.2021 18:27:04
          message= ;  line_tag=0x0
Error_Code=AQ==
id=15;  level=2;  module=0;  code=0;  date/time=03.01.2021 18:27:04
          message= ;  line_tag=0x0
Error_Code=AQ==
id=16;  level=2;  module=29;  code=0;  date/time=03.01.2021 18:27:04
          message=Aktion zur Wiederherstellung der Bootfähigkeit wurde beendet.
id=17;  level=2;  module=316;  code=6;  date/time=03.01.2021 18:27:56
          message=Operation has succeeded.

If the more detailed info is somewhere else to find, please let me know where to look for it.
Thanks

Beginner
Posts: 1
Comments: 5

Using MVP Assistant instead of ReadLogFileNewGen.exe, I fond this more detailed log. Since its a long one, I only copied the section from the time around the Error_Codes. But not sure if that helps any forther:

...
03.01.2021 17:52:17.767       5144     GetCurrentSession: > WtsId=1 LogonSid=S-1-5-5-0-151687 User="rechenwerk\danielf"
03.01.2021 17:52:22.771       5144 OnServiceEvent(SE_WORKSTATION_UNLOCK)
03.01.2021 17:52:22.773       5144     GetCurrentSession: > WtsId=1 LogonSid=S-1-5-5-0-151687 User="rechenwerk\danielf"
03.01.2021 18:27:56.819       3056 OnServiceEvent(SE_DEVICE_CHANGED)
03.01.2021 18:27:56.823       8028 RpcImpersonateClient: > error=Error 0x903e8
| line info: 0xf8b755370513679e
| $module: 0x0
|
| error 0xfff0: In diesem Thread sind keine Remoteprozeduraufrufe (RPCs) aktiv
| line info: 0xbd28fdbd64edb8f4
| code: 0x800706bd
| $module: 0x0
03.01.2021 18:27:56.824       8028 RpcRevertToSelf: > error=Error 0x903e8
| line info: 0xf8b755370513679e
| $module: 0x0
|
| error 0xfff0: In diesem Thread sind keine Remoteprozeduraufrufe (RPCs) aktiv
| line info: 0xbd28fdbd64edb8f4
| code: 0x800706bd
| $module: 0x0
03.01.2021 18:27:56.827       8028     GetCurrentSession: > WtsId=1 LogonSid= User="NT-AUTORIT T\SYSTEM"
03.01.2021 18:27:56.950       8548 API Entry: OP=SET_EXIT_ERROR_NOT_RETRY_FLAG Ver=4 Misc=0 Id=10948 IntUser=0 LogonSid=S-1-5-5-0-4331474 User="NT-AUTORIT T\SYSTEM"
03.01.2021 18:27:56.951       8548     Different packet sizes: Client=21 Service=3372
03.01.2021 18:27:56.964       8548   API Reply: OP=SET_EXIT_ERROR_NOT_RETRY_FLAG Ver=4 Status=0 Misc=0 Id=10948
03.01.2021 18:27:56.966       8548 API Entry: OP=STOP_WAIT_CHANGES Ver=4 Misc=0 Id=221 IntUser=0 LogonSid=S-1-5-5-0-4331474 User="NT-AUTORIT T\SYSTEM"
03.01.2021 18:27:56.967       8548   API Reply: OP=STOP_WAIT_CHANGES Ver=4 Status=0 Misc=0 Id=221
03.01.2021 18:27:56.968       8128   API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=1223 Misc=4294967295 Id=0
03.01.2021 18:27:56.970       8128 API Entry: OP=DELETE_TASK Ver=4 Misc=0 Id=5 IntUser=2 LogonSid=S-1-5-5-0-4331474 User="NT-AUTORIT T\SYSTEM"
03.01.2021 18:27:56.972       8128   API Reply: OP=DELETE_TASK Ver=4 Status=0 Misc=0 Id=5
03.01.2021 18:27:56.972       9552   API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Misc=0 Id=5
03.01.2021 18:27:56.972      10972   API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Misc=0 Id=5
03.01.2021 18:27:56.976       9552 API Entry: OP=WAIT_CHANGES_EX Ver=4 Misc=23338640 Id=0 IntUser=-1 LogonSid= User="NT-AUTORIT T\SYSTEM"
03.01.2021 18:27:56.976      10972 API Entry: OP=WAIT_CHANGES_EX Ver=4 Misc=0 Id=0 IntUser=-1 LogonSid=S-1-5-5-0-151687 User="rechenwerk\danielf"
03.01.2021 18:27:56.977       9552     WaitId=219 Product=2 (ATI)
03.01.2021 18:27:56.979      10972     WaitId=220 Product=2 (ATI)
03.01.2021 18:27:56.996       7280       Deleted session
03.01.2021 18:27:57.032       7280     Task 1-39 completed with exit code=0
03.01.2021 18:27:57.034      10972   API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Misc=0 Id=39
03.01.2021 18:27:57.034       9552   API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Misc=23338640 Id=39
03.01.2021 18:27:57.040      10972 API Entry: OP=WAIT_CHANGES_EX Ver=4 Misc=0 Id=0 IntUser=-1 LogonSid=S-1-5-5-0-151687 User="rechenwerk\danielf"
03.01.2021 18:27:57.042      10972     WaitId=220 Product=2 (ATI)
03.01.2021 18:27:57.047       9552 API Entry: OP=WAIT_CHANGES_EX Ver=4 Misc=0 Id=0 IntUser=-1 LogonSid= User="NT-AUTORIT T\SYSTEM"
03.01.2021 18:27:57.048       9552     WaitId=219 Product=2 (ATI)
03.01.2021 18:38:58.965      11452 OnServiceEvent(SE_DEVICE_CHANGED)
03.01.2021 18:38:58.967       3224 RpcImpersonateClient: > error=Error 0x903e8
| line info: 0xf8b755370513679e
| $module: 0x0
|
| error 0xfff0: In diesem Thread sind keine Remoteprozeduraufrufe (RPCs) aktiv
| line info: 0xbd28fdbd64edb8f4
| code: 0x800706bd
| $module: 0x0
03.01.2021 18:38:58.968       3224 RpcRevertToSelf: > error=Error 0x903e8
| line info: 0xf8b755370513679e
| $module: 0x0
|
| error 0xfff0: In diesem Thread sind keine Remoteprozeduraufrufe (RPCs) aktiv
| line info: 0xbd28fdbd64edb8f4
| code: 0x800706bd
| $module: 0x0
03.01.2021 18:38:58.969       3224     GetCurrentSession: > WtsId=1 LogonSid= User="NT-AUTORIT T\SYSTEM"
 

Legend
Posts: 105
Comments: 24712

Daniel, thanks for the extra log information.  The error entries all look to be long after the main time was taken doing the restore operations, so are probably nothing to cause real concern.

Note: the latest log you posted is from the Scheduler 2 service which is not relevant for this issue.

Looking back over the various log entries, the real area where the most time was lost was when the second Volume was restored which took from 16:07 until 18:27 to complete.

id=6;  date/time=03.01.2021 16:07:11;  message=Pending operation 52 started: 'Laufwerk löschen'.
id=7;  date/time=03.01.2021 16:07:11;  message=Pending operation 14 started: 'Volume wiederherstellen'.
id=8;  date/time=03.01.2021 16:07:12;  message=Pending operation 14 started: 'Volume wiederherstellen'.
id=9;  date/time=03.01.2021 18:27:01;  message=Pending operation 61 started: 'MBR wiederherstellen'.

What I find most strange here is that when doing any OS restore starting from the ATI installed application running in Windows, this should prompt for the PC to be restarted in order to continue with the restore, not do this on the active Windows system!
See KB 59870: Acronis True Image: how to restore the system to the original disk from within running Windows - where step 11. onwards shows the expected behaviour!

I suspect that if you had booted your PC from the Acronis Rescue Media directly and performed this restore, that it would have been significantly quicker than the 2 hours 20 minutes it took in Windows.

Beginner
Posts: 1
Comments: 5

Hi Steve, I wasn't restoring to the currently running Windows partition. Both drives, the HDD and the SSD are not the same, where the current windows is running from, otherwise I probably would have been asked to reboot, apart from that I wasn't asked to reboot or giving a choice.
So far when using previous versions, I often restored system-partitions way bigger than this one, without rebooting (unless it was the active windows) and it never took that long, even with older and slower harddrives.
So for me I still cant see a reason why it took so long.

 

Legend
Posts: 105
Comments: 24712

Daniel, from your comments above, I assume that this is a dual-boot system with 2 separate copies of Windows.

I have not done any testing of ATI 2021 with any similar scenario and no longer have any dual-boot systems as I decided to use VMware virtual machines with my main PC  instead of using dual-boot on an EFI machine.  I used to have a triple-boot machine with Win 10 (standard & Insiders) plus Ubuntu Linux where this was run on a Legacy / MBR system.  That would have been running ATI 2018, 2019 or perhaps even 2020 early on.