Back in Time takes long time for incremental backup (over 2 hours)

[florianr]

Hello!

Running back in time after initial backup to my NAS it takes a long time to complete backup ...

Here is part of the logfile:
May 16 20:00:01 florian-laptop backintime (florian): INFO: Lock
May 16 20:00:01 florian-laptop backintime (florian): INFO: Include folders: ['/home/florian']
May 16 20:00:01 florian-laptop backintime (florian): INFO: Ignore folders: []
May 16 20:00:01 florian-laptop backintime (florian): INFO: Last snapshots: {}
May 16 20:00:01 florian-laptop backintime (florian): INFO: [GnomePlugin.Systray.run]
May 16 20:00:01 florian-laptop backintime (florian): INFO: [GnomePlugin.Systray.run] begin loop
May 16 20:00:01 florian-laptop backintime (florian): INFO: Compare with old snapshot: 20100516-160001
May 16 20:02:34 florian-laptop backintime (florian): INFO: Command "rsync -aEAX -i --dry-run --chmod=Fa-w,D+w --whole-file --delete --exclude="/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu" --exclude="/home/florian/.local/share/backintime" --include="/home/florian/" --include="/home/" --exclude=".*" --exclude="*.backup*" --exclude="*~" --exclude="/home/florian/bb" --exclude="/home/florian/vmware" --exclude="/home/florian/Archive" --exclude="/home/florian/Musik" --exclude="/home/florian/Videos" --exclude="/home/florian/CD_Sissi" --exclude="/home/florian/tmp" --exclude="/home/florian/krautzberger" --exclude="/home/florian/.mozilla/firefox/8rlbdpz5.default/Cache" --exclude="/home/florian/Pictures" --exclude="/home/florian/_VirtualBox" --exclude="/home/florian/Bilder" --exclude="/home/florian/download" --exclude="/home/florian/.VirtualBox/HardDisks" --exclude="/home/florian/.cache" --exclude="/home/florian/Downloads" --include="/home/florian/**" --exclude="*" / "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/20100516-160001/backup/"" returns 0
May 16 20:02:34 florian-laptop backintime (florian): INFO: Create hard-links
May 16 20:12:50 florian-laptop backintime (florian): WARNING: Command "cp -al "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/20100516-160001/backup/"* "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/new_snapshot/backup/"" returns 256
May 16 20:12:50 florian-laptop backintime (florian): INFO: Call rsync to take the snapshot
May 16 21:00:02 florian-laptop backintime (florian): WARNING: A backup is already running
May 16 22:00:02 florian-laptop backintime (florian): WARNING: A backup is already running
May 16 23:00:02 florian-laptop backintime (florian): WARNING: A backup is already running
May 16 23:32:14 florian-laptop backintime (florian): WARNING: Command "rsync -aEAX -v --delete-excluded --chmod=Fa-w,D+w --whole-file --delete --exclude="/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu" --exclude="/home/florian/.local/share/backintime" --include="/home/florian/" --include="/home/" --exclude=".*" --exclude="*.backup*" --exclude="*~" --exclude="/home/florian/bb" --exclude="/home/florian/vmware" --exclude="/home/florian/Archive" --exclude="/home/florian/Musik" --exclude="/home/florian/Videos" --exclude="/home/florian/CD_Sissi" --exclude="/home/florian/tmp" --exclude="/home/florian/krautzberger" --exclude="/home/florian/.mozilla/firefox/8rlbdpz5.default/Cache" --exclude="/home/florian/Pictures" --exclude="/home/florian/_VirtualBox" --exclude="/home/florian/Bilder" --exclude="/home/florian/download" --exclude="/home/florian/.VirtualBox/HardDisks" --exclude="/home/florian/.cache" --exclude="/home/florian/Downloads" --include="/home/florian/**" --exclude="*" / "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/new_snapshot/backup/"" returns 5888
May 16 23:32:14 florian-laptop backintime (florian): INFO: Save permissions
May 16 23:36:21 florian-laptop backintime (florian): INFO: Remove backups older than: 20000516-000000
May 16 23:36:21 florian-laptop backintime (florian): INFO: [smart remove] keep all >= 20100515-000000
May 16 23:36:21 florian-laptop backintime (florian): INFO: [smart remove] keep first >= 20100503-000000 and < 20100510-000000
May 16 23:36:21 florian-laptop backintime (florian): INFO: [smart remove] keep first >= 20100426-000000 and < 20100503-000000
May 16 23:36:21 florian-laptop backintime (florian): INFO: [smart remove] keep first >= 20100101-000000 and < 20100201-000000
May 16 23:36:21 florian-laptop backintime (florian): INFO: [smart remove] keep first >= 20100201-000000 and < 20100301-000000
May 16 23:36:21 florian-laptop backintime (florian): INFO: [smart remove] keep first >= 20100301-000000 and < 20100401-000000
May 16 23:36:21 florian-laptop backintime (florian): INFO: [smart remove] keep first >= 20100401-000000 and < 20100501-000000
May 16 23:36:21 florian-laptop backintime (florian): INFO: [smart remove] keep snapshots: ['20100516-200001', '20100516-160001', '20100516-114724']
May 16 23:36:21 florian-laptop backintime (florian): INFO: Keep min free disk space: 1024 Mb
May 16 23:36:24 florian-laptop backintime (florian): INFO: [GnomePlugin.Systray.run] end loop
May 16 23:36:24 florian-laptop backintime (florian): INFO: Unlock

[Alexis de Lattre (alexis-via)]

I have the same problem here, but I think I found the cause. My recent backups made by backintime are not incremental any more, which is why they take a lot of time to perform.

I measured the size of the backups made by backintime :

du -h --max-depth=1
0 ./backintime
4,3G ./20100504-000000
26M ./20100509-000000
4,6M ./20100511-000000
4,5G ./20100514-000404
4,5G ./20100516-000000
4,7G ./20100517-000000
18G .

So I can say that may backup are not incremental any more since May 11-14.

I have changed the way to access my backup share on May 13th : before that date, I used NFS ; after that date, I use CIFS. So it seems that my backups are not incremental any more since I access my backup destination via CIFS.

[Alexis de Lattre (alexis-via)]

I confirm this. In fact, the reason is that backintime can't create hardlink on the backup destination. Florianr, you have the same problem than me. Look in your logs, you have :

May 16 20:12:50 florian-laptop backintime (florian): WARNING: Command "cp -al "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/20100516-160001/backup/"* "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/new_snapshot/backup/"" returns 256

-> you see that the command "cp -al <source> <destination>" returns a non-zero value, which means it fails.

The option "-l" of cp means cp tries to make a hard link ; the use of hard links is required to have incremental backups.

Try "cp -l" command on your local filesystem -> it should work.
Try "cp -l" command on your backup destination filesystem -> you will have an error.

If you solve this, the backup will be incremental again and, as a consequence, they will be quick to perform.

[Alexis de Lattre (alexis-via)]

Here are my last findings :

- Samba usually supports hard links (related to option "unix extensions = yes" in smb.conf, which is enabled by default), so if your destination backup directory is a Samba share, you should be able to have incremental backups.

- the problem came from the fact that my Samba server was a light embedded Samba on my dreambox which apparently didn't handle Unix extensions ; so I was not able to make hard links, so no incremental backups with Backintime.

I am now back to my NFS destination backups directory. I am now able to do incremental backups again. Backintime logs now print :

May 17 16:44:48 wide backintime (alexis): INFO: Create hard-links
May 17 16:46:27 wide backintime (alexis): INFO: Command "cp -al [.....]" returns 0

[Dave (dave2010)]

I have the same issue - well, it looks like the same issue. I don't think its whether hard links are supported on CIFS or not though. Would be interesting if you could try this fix.

Using CIFS the incremental backups aren't incremental, but they are incremental when using a local target filesystem. I started to wonder about this when all my test backups were taking the same amount of time :) I confirmed it by looking at the inode numbers of the various snapshots - different inode numbers for the same files.

It looks like this is due to the permissions on the snapshot heirarchy being set to remove write permission. cp -al seems to work ok on a local filesystem but when using a CIFS mounted filesystem the cp fails because it can't write subdirectories (it must be applying permissions at the time the directories are created unlike local filesystems). So since the cp failed, rsync just creates all the files as if they were new.

I've attached a patched 0.9.99.37 snapshot.py file that appears to fix the issue (copy_snapshot function not modified since it doesn't appear to be called from anywhere. The find command added as a Debian patch was removed since files should already be u+wx before the copy now):

Diff of snapshots.py with 0.9.99.37
62c962,964
< cmd = "cp -al \"%s\"* \"%s\"" % ( self.get_snapshot_path_to( prev_snapshot_id ), new_snapshot_path_to )
---
> old_snapshot_path_to = self.get_snapshot_path_to( prev_snapshot_id )
> self._execute( "find \"%s\" -type d -exec chmod u+wx {} \\;" % old_snapshot_path_to ) #CIFS patch
> cmd = "cp -al \"%s\"* \"%s\"" % ( old_snapshot_path_to, new_snapshot_path_to )
964c966
< self._execute( "find \"%s\" -type d -exec chmod u+wx {} \\;" % new_snapshot_path ) #Debian patch
---
> self._execute( "find \"%s\" -type d -exec chmod u-w {} \\;" % old_snapshot_path_to ) #CIFS patch

Note that there still seems to be an issue with being unable to change ownership of the files on a CIFS filesystem using cp at least for me - this does not stop the copy but just generates needless warnings from chmod saying it can't set ownership. I'll raise this in a separate bug report

[florianr (florianr-gmx)]

I can't find the beta packege for download. I am still using Version 9.26. I tried to add the testing repository but got this error:
~$ sudo add-apt-repository ppa:bit-team/testing
Executing: gpg --ignore-time-conflict --no-options --no-default-keyring --secret-keyring /etc/apt/secring.gpg --trustdb-name /etc/apt/trustdb.gpg --keyring /etc/apt/trusted.gpg --primary-keyring /etc/apt/trusted.gpg --keyserver keyserver.ubuntu.com --recv 589EEDCD16567B0E6D23C3144B6071B7D6FDC9D0
gpg: Schlüssel D6FDC9D0 von hkp Server keyserver.ubuntu.com anfordern
gpg: Schlüsselserver hat das Zeitlimit überschritten
gpg: Empfangen vom Schlüsselserver fehlgeschlagen: Schlüsselserverfehler

Is there an other link where I could download backintime beta?

Thanks for your support so far.

Kind regards

Florian

[florianr (florianr-gmx)]

Sorry for the noise ^^^, I finaly found the 9.99 package for download.

First Run (with your patch aplied) gave me an error:

##################################################################################

May 18 00:51:17 florian-laptop backintime (florian): INFO: Snapshot location update flag detected
May 18 00:51:17 florian-laptop backintime (florian): WARNING: Snapshot location needs update
May 18 00:51:24 florian-laptop backintime (florian): INFO: Update snapshot locations
May 18 00:51:24 florian-laptop backintime (florian): INFO: Only 1 profile found
May 18 00:51:25 florian-laptop backintime (florian): INFO: Folder of profile 1 is set to /mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu
May 18 00:51:25 florian-laptop backintime (florian): INFO: Update was successful. Snapshots of profile 1 are moved to their new location
May 18 00:51:25 florian-laptop backintime (florian): INFO: BackinTime will be able to make new snapshots again!
May 18 00:53:55 florian-laptop backintime (florian): INFO: Lock
May 18 00:53:55 florian-laptop backintime (florian): INFO: [GnomePlugin.Systray.run]
May 18 00:53:55 florian-laptop backintime (florian): INFO: on process begins
May 18 00:53:55 florian-laptop backintime (florian): INFO: Profile_id: 1
May 18 00:53:55 florian-laptop backintime (florian): INFO: [GnomePlugin.Systray.run] begin loop
May 18 00:53:56 florian-laptop backintime (florian): INFO: Command "find "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/new_snapshot" -type d -exec chmod u+wx {} \;" returns 0
May 18 00:53:56 florian-laptop backintime (florian): WARNING: Command "rm -rf "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/new_snapshot"" returns 256
May 18 00:53:58 florian-laptop backintime (florian): INFO: Command "rm -rf "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/florian-laptop/florian/1/20100518-005355-684"" returns 0
May 18 00:54:02 florian-laptop backintime (florian): INFO: [GnomePlugin.Systray.run] end loop
May 18 00:54:02 florian-laptop backintime (florian): INFO: Unlock

###############################################################################

So I removed the "new snapshot" directory and run BackInTime again. I think comparing was much faster than befor, but I didn't get a new snapshot. Only an empty directory new snapshot is created.

################################################################################
May 18 00:58:12 florian-laptop backintime (florian): INFO: Lock
May 18 00:58:12 florian-laptop backintime (florian): INFO: [GnomePlugin.Systray.run]
May 18 00:58:12 florian-laptop backintime (florian): INFO: on process begins
May 18 00:58:12 florian-laptop backintime (florian): INFO: [GnomePlugin.Systray.run] begin loop
May 18 00:58:12 florian-laptop backintime (florian): INFO: Profile_id: 1
May 18 00:58:12 florian-laptop backintime (florian): INFO: Compare with old snapshot: 20100516-200001
May 18 01:00:01 florian-laptop backintime (florian): WARNING: A backup is already running
May 18 01:01:01 florian-laptop backintime (florian): INFO: Command "rsync -aEH --delete --delete-excluded -i --dry-run --out-format="BACKINTIME: %i %n%L" --chmod=Da+w --exclude=...

[Dave (dave2010)]

Hmm, that's odd since the updates don't change the new_snapshot code. If you run it and new_snapshot is not deleted, its interesting that you can delete it from the command line. What does ls -als new_snapshot/* show ?

What happens if you touch/create a new file in your backed up directory and run backup again?

In any case, here is an updated version of snapshot.py - I removed an extra find that didn't seem necessary. And I probably shouldn't combine changes, but I also added some lines that remove write permission for the entire snapshot directory and files, not just the backup directory (which needed some changes to the 'name' code to make sure permissions were still ok)

[florianr (florianr-gmx)]

with your new patch aplied, removing of the new_snapshot worked:

INFO: Lock
INFO: [GnomePlugin.Systray.run]
INFO: [GnomePlugin.Systray.run] begin loopINFO: on process begins

INFO: Profile_id: 1
INFO: Command "find "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/florian-laptop/florian/1/new_snapshot" -type d -exec chmod u+wx {} \;" returns 0
INFO: Command "rm -rf "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/florian-laptop/florian/1/new_snapshot"" returns 0
ABC:
['20100516-200001', '20100516-160001', '20100516-114724']
INFO: Compare with old snapshot: 20100516-200001

###################################################################################

But while creating the hard-links ist stcuk ...

INFO: Compare with old snapshot: 20100516-200001
INFO: Command "rsync -aEH --delete --delete-excluded -i --dry-run --out-format="BACKINTIME: %i %n%L" --chmod=Da+w --exclude="/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu" --exclude="/home/florian/.local/share/backintime" --include="/home/florian/" --include="/home/" --exclude=".*" --exclude="*.backup*" --exclude="*~" --exclude="/home/florian/bb" --exclude="/home/florian/vmware" --exclude="/home/florian/Archive" --exclude="/home/florian/Musik" --exclude="/home/florian/Videos" --exclude="/home/florian/CD_Sissi" --exclude="/home/florian/tmp" --exclude="/home/florian/krautzberger" --exclude="/home/florian/.mozilla/firefox/8rlbdpz5.default/Cache" --exclude="/home/florian/Pictures" --exclude="/home/florian/_VirtualBox" --exclude="/home/florian/Bilder" --exclude="/home/florian/download" --exclude="/home/florian/.VirtualBox/HardDisks" --exclude="/home/florian/.cache" --exclude="/home/florian/Downloads" --exclude="/home/florian/Desktop/Desktop08" --exclude="/home/florian/Desktop/Android" --exclude="/home/florian/Desktop/Desktop09" --include="/home/florian/**" --exclude="*" / "/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/florian-laptop/florian/1/20100516-200001/backup/"" returns 0
INFO: Create hard-links

#################################################################################
$ ls -al new_snapshot/
insgesamt 0
drwxr-xr-x 2 florian florian 0 2010-05-18 12:33 .
drwxr-xr-x 2 florian florian 0 2010-05-18 12:33 ..
drwxr-xr-x 2 florian florian 0 2010-05-18 12:33 backup
###############################################################################
The last snapshot I took is from Mai 16. Also I changes a lot of files, non of them are in any backup snapshot.
So creating or touching a file makes no difference.

[florianr (florianr-gmx)]

I get a lot of errors like this:
cp: Erzeugen von Verknüpfung „/mnt/backup/WORKGROUP/LS-CHL-V2719/share/BiT_Ubuntu/backintime/florian-laptop/florian/1/new_snapshot/backup/home/florian/Desktop/Desktop09/xxxxx/xxxxxxx/xxxxx.gif“ nicht möglich: Function not implemented

[Dave (dave2010)]

Maybe your problem isn't exactly the same as mine. Maybe you really do have a problem with creating hard-links as Alexis wrote.

Have you tried what Alexis suggested in order to verify if you can create hard-links?
Try "cp -l" command on your local filesystem -> it should work.
Try "cp -l" command on your backup destination filesystem -> you will have an error.

e.g.
cd to backup area
echo hello >a
cp a b
cp -l a c
ls -li a b c
  13397 -rw-r--r-- 2 dave dave 6 2010-05-18 15:51 a
  13398 -rw-r--r-- 2 dave dave 6 2010-05-18 15:51 b
  13397 -rw-r--r-- 2 dave dave 6 2010-05-18 15:51 c

The first number is the inode number, and if the inode for a and c are not identical, then you can't create hard links

Also - the patch I provided worked for me and seemed to run ok- but it hasn't been vetted by the developers - its just a suggestion to them on one way that might fix an issue. Use at your own risk...

[Dave (dave2010)]

OK, been a bit hasty with that patch. I can now see why that extra find/chmod is at the bottom.

Please ignore all patches/comments on find/chmod above.

I will resubmit a new bug/patch to cover my issue with directory permissions on CIFS, and a separate new bug/patch for writable top level files.

Let's see if the cp -l above works for florienr

[florianr (florianr-gmx)]

No, the cp -l doesn't work on my smbmount. So it seems I have a problem with the configuration of the sambaclient or server.

Any help would be welcome, but it seems the primary problem is on my site and not a bug in BiT. Thanks for your help so far.

[Dave (dave2010)]

Thanks for the confirmation.

I wonder if a bit of code to test if cp -l works in the backup destination is needed - and if it doesn't to issue an error.

[Dave (dave2010)]

Created code branch to implement a test for creating a hard link with cp and fail the snapshot if it doesn't work to avoid rsync just copying all files each time.

[Marja Erwin (marja-e)]

I've never had it back up in as little as two hours. Right now, though, it takes about that long for it to crash everything while trying an incremental backup.