[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: [Bacula-devel] Accurate Incremental backup problem


I've made some changes few days ago, please, can you test the lastest svn ?
(you can update only the FD) and report the debug output ?

Thanks

Le Wednesday 24 September 2008 19:11:40 Ulrich Leodolter, vous avez écrit :
> Hello,
>
> On Wed, 2008-09-24 at 17:56 +0200, Kern Sibbald wrote:
> > On Wednesday 24 September 2008 16:19:29 Ulrich Leodolter wrote:
> > > Hello,
> > >
> > > ok, i've started bacula-fd in debug mode
> > >
> > > leodolter:~# nohup /opt/bacula/sbin/bacula-fd -f -d 200 -u root -g
> > > bacula \ -c /opt/bacula/etc/bacula-fd.conf >& /tmp/bacula-fd.log
> > >
> > > then i've started 2 consecutive incremental backups, and again looked
> > > at /usr/bin/wget, (i can send u 350MB debug file if u like)
> > >
> > > leodolter:~# fgrep '/usr/bin/wget' /tmp/bacula-fd.log
> > > leodolter-fd: htable.c:288-3680 Insert hp->next=0 hp->hash=0x59616a69
> > > hp->key=/usr/bin/wget leodolter-fd: htable.c:294-3680 Leave insert
> > > index=25223 num_items=50014 key=/usr/bin/wget leodolter-fd:
> > > backup.c:1210-3680 No strip for /usr/bin/wget
> > > leodolter-fd: accurate.c:182-3680 /usr/bin/wget      st_mtime differs
> > > leodolter-fd: backup.c:307-3680 FT_REG saving: /usr/bin/wget
> > > leodolter-fd: backup.c:402-3680 bfiled: sending /usr/bin/wget to stored
> > > leodolter-fd: backup.c:1210-3680 No strip for /usr/bin/wget
> > > leodolter-fd: bfile.c:835-3680 open file /usr/bin/wget
> > > leodolter-fd: htable.c:288-3681 Insert hp->next=0 hp->hash=0x59616a69
> > > hp->key=/usr/bin/wget leodolter-fd: htable.c:294-3681 Leave insert
> > > index=25223 num_items=50014 key=/usr/bin/wget leodolter-fd:
> > > backup.c:1210-3681 No strip for /usr/bin/wget
> > > leodolter-fd: accurate.c:182-3681 /usr/bin/wget      st_mtime differs
> > > leodolter-fd: backup.c:307-3681 FT_REG saving: /usr/bin/wget
> > > leodolter-fd: backup.c:402-3681 bfiled: sending /usr/bin/wget to stored
> > > leodolter-fd: backup.c:1210-3681 No strip for /usr/bin/wget
> > > leodolter-fd: bfile.c:835-3681 open file /usr/bin/wget
> > >
> > > as u see , st_mtime is the reason.
> > > but i am very sure that st_mtime did not change between incremental
> > > backups! verified that st_time did not change using a simple perl
> > > script called it before and after incremental jobs.
> >
> > When I look at the above, it looks perfectly normal to me.  I see that
> > st_mtime is different from the last backup, but that you are running two
> > simultaneous jobs that seem to have the same FileSet, so they both want
> > to save the same file.  This is normal.  If you want the second job to
> > take into account what the first job backs up, you must ensure that it
> > starts after the first job has finished.
>
> I have started the second Job after the first finished, look at Start
> and  End time below,  there are 2 minutes between.  Look also at
> the number of Files written,  this looks very strange to me!
> i am sure my system does not touch or modify more than 20000 files in 2
> minutes. /usr/bin/wget i just an example.
>
> again: when i look at the file names backed up, i looks like accurate
> incremental backups are only compared against last full.
>
>   Build OS:               i686-pc-linux-gnu redhat Enterprise release
>   JobId:                  3680
>   Job:                    Backup-leodolter.2008-09-24_15.49.11
>   Backup Level:           Incremental, since=2008-09-24 02:05:06
>   Client:                 "leodolter-fd" 2.5.3 (16Sep08)
> i686-pc-linux-gnu,debian,lenny/sid FileSet:               
> "LinuxLocalPartitions" 2008-05-23 14:56:44 Pool:                  
> "DiskBackup" (From Job resource)
>   Catalog:                "MyCatalog" (From Client resource)
>   Storage:                "File" (From Job resource)
>   Scheduled time:         24-Sep-2008 15:48:58
>   Start time:             24-Sep-2008 15:49:03
>   End time:               24-Sep-2008 15:51:32
>   Elapsed time:           2 mins 29 secs
>   Priority:               10
>   FD Files Written:       22,297
>   SD Files Written:       22,297
>   FD Bytes Written:       249,462,630 (249.4 MB)
>   SD Bytes Written:       252,590,613 (252.5 MB)
>   Rate:                   1674.2 KB/s
>   Software Compression:   63.2 %
>   VSS:                    no
>   Encryption:             no
>   Accurate:               yes
>   Volume name(s):         Backup-0158
>   Volume Session Id:      178
>   Volume Session Time:    1221573719
>   Last Volume Bytes:      2,297,116,205 (2.297 GB)
>   Non-fatal FD errors:    0
>   SD Errors:              0
>   FD termination status:  OK
>   SD termination status:  OK
>   Termination:            Backup OK
>
>   Build OS:               i686-pc-linux-gnu redhat Enterprise release
>   JobId:                  3681
>   Job:                    Backup-leodolter.2008-09-24_15.53.12
>   Backup Level:           Incremental, since=2008-09-24 15:49:03
>   Client:                 "leodolter-fd" 2.5.3 (16Sep08)
> i686-pc-linux-gnu,debian,lenny/sid FileSet:               
> "LinuxLocalPartitions" 2008-05-23 14:56:44 Pool:                  
> "DiskBackup" (From Job resource)
>   Catalog:                "MyCatalog" (From Client resource)
>   Storage:                "File" (From Job resource)
>   Scheduled time:         24-Sep-2008 15:53:32
>   Start time:             24-Sep-2008 15:53:43
>   End time:               24-Sep-2008 15:56:18
>   Elapsed time:           2 mins 35 secs
>   Priority:               10
>   FD Files Written:       22,299
>   SD Files Written:       22,299
>   FD Bytes Written:       249,462,803 (249.4 MB)
>   SD Bytes Written:       252,591,047 (252.5 MB)
>   Rate:                   1609.4 KB/s
>   Software Compression:   63.2 %
>   VSS:                    no
>   Encryption:             no
>   Accurate:               yes
>   Volume name(s):         Backup-0158
>   Volume Session Id:      179
>   Volume Session Time:    1221573719
>   Last Volume Bytes:      2,550,602,312 (2.550 GB)
>   Non-fatal FD errors:    0
>   SD Errors:              0
>   FD termination status:  OK
>   SD termination status:  OK
>   Termination:            Backup OK
>
> > If you really think that st_mtime has not changed since the last backup,
> > then please find the backup record in the catalog associated with the
> > previous backup job, and list it as well as the backup record from one of
> > the two jobs above.
>
> There a 2 minutes between End time of Job 3680
> and Start time of Job 3681 (see above)
>
> I don't think, i am sure st_time of /usr/bin/wget did not change.
> I used system call lstat to read st_mtime before i started Job 3680
> and after Job 3681 finished, it was exactly the same.
>
> Bacula reports different st_mtime, but stores the same st_mtime.
> Look at the sql query result,   u can see that only the 11'th column
> st_atime in LStat  changed, which is totally correct, but st_mtime and
> st_ctime are the same.
> (hopefully your email reader does not break lines)
>
> mysql> select File.JobId, File.FileId,
> Filename.Name,Path.Path,File.LStat,File.MD5 from File join Filename using
> (FilenameId)
>   join Path using (PathId) where File.JobId in  (3680,3681) and
> Filename.Name = 'wget';
> +-------+----------+------+-----------+------------------------------------
>------------------------+-----------------------------+
>
> | JobId | FileId   | Name | Path      | LStat                              
> |                        | MD5                         |
>
> +-------+----------+------+-----------+------------------------------------
>------------------------+-----------------------------+
>
> |  3680 | 79476174 | wget | /usr/bin/ | P4A HECd IHt B A A A 3PU BAA HI
> | BI2kMY BIxGDt BI11Hr A A E | FyVUN2j34bKjITbKF5khOovbiGs | 3681 |
> | 79498472 | wget | /usr/bin/ | P4A HECd IHt B A A A 3PU BAA HI BI2kWI
> | BIxGDt BI11Hr A A E | FyVUN2j34bKjITbKF5khOovbiGs |
>
> +-------+----------+------+-----------+------------------------------------
>------------------------+-----------------------------+ 2 rows in set (0.22
> sec)
>
> > I may be missing something here, but this looks normal to me.  I cannot
> > rule out a bug with st_mtime with the new code, but I would like to see
> > more information before asking Eric to look into it.
> >
> > Regards,
> >
> > Kern
>
> Thanks
> Ulrich
>
> > > so please tell me which st_mtime are compared?
> > > (maybe there is a hash code bug in accurrate.c,  just thinking
> > > because i dont understand)
> > >
> > > ulrich@leodolter:~$ bin/ul_bacula_lstat.pl /usr/bin/wget
> > > dev      =      65024 P4A
> > > ino      =    1851549 HECd
> > > mode     =      33261 IHt
> > > nlink    =          1 B
> > > uid      =          0 A
> > > gid      =          0 A
> > > rdev     =          0 A
> > > size     =     226260 3PU
> > > atime    = 1222265400 BI2ko4
> > > mtime    = 1220829421 BIxGDt
> > > ctime    = 1222070763 BI11Hr
> > > blksize  =       4096 BAA
> > > blocks   =        456 HI
> > > sha1     = FyVUN2j34bKjITbKF5khOovbiGs
> > >
> > >
> > > mysql> select File.JobId, Filename.Name,Path.Path,File.LStat,File.MD5
> > > from File join Filename using (FilenameId)
> > >    join Path using (PathId) where File.JobId in
> > > (3574,3605,3637,3669,3680,3681) and Filename.Name = 'wget';
> > > +-------+------+-----------+-------------------------------------------
> > >---- -------------+-----------------------------+
> > >
> > > | JobId | Name | Path      | LStat
> > > |
> > > |             | MD5                         |
> > >
> > > +-------+------+-----------+-------------------------------------------
> > >---- -------------+-----------------------------+
> > >
> > > |  3574 | wget | /usr/bin/ | P4A HEEh IHt B A A A 3PU BAA HI BIz28l
> > > | BIaVNu BIfhPi A A E | 8dz2rHajxE25WMWnQ2U6DUja/MI | 3637 | wget |
> > > | /usr/bin/ | P4A HECd IHt B A A A 3PU BAA HI BI2CXZ BIxGDt BI11Hr A A
> > > | E | FyVUN2j34bKjITbKF5khOovbiGs | 3669 | wget | /usr/bin/ | P4A HECd
> > > | IHt B A A A 3PU BAA HI BI2DL7 BIxGDt BI11Hr A A E |
> > > | FyVUN2j34bKjITbKF5khOovbiGs | 3680 | wget | /usr/bin/ | P4A HECd IHt
> > > | B A A A 3PU BAA HI BI2kMY BIxGDt BI11Hr A A E |
> > > | FyVUN2j34bKjITbKF5khOovbiGs | 3681 | wget | /usr/bin/ | P4A HECd IHt
> > > | B A A A 3PU BAA HI BI2kWI BIxGDt BI11Hr A A E |
> > > | FyVUN2j34bKjITbKF5khOovbiGs |
> > >
> > > +-------+------+-----------+-------------------------------------------
> > >---- -------------+-----------------------------+
> > >
> > >
> > > Please have a closer look at this
> > > Ulrich
> > >
> > > On Wed, 2008-09-24 at 14:01 +0200, Eric Bollengier wrote:
> > > > Hello,
> > > >
> > > > On Wednesday 24 September 2008 13:34:53 Kern Sibbald wrote:
> > > > > Hello,
> > > > >
> > > > > On Wednesday 24 September 2008 11:52:41 Ulrich Leodolter wrote:
> > > > > > Hi,
> > > > > >
> > > > > > I looks like Accurate Incremental backups work not like expected.
> > > > > >
> > > > > > I am using current bacula trunk, last update 2008-09-16.
> > > > > > No config changes since last update.
> > > > > >
> > > > > > Below is a Job list where i tried to track down the problem.
> > > > > > On Monday Sep 22 i did a system update (apt-get), so 20794 Files
> > > > > > are ok for Job 3637. But i did not make major changes on Sep 23,
> > > > > > so 21725 Files for Job 3669 are not expected!
> > > > > >
> > > > > >
> > > > > > JobId JobName Status Level Client Pool StartTime EndTime Duration
> > > > > > Files Bytes 3574 Backup-leodolter OK F leodolter-fd DiskBackup
> > > > > > 08-Sep-21 02:05 08-Sep-21 02:26 00:21:45 178,917   4.5 GB 3605
> > > > > > Backup-leodolter OK I leodolter-fd DiskBackup 08-Sep-22 02:05
> > > > > > 08-Sep-22 02:06 00:01:27     202 13.3 MB 3637 Backup-leodolter OK
> > > > > > I leodolter-fd DiskBackup 08-Sep-23 02:05 08-Sep-23 02:07
> > > > > > 00:02:34 20,794 187.6 MB 3669 Backup-leodolter OK I leodolter-fd
> > > > > > DiskBackup 08-Sep-24 02:05 08-Sep-24 02:07 00:02:42 21,725 192.6
> > > > > > MB
> > > > > >
> > > > > >
> > > > > > Now i looked at some special file /usr/bin/wget (see mysql select
> > > > > > below) As far as i can see only st_atime (11'th field in LStat)
> > > > > > changed from 23 Sep (JobId 3637) to 24 Sep (JobId 3669).
> > > > > >
> > > > > > Until now i thought st_atime is not used for Accurate backups.
> > > > >
> > > > > To the best of my knowledge, st_atime is not used by Bacula to make
> > > > > any decision whether or not to backup the file.  The tests are
> > > > > strictly against st_mtime and st_ctime (depending on how you
> > > > > configure Bacula).
> > > > >
> > > > > It sounds to me like you have a problem of an anti-virus program
> > > > > that is "touching" some files or some other change to your system
> > > > > happened. Running verify InitCatalog, then later Catalog can verify
> > > > > this ...
> > > > >
> > > > > > For me i looks like Accurate Incremental backups are always made
> > > > > > against last Full while ignoring previous Accurate Incremental
> > > > > > jobs (maybe i am completely wrong)
> > > > >
> > > > > I haven't taken a careful look at all the details you presented
> > > > > above, but Accurate works very much like existing backups -- that
> > > > > is it looks at st_mtime and st_ctime (if I am not mistaken), and if
> > > > > the file needs to be backed up for the "normal" backup reasons, it
> > > > > will be.  What Accurate does is in *addition* to the "normal"
> > > > > rules, it will check to see if a file has been deleted or has been
> > > > > added with an old date, and in those cases, it ensures that files
> > > > > that are deleted are so marked, and any file that is missed by the
> > > > > normal backup will also be backed up.
> > > > >
> > > > > I'll let Eric confirm this.
> > > >
> > > > I confirm :)
> > > >
> > > > Ulrich, you can try to run the the FD at debuglevel 200, and you will
> > > > see why the file has been backuped.
> > > >
> > > > Bye
> > > >
> > > > > If it is not working like I described above, then please let me
> > > > > know and we can look at it in more details.
> > > > >
> > > > > Best regards,
> > > > >
> > > > > Kern
> > > > >
> > > > > > mysql> select File.JobId,
> > > > > > Filename.Name,Path.Path,File.LStat,File.MD5 from File join
> > > > > > Filename using (FilenameId)
> > > > > >   join Path using (PathId)
> > > > > >  where File.JobId in (3574,3605,3637,3669) and Filename.Name =
> > > > > > 'wget';
> > > > > >
> > > > > > +-------+------+-----------+-------------------------------------
> > > > > >---- ---- -- -------------+-----------------------------+
> > > > > >
> > > > > > | JobId | Name | Path      | LStat
> > > > > > |
> > > > > > |             | MD5                         |
> > > > > >
> > > > > > +-------+------+-----------+-------------------------------------
> > > > > >---- ---- -- -------------+-----------------------------+
> > > > > >
> > > > > > |  3574 | wget | /usr/bin/ | P4A HEEh IHt B A A A 3PU BAA HI
> > > > > > | BIz28l BIaVNu BIfhPi A A E | 8dz2rHajxE25WMWnQ2U6DUja/MI | 3637
> > > > > > | | wget | /usr/bin/ | P4A HECd IHt B A A A 3PU BAA HI BI2CXZ
> > > > > > | BIxGDt BI11Hr A A E
> > > > > > |
> > > > > > | FyVUN2j34bKjITbKF5khOovbiGs | 3669 | wget | /usr/bin/ | P4A
> > > > > > | HECd IHt B A A A 3PU BAA HI BI2DL7 BIxGDt BI11Hr A A E |
> > > > > > | FyVUN2j34bKjITbKF5khOovbiGs |
> > > > > >
> > > > > > +-------+------+-----------+-------------------------------------
> > > > > >---- ---- -- -------------+-----------------------------+ 3 rows
> > > > > > in set (0.00 sec)
> > > > > >
> > > > > >
> > > > > > Please have a look at this
> > > > > > Thanks



-------------------------------------------------------------------------
This SF.Net email is sponsored by the Moblin Your Move Developer's challenge
Build the coolest Linux based applications with Moblin SDK & win great prizes
Grand prize is a trip for two to an Open Source event anywhere in the world
http://moblin-contest.org/redirect.php?banner_id=100&url=/
_______________________________________________
Bacula-devel mailing list
Bacula-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.sourceforge.net/lists/listinfo/bacula-devel


This mailing list archive is a service of Copilot Consulting.