Backup to NAS very slow in 2020
Just updated (doesnt seem like an update at the moment) to the all singing all dancing much faster ATI 2020
My 1.2Tb backup to NAS now takes around 12 hours.....previously I was using ATI 2018 and it took a mere 6 hours to do the same backup
nothing else has changed and I run it overnight so the PC isnt in use
VSS doctor says there are no issues
so what is causing this tiresome slowdown in the upgrade I have just bought?
David, are you including doing validation with your backup task? If so, try disabling that option in the Advanced Options and see if the backup gives a more reasonable time for completion.
There are known issues with Validation taking much longer in ATI 2020, partially due to the change in file format from .tib to .tibx but also because ATI now seems to want to validate the whole backup chain including earlier version chains if present, instead of just the current one.
Thanks Steve,
no, I am not doing validation
....and in fact the backup took 15 hours which is totally un-acceptable
I did a NAS check and got transfer speeds of around 100mb/sec so clearly thats not the problem
David, sorry but still too little information to really guess at why the backup is taking so long?
Is this a new task that was created using ATI 2020 or an existing task brought forward from your earlier ATI 2018?
Have you checked all the settings for this task since this issue arose?
There is a known problem being reported across multiple different ATI versions where settings are being lost / reset back to defaults (arising on/after Oct 22nd).
How are you connecting to the NAS from this computer?
Is this wireless or wired?
Is your source data all on the same computer where the task is running from?
This is a new task created in 2020...I deleted and cleared all previous installations and backups
settings as attached
WD EX2100 Mycloud NAS is connected via Gigabit ethernet (CAT6) cable via Gigabit ethernet switch
Source data is from PC "D" drive to NAS
David, the settings all look fine to me & thanks for the other information.
Please download the MVP Log Viewer tool (link in my signature below) and use this to review the log file for your backup operation.
Note: with ATI 2020 the ti_demon log only shows minimal information compared to earlier versions as Acronis have moved the detail of backup activity to the backup_worker log instead, but the latter is not a choice in the log viewer tool, so has to be collected manually from the C:\ProgramData\Acronis\TrueImageHome\Logs\backup_worker folder.
If posting the logs to the forum, then please zip them to retain their original names.
I already use the log viewer and havent seen any issues
are these what you are after ?
wont let me use 7-zip!
David, the logs don't tell us any more than that the task started and finished with no detail of any activities in the intervening period, as these look to all be ti_demon logs.
You need to zip up some of the C:\ProgramData\Acronis\TrueImageHome\Logs\backup_worker folder recent logs covering the backup task start / end period, then just upload a single zip file.
The zip file below was created by 7-zip for just the relevant logs you posted above.
hmmm....it wouldnt let me attach my 7zip file... ?????
aha...saved as .zip ......
apologies, I dont use zip very often !
David, the logs appear to be telling a conflicting story here?
The backup to the NAS seems to finish pretty quickly when viewed via the backup_worker log but not according to the ti_demon log, where this shows that you are running a Post Command.
Example taken from 31/10 - ti_demon log first.
31/10/2019 02:31:30 :999 -----
31/10/2019 02:31:30 :999 ATI Demon started. Version: 24.4.1.21400.
31/10/2019 02:31:31 :046 Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
31/10/2019 02:31:31 :046 Operation WDC WD4005FZBX-00K5WB0 01.01A01 started by schedule.
31/10/2019 02:31:31 :062 Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
31/10/2019 02:31:31 :062 Operation: Backup
31/10/2019 07:58:54 :035 Child process has exited with code '0'.
31/10/2019 07:58:54 :035 Execution of user command succeeded: D:/Misc_Updates/PStools/psshutdown.exe
31/10/2019 07:58:54 :066 Operation has succeeded.Start: 31/10/2019 02:31:30
Stop: 31/10/2019 07:58:54
Total Time: 05:27:24
Next, extracts from the corresponding backup_worker log.
10/31/2019 02:31:31 type=retcode; value=0; id=10001;
10/31/2019 02:31:31 >>> id=1
action=backup
action=cleanup
action=metainfo
disk-backup
agent="Acronis True Image 2020 24.4.1.21400 Win"
archive="smb://WDMYCLOUDEX2100/pc/D/WDC WD4005FZBX-00K5WB0 01.01A01.tibx"
10/31/2019 02:31:31 type=log; level=inf; message=
ar#1: opening archive path="\\?\UNC\WDMYCLOUDEX2100\pc\D\/WDC WD4005FZBX-00K5WB0 01.01A01.tibx" in append mode (create);
10/31/2019 02:31:31 type=log; level=inf; message=
ar#1: archive file has unused tail 2650491858944-2650491863040;
10/31/2019 02:31:31 type=log; level=inf; message=
ar#1: archive file unused tail 2650491858944-2650491863040 has been truncated;
10/31/2019 02:31:31 type=log; level=inf; message=
ar#1: opened archive path="\\?\UNC\WDMYCLOUDEX2100\pc\D\/WDC WD4005FZBX-00K5WB0 01.01A01.tibx" mode=append uuid=1a9952b067009eef72095027cce9a6bd reopen=1:0;<< entries for exclusions skipped >>
10/31/2019 02:31:31 type=log; level=inf; message=
ar#1: archive_slice_create(sid=14,type=inc,user_type=inc,uuid=00000000000000000000000000000000,ctime=0);
10/31/2019 02:32:55 type=log; level=inf; message=
ar#1: archive_slice_finish(sid=14);
10/31/2019 02:32:55 type=log; level=inf; message=
ar#1: archive closing;
10/31/2019 02:32:55 type=log; level=inf; message=
io#1: total req: 4629 (rd: 4589 wr: 37 sync: 3), pgreq: 125445 (rd: 90391 wr: 35054) sync: 15.6 ms;<< entries for statistics skipped >>
10/31/2019 02:32:55 type=log; level=inf; message=
ar#1: archive close (commit_seq=170, reuse_seq=170, file_size=2650635440128, uuid=1a9952b067009eef72095027cce9a6bd);
10/31/2019 02:32:55 type=stat; total_nr=206860; total_sz=1544820737657; pics_nr=36290; pics_sz=90638273582; music_nr=3155; music_sz=8710570843; video_nr=356; video_sz=314409984015; docs_nr=6583; docs_sz=2418375779; sys_nr=12147; sys_sz=225899629383; others_nr=148329; others_sz=902743904055; id=1;
10/31/2019 02:32:55 type=log; level=inf; message=
lsm#1: dedup_map nr_lookup=71285 nr_found=8634 false+=5136 (7.20%/59.49%);
10/31/2019 02:32:55 type=log; level=inf; message=
ar#1: opening archive path="\\?\UNC\WDMYCLOUDEX2100\pc\D\/WDC WD4005FZBX-00K5WB0 01.01A01.tibx" in append mode (create);
10/31/2019 02:32:55 type=log; level=inf; message=
ar#1: opened archive path="\\?\UNC\WDMYCLOUDEX2100\pc\D\/WDC WD4005FZBX-00K5WB0 01.01A01.tibx" mode=append uuid=1a9952b067009eef72095027cce9a6bd reopen=1:0;
10/31/2019 02:32:55 type=cleanup; slices_deleted=0; cleaned_up=0; new_size=1321652318208; id=1;<< entries for metainfo skipped >>
10/31/2019 02:32:55 type=log; level=inf; message=
ar#1: archive closing;
10/31/2019 02:32:55 type=log; level=inf; message=
io#1: total req: 2 (rd: 0 wr: 1 sync: 1), pgreq: 1 (rd: 0 wr: 1) sync: 0.0 ms;
10/31/2019 02:32:55 type=log; level=inf; message=
io#1: pg cache hit=5 ra_hit=0 ra_pages=0 ra=0.00%;
10/31/2019 02:32:55 type=log; level=inf; message=
ar#1: umap allocations: 1 times, 0ms total, 0ms max, 0ms average;
10/31/2019 02:32:55 type=log; level=inf; message=
ar#1: wait stats: wr 0 rd 0 compr 0 decompr 0 (ms);
10/31/2019 02:32:55 type=log; level=inf; message=
ar#1: archive close (commit_seq=170, reuse_seq=170, file_size=2650635444224, uuid=1a9952b067009eef72095027cce9a6bd);
10/31/2019 02:32:55 type=retcode; value=0; id=1;
10/31/2019 02:32:55 >>> exit
10/31/2019 02:32:55 >>> exit
The above backup_worker log shows a backup time of around 90 seconds before the log ends with a success exit code (value = 0)...! This seems too fast to allow for the backup data to be transferred across the network to your NAS.
I would suggest removing the Post Command for the purpose of testing the backup without it and see if it makes a difference here?
Otherwise, I would suggest opening a Support Case direct with Acronis and sending them an Acronis System Report to let them review these logs and try to explain what is being shown here?
thanks for studying those!!!!
I should perhaps have mentioned that I have two backups running, the C drive which only has the operating system and programs on and D drive which has all the user data but am guessing you worked that out....
After the initial backup, the C drive (SSD) indeed takes but a few seconds to complete as barely anything changes so that could well be correct.
I watched the D drive backup towards the end of the mammoth 15 hour session and the NAS file was still incrementing at a steady rate.
I think we can discount the post command as it merely puts the PC back to sleep......and the post command is only present on the D drive backup, not the C
So how much total data are you backing up fro drive D:?
Looking in the ATI GUI and selecting the Activity tab in the main window what do see there? What show to be your mbps? This mbps in an average during the backup period.
If your D: drive contains many small files 4K and under your performance will be slower vs. a drive containing mostly larger files. On average for smile files you should see an average of 345 to 450 mbps for small files. Large files should run 800 mbps up to around 1000 mbps in best case scenario. If you disk contains a lot of already compressed files this will slow the process as well.
Have you looked at the NAS GUI interface for any issues like error messages, available firmware updates, etc. that might be helpful in diagnosing your issue?
David, I saw your other smaller backup task for C:
Looking some more, the backup for 01/11 is adding to my confusion here.
01/11/2019 02:41:31 :316 -----
01/11/2019 02:41:31 :316 ATI Demon started. Version: 24.4.1.21400.
01/11/2019 02:41:31 :369 Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
01/11/2019 02:41:31 :370 Operation WDC WD4005FZBX-00K5WB0 01.01A01 started by schedule.
01/11/2019 02:41:31 :386 Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
01/11/2019 02:41:31 :386 Operation: Backup
01/11/2019 17:17:40 :579 Child process has exited with code '0'.
01/11/2019 17:17:40 :579 Execution of user command succeeded: D:/Misc_Updates/PStools/psshutdown.exe
01/11/2019 17:17:40 :648 Operation has succeeded.
Start: 01/11/2019 02:41:31
Stop: 01/11/2019 17:17:40
Total Time: 14:36:09
The ti_demon log above confirms the backup took over 14.5 hours to complete.
The backup_worker log also confirms this with a huge gap in the middle of the entries!
11/01/2019 02:41:31 type=log; level=inf; message=
io#1: start new vol 2 at 0x269262f2000;
11/01/2019 02:41:31 type=log; level=inf; message=
ar#1: archive_slice_create(sid=15,type=full,user_type=full,uuid=00000000000000000000000000000000,ctime=0);
11/01/2019 02:42:20 type=log; level=inf; message=
ar#1: archive_slice_create(sid=16,type=inc,user_type=full,uuid=00000000000000000000000000000000,ctime=0);
11/01/2019 17:14:20 type=log; level=inf; message=
ar#1: archive_slice_finish(sid=16);
11/01/2019 17:14:20 type=log; level=inf; message=
ar#1: archive closing;
11/01/2019 17:14:20 type=log; level=inf; message=
io#1: total req: 5380971 (rd: 5065526 wr: 315267 sync: 178), pgreq: 405434881 (rd: 82698847 wr: 322736034) sync: 6381.4 ms;
What makes this a little more confusing is that there is another backup_worker log inbetween the above times suggesting either another backup task (not supported by any ti_demon log) or some action to open a backup on your NAS?
11/01/2019 09:03:57 >>> id=10002
action=metainfo
agent="Acronis True Image 2020 24.4.1.21400 Win"
archive="\\\\Wdmycloudex2100\\pc\\C\\NVMe Samsung SSD 970 2B2Q-0002.tibx"
ar-loc-username="PC\\Guest"
11/01/2019 09:03:57 type=log; level=inf; message=
ar#1: opening archive path="\\?\UNC\Wdmycloudex2100\pc\C\/NVMe Samsung SSD 970 2B2Q.tibx" in readonly mode;
ATI does not allow for more than one backup task to be active, so the above may be a red herring..!
There was another backup_worker log for the same day during the long backup period but which looks to be for the same NAS backup task but for a later -0002 file in the chain.
11/01/2019 13:29:29 >>> id=10002
action=metainfo
agent="Acronis True Image 2020 24.4.1.21400 Win"
archive="\\\\Wdmycloudex2100\\pc\\D\\WDC WD4005FZBX-00K5WB0 01.01A01-0002.tibx"
ar-loc-username="PC\\Guest"
11/01/2019 13:29:29 type=log; level=inf; message=
ar#1: opening archive path="\\?\UNC\Wdmycloudex2100\pc\D\/WDC WD4005FZBX-00K5WB0 01.01A01.tibx" in readonly mode;
David, while I don't think this would have anything to do with the speed issue, I do see an oddity in your cleanup rules. You run a daily backup with five increments. But you say to delete backups older than 1 day. If what you want is to only have one chain, just select the other option to store no more than 1 recent chain.
will take a look at that next time
disk is not compressed, error checked (all OK) and fully de-fragmented
no errors in NAS and it is fully up to date
as previously stated it was OK in ATI 2018 before upgrading
no other backups running - no idea what pc\guest is...should be pc\david
BrunoC :
This is the setting I have always used....after 5 incrementals it creates a new full and deletes the old one...it has always worked until now - and does indeed delete the old one afterwards.... whilst I appreciate your thought, I dont think this is contributing to the lengthy times
the daily incrementals take but a few minutes every night
David, I am going to recommend doing a Repair Install of ATI 2020 #21400 because another issue that I am seeing is with the size of your backup_worker logs which simply look to be too small when I compare against my own system.
Your logs are all 20kb or smaller in size despite having similar tasks.
The selected log above (1.58MB) was for my backup of my C: NVMe drive to my NAS and my smallest log is still over 20KB.
KB 60915: Acronis True Image: repairing program settings - has details of doing the repair install.
OK, happy to try anything!....will have to wait until PC is free later this evening
Seems strange though as, once the initial backup is done, subsequent dailies complete in a few minutes
I used their removal tool before installing 2020 and also ran registry cleanup to try and ensure I WAS DOING a clean install.
thanks for your help so far......
I HAVE had a couple of rogue entries in the NAS destination folders of a "backup" for both C and D drives that only showed12Kb (!!) filesize but that was weeks ago and, after the second full a couple of days ago deleted those files
Happy to totally remove it and do another cleanup then re-install....would that be better than trying a repair ?
David Faulkner wrote:I HAVE had a couple of rogue entries in the NAS destination folders of a "backup" for both C and D drives that only showed12Kb (!!) filesize but that was weeks ago and, after the second full a couple of days ago deleted those files
David, with the new .tibx format, the first .tibx file for the backup task will never be deleted but will be reduced to 12kb. They contain metadata for the job and should NOT be deleted.
AH, OK, wrists slapped......but this isnt the problem as I only deleted it this morning
David, recommend reading KB 63498: Acronis True Image 2020: new tibx backup format FAQ - which includes:
Q: First backup file in my backup location has .tibx format and is about 12KB in size. Is it corrupted? Should I delete it?
A: After the very first backup version is deleted, the .tibx file itself will drastically reduce in size, down to 12KB or similar size (up to several MB), but will not be removed completely. Do not delete this file, as it is required for proper functioning of backup browsing mechanism. See also Acronis True Image 2020: do not delete first tibx file
David Faulkner schrieb:Ich habe das Tool zum Entfernen vor der Installation von 2020 verwendet und auch die Registrierungsbereinigung ausgeführt, um sicherzustellen, dass ich eine saubere Installation ausgeführt habe.
Gerne entfernen Sie es komplett und führen eine erneute Bereinigung durch, bevor Sie es erneut installieren. Wäre das besser, als eine Reparatur zu versuchen?
Keine Reparatur sondern eine Neuinstallation Empfehle ich immer.
Erm....sorry, no German
David,
After the last 10 posts here I would recommend that you start over from scratch with the backup task. Allow the new task to run and do not remove/delete/move any of produced backup files by any means other than what is available in True Image itself. I believe that should fix things for you.
Enchantech wrote:So how much total data are you backing up fro drive D:?
Looking in the ATI GUI and selecting the Activity tab in the main window what do see there? What show to be your mbps? This mbps in an average during the backup period.
I am backing up around 1.2Tb
Have now completely un-installed and re-installed from scratch using the cleanup tool
attached info from the NEW C drive backup., it created a file size of 39.7Gb in 15 mins.......around 44mb/sec (or should it be the un-compressed file size of 84.6Gb which equates to 94mb/sec???)
D drive still running... so far 132Gb in 45 mins = around 48mb/sec ..... however watching the file counter incrementing in the NAS folder it "looks" a lot lot quicker.....
C drive is a 500Gb Samsung M2 SSD, D drive is a 4Tb WD black drive
The time remaining estimate is just over 6 hours which is more like it....
So, by the LOOK of things it may be sorted....if not I will be back
Thank you to all who have helped in particular Steve Smith
Assuming your D: drive is a data disk it likely contains a mix of small and large files with most on the small side. At 48MBps that should equate to the 450mbps range which given your hardware I would think is about right.
Looks like your issue is sorted. Thanks for posting your results.
D drive results.....took just under 8 hours which, whilst clearly better than 15 is still more than ATI 2018 managed in under 7 hours
David Faulkner schrieb:D Laufwerk Ergebnisse ..... dauerte knapp 8 Stunden, obwohl deutlich besser als 15 ist immer noch mehr als ATI 2018 in weniger als 7 Stunden verwaltet
Tomorrow that tibx format and the backup.worker.exe changes in the 2020 slow down according to my experience the backup times and is a serious power guzzler.
This is still taking longer than ATI 2018 did.......
David Faulkner schrieb:Dies dauert immer noch länger als ATI 2018 .......
Open a support ticket so you can take a look at your times.
Can you post the log file of your most recent backup of drive D?
The backup_worker log looks good to me for a new full backup. Prettied copy attached.
David,
From your log file:
11/02/2019 23:15:00 type=log; level=err; message=ar#1: failed to open archive path="\\?\UNC\WDMYCLOUDEX2100\pc\D\/WDC WD4005FZBX-00K5WB0 01.01A01.tibx" mode=readonly uuid=00000000000000000000000000000000, err=-5022 (File not found);
err=-5022 is likely that your system clock is incorrect. Please enter your bios and make certain that the time in the bios is within + or - 3 minutes of the correct time. Check to see that the clock is set to the right time zone. Check that correct date is shown. If date is off substantially (a few years for example) replace the battery on the motherboard.
11/02/2019 23:15:00 type=log; level=err; message=io#1: failed to open "\\?\UNC\WDMYCLOUDEX2100\pc\D\/WDC WD4005FZBX-00K5WB0 01.01A01.tibx" (pcs_err=-8);
pcs err=-8 can be caused by a failed port or cable and is usually seen when a switch is used in the network. Try a different cable. If the error persists try a different port. If the error persists the error is likely on the other end (ie. PC or NAS). If the problem is solved however then there is likely a problem with that particular port.
Hmmm...interesting observations, thank you.......I will check these later
internet time was spot on on the NAS and only about 3 seconds out on the PC...now all synced
I AM using an 8 port Gigabit switch....but I was when I had ATI 2018.....
I would still try switching ports and cables. Things can go south on you at anytime. Since you are troubleshooting here you have to follow the errors.
I will re-cable everything in CAT7 cable....was going to do that sometime anyway, presently using CAT 5e cable
Sound good, post back your results.
total overkill I know but I was contemplating re-cabling in CAT 6 so what the hell, CAT 7 it is....every single cable, connection and patch cable is now CAT 7 throughout
NAS write speed has notably increased but strangely the read speed hasn't
I have repeated the tests several times and this result is typical and repeatable, the write speeds have always been much higher and the read speed has dropped slightly in some tests
Maybe the speed wont increase much more than it was but with the amount of screening on the cables surely any interference will be considerably reduced......I know from experience when digital TV started we had problems with errors and some channels not even receivable at all, I ran it all in the "proper" dual screened cable and we not only receive every channel at a good strength but the errors are zero so I appreciate the need for heavily screened cable, especially at the frequencies now being used.
new CAT 7 speeds on left old CAT5 & 5e cable on right
CAT 5 vs CAT 7...again slightly better... the big backup that caused the trouble (D drive) is tonight.......
Now that the times seem to be back in the realm of normal, don't sweat some minor differences - just consider the "average" of many similar backups to be your best comparison.
There's always going to be some variation in times, even if you were to do a full and then a back to back full right after under nearly identical circumstances - it could be off by a couple of minutes if backing up large data. Too many variables involved such as CPU availability, the specific blocks being written to, memory usage, etc come into play. These variables are 3-fold since you have the host PC, the destination NAS and switch/router all working together for the transfer and at any given time, may be doing other things too... for instance, your router/switch might help transfer a backup faster when it has fewer clients attached to it (like half of the wireless devices in the house are asleep at that time).. compared to when it has all devices connected at the same time and taking up resources.
The CAT 7 did a little better than CAT 5(e?), but the cable isn't likely to be any faster unless you have a very long run and it was degraded. It certainly won't hurt, but you're not gaining much if you're still using 1GBps NICs at any point in the data transfer (which is likely the case on all 3 of the devices in play here). CAT6, CAT6A and CAT7 can support speeds up to 10GBps.
--------------------
As for the larger drive - time will tell on your next run. Keep in mind though, that as the destination drives fills up, if it's fragmented, etc. that can also impact performance. You say nothing has changed, but every time new data is written to that same drive, something is changing... more writes to the disk will wear it down overtime. If the drive is filling up, it will degrade in performance as compared to a drive that has lots of free space on it. If it is in the ball-park of previous backups, consider it OK and don't sweat a couple of minutes of variation.
David Faulkner Simply use the 2018 Ati again and your request is resolved.
Did full backups last night .....and there is marked reduction in backup times
Although the Mbps speed on the D drive appears slower it completed in far less time....so maybe the problem was not outright network speed but noise.....either way it looks promising
have attached the logs in case someone can review to see if the earlier problems have gone
thanks all for your help
David,
Looks like your errors as shown in log ending in 164 do not appear in log ending in 173 your D drive. I take it that the 164 log being a full version and showing the errors was the 4 hour7 min. Activity screenshot?
Given that log 173 is an incremental version of the full backup it is of course much faster. Strange that the errors are gone in that log though.
Have you tried re-seating the data cable for the D drive at both ends by unplugging the cable and then plugging it back in? I would give that a go if the errors appear again.
I had a drive in and NAS that would send CRC errors to a log and re-seating the cable would fix it for awhile. I finally replaced the cable and fixed the issue completely.
Thanks...
no, I havent touched the D drive in the PC......but surely any problems or errors with that would be flagged by windows ......no???
The D drive is SATA connected
I would not rely on Windows to flag errors like this no. SMART output can show these types of errors but are cryptic to interpret.
Loose, corroded, or faulty cables can cause many issues such as these. True Image logs may be showing what it interprets is the reason for error but may not be accurate as well.
I would check it as I indicated. If your logs stay clear then you know you fixed it if they return after re-seating then replace the cable. If you end up replacing it get a premium cable. Although they may look good on the outside like network cable shielding is poor on cheap cables as well as overall construction. Bottom line is, you get what you pay for.
well aware of the cheap cable issues & problems it causes....as previously noted comments about TV co-ax cable......thats why I upgraded everything to overkill CAT 7 :)
Yeah, you got it!
This is more like it....1.3Tb in 3 1/2 hours and 210Gb in 7 mins....so maybe, just maybe that new cabling WAS worthwhile
Following advice from Enchantech I am also going to replace the D drive SATA cable with a decent thick screened one https://www.amazon.co.uk/gp/product/B00IML7E5S/ref=ppx_yo_dt_b_asin_title_o00_s01?ie=UTF8&psc=1
