#1116 Issue closed: Wrong progress 'Restored' values while backup restore¶
Labels: fixed / solved / done, minor bug
jsmeix opened issue at 2016-12-08 15:51:¶
I did a restore of mutiple backups.
Actually everything was correctly restored but
the progress 'Restored' values while it runs
are wrong:
RESCUE f79:~ # rear -C home_backup -d -D restoreonly & rear -C opt_backup -d -D restoreonly & wait [1] 2935 [2] 2936 ... 2935: Backup archive size is 1.2G /tmp/rear.pXHHHCOVcXR7NCH/outputfs/f79/backup-home_backup.tar.gz (compressed) 2936: Backup archive size is 1.1G /tmp/rear.UBikrzrDRQSEiIs/outputfs/f79/backup-opt_backup.tar.gz (compressed) 2935: Restoring from '/tmp/rear.pXHHHCOVcXR7NCH/outputfs/f79/backup-home_backup.tar.gz'... 2936: Restoring from '/tmp/rear.UBikrzrDRQSEiIs/outputfs/f79/backup-opt_backup.tar.gz'... 2935: Restoring... 2936: Restoring... 2935: Restored 34 MiB [avg 11857 KiB/sec] 2936: Restored 0 MiB [avg 0 KiB/sec] 2935: Restored 34 MiB [avg 5928 KiB/sec] 2936: Restored 0 MiB [avg 0 KiB/sec] 2935: Restored 192 MiB [avg 21944 KiB/sec] 2936: Restored 0 MiB [avg 0 KiB/sec] ... 2935: Restored 192 MiB [avg 6370 KiB/sec] 2936: Restored 0 MiB [avg 0 KiB/sec] 2935: Restored 192 MiB [avg 5808 KiB/sec] 2936: OK 2936: Restored 0 MiB in 34 seconds [avg 0 KiB/sec] 2936: Restoring finished. ... 2935: Restored 192 MiB in 37 seconds [avg 5337 KiB/sec] 2935: Restoring finished.
jsmeix commented at 2016-12-08 15:58:¶
FWIW:
For the opposite operation multiple mkbackuponly
the progress 'Archived' values are o.k.:
# usr/sbin/rear -C home_backup -d -D mkbackuponly & usr/sbin/rear -C opt_backup -d -D mkbackuponly & wait [1] 1918 [2] 1919 ... 1919: Creating tar archive '/tmp/rear.nfyWpBWU4xGyqLG/outputfs/f79/backup-opt_backup.tar.gz' 1919: Preparing archive operation 1918: Creating tar archive '/tmp/rear.SpO43ouDMJMPv00/outputfs/f79/backup-home_backup.tar.gz' 1918: Preparing archive operation 1919: Archived 133 MiB [avg 22818 KiB/sec] 1918: Archived 121 MiB [avg 20656 KiB/sec] 1918: Archived 214 MiB [avg 22008 KiB/sec] 1919: Archived 236 MiB [avg 24228 KiB/sec] 1919: Archived 347 MiB [avg 25403 KiB/sec] ... 1919: Archived 998 MiB [avg 25548 KiB/sec] 1918: Archived 954 MiB [avg 24442 KiB/sec] 1919: OK 1918: Archived 1058 MiB [avg 24634 KiB/sec] 1919: Archived 998 MiB in 43 seconds [avg 23766 KiB/sec] ... 1918: Archived 1165 MiB [avg 25397 KiB/sec] 1918: OK 1918: Archived 1165 MiB in 50 seconds [avg 23873 KiB/sec]
jsmeix commented at 2016-12-14 14:50:¶
Restoring sequentially does not make a difference:
RESCUE f79:~ # rear -C basic_system -d -D recover ... 724: Restoring... 724: Restored 167 MiB [avg 57105 KiB/sec] 724: Restored 387 MiB [avg 66074 KiB/sec] 724: Restored 552 MiB [avg 62912 KiB/sec] 724: Restored 727 MiB [avg 62116 KiB/sec] 724: Restored 895 MiB [avg 61103 KiB/sec] 724: Restored 1195 MiB [avg 68023 KiB/sec] 724: Restored 1505 MiB [avg 73394 KiB/sec] 724: Restored 1721 MiB [avg 73435 KiB/sec] 724: Restored 1995 MiB [avg 75696 KiB/sec] 724: Restored 2223 MiB [avg 75884 KiB/sec] 724: Restored 2456 MiB [avg 76216 KiB/sec] 724: Restored 2687 MiB [avg 76433 KiB/sec] 724: OK 724: +++ grep -m1 'Total bytes written: ' in 39 seconds. 724: Restoring finished. ... RESCUE f79:~ # rear -C home_backup -d -D restoreonly ... 2935: Restoring... 2935: Restored 192 MiB [avg 65833 KiB/sec] 2935: Restored 192 MiB [avg 32916 KiB/sec] 2935: Restored 192 MiB [avg 21944 KiB/sec] 2935: Restored 192 MiB [avg 16458 KiB/sec] 2935: Restored 192 MiB [avg 13166 KiB/sec] 2935: Restored 192 MiB [avg 10972 KiB/sec] 2935: OK 2935: +++ grep -m1 'Total bytes written: ' in 21 seconds. 2935: Restoring finished. ... RESCUE f79:~ # rear -C opt_backup -d -D restoreonly ... 3832: Restoring... 3832: Restored 0 MiB [avg 0 KiB/sec] 3832: Restored 0 MiB [avg 0 KiB/sec] 3832: Restored 0 MiB [avg 0 KiB/sec] 3832: Restored 0 MiB [avg 0 KiB/sec] 3832: Restored 0 MiB [avg 0 KiB/sec] 3832: OK 3832: +++ grep -m1 'Total bytes written: ' in 18 seconds. 3832: Restoring finished. ...
It only works for 'recover' but not for 'rstoreonly'
and there is a bug regarding a 'grep' command in
restore/NETFS/default/400_restore_backup.sh
jsmeix commented at 2016-12-14 15:34:¶
Argh!
The whole issue is basically false alarm.
It is caused by my special huge testing files that I created via
# cat /dev/urandom | head -c 1G >/home/urandom.data # cat /dev/urandom | head -c 1G >/root/urandom.data
cf.
https://github.com/rear/rear/issues/1088#issuecomment-264463210
During restore those single huge files
result no useful output from 'tar' into
${TMP_DIR}/${BACKUP_PROG_ARCHIVE}-restore.log
so that those *-restore.log look as follows:
RESCUE f79:~ # cat /tmp/rear.dntbRYvtw7mWH4d/tmp/backup-basic_system-restore.log block 3: ./ block 6: dev/ block 9: home/ block 12: sys/ ... block 5881707: lib64/libfreebl3.so block 5882676: lib64/libcom_err.so.2 block 5882679: root/rear/var/log/rear/rear-f79.28698.log block 5882679: ** Block of NULs ** RESCUE f79:~ # cat /tmp/rear.rKkQ3AcACB0UqNP/tmp/backup-home_backup-restore.log block 3: home/johannes/ block 6: home/johannes/.xinitrc.template block 12: home/johannes/.inputrc block 17: home/johannes/.bashrc ... block 394959: home/stuff/usr/sbin/rear block 394998: home/urandom.data block 2492153: root/rear/var/log/rear/rear-f79.32141.log block 2492881: ** Block of NULs ** RESCUE f79:~ # cat /tmp/rear.CKoGevFoVc7cPow/tmp/backup-opt_backup-restore.log block 3: opt/urandom.data block 2097158: root/rear/var/log/rear/rear-f79.3499.log block 2097882: ** Block of NULs **
I.e. during restore of huge files there is no useful 'tar' output
and that leads to useless progress 'Restored' values.
jsmeix commented at 2016-12-14 16:52:¶
For me
https://github.com/rear/rear/pull/1129
fixes it and works really well.
For example now it looks like
RESCUE f79:~ # rear -C home_backup -d -D restoreonly ... 9642: Restoring... 9642: Restored 34 MiB [avg 11857 KiB/sec] 9642: Restored 192 MiB [avg 32916 KiB/sec] 9642: Restoring home/urandom.data 9642: Restoring home/urandom.data 9642: Restoring home/urandom.data 9642: Restoring home/urandom.data 9642: OK 9642: Restored 1217 MiB in 21 seconds [avg 59354 KiB/sec] 9642: Restoring finished. ...
jsmeix commented at 2016-12-15 15:30:¶
With
https://github.com/rear/rear/pull/1129
merged
the whole backup 'tar' restore messaging should
be much improved now.
For example how it looks now for me
(2 parallel restores with 1GB urandom.data files):
RESCUE f79:~ # rear -C home_backup -d -D restoreonly & rear -C opt_backup -d -D restoreonly & wait ... 15106: Backup restore program 'tar' started in subshell (PID=16351) 15107: Backup restore program 'tar' started in subshell (PID=16353) 15106: Restored 34 MiB [avg. 11857 KiB/sec] 15107: Restored 0 MiB [avg. 0 KiB/sec] 15106: Restoring home/stuff/var/lib/rear/output/rear-d25.iso 15107: Restoring opt/urandom.data 15106: Restored 192 MiB [avg. 21944 KiB/sec] 15107: Restoring opt/urandom.data 15106: Restoring home/urandom.data 15107: Restoring opt/urandom.data 15106: Restoring home/urandom.data 15107: Restoring opt/urandom.data 15106: Restoring home/urandom.data 15107: Restoring opt/urandom.data 15106: Restoring home/urandom.data 15107: Restoring opt/urandom.data 15106: Restoring home/urandom.data 15107: Restoring opt/urandom.data 15106: Restoring home/urandom.data 15107: Restoring opt/urandom.data 15106: Restoring home/urandom.data 15107: Restoring opt/urandom.data 15107: OK 15106: Restoring home/urandom.data 15107: Restored 1024 MiB in 34 seconds [avg. 30851 KiB/sec] 15107: Restoring finished. ... 15106: Restoring home/urandom.data 15106: OK 15106: Restored 1217 MiB in 40 seconds [avg. 31161 KiB/sec] 15106: Restoring finished.
[Export of Github issue for rear/rear.]