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

Re: [Bacula-devel] Accurate Incremental backup problem


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.