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

[Bacula-devel] restore problem: bacula 2.5.26 reads 469GB from tape to restore 7GB job


Hello,

I am running the very latest svn version 2.5.26 (21 December 2008).

Today i tried to restore full copy job from tape.
Restore job finished OK, but took very long time.
After a few minutes disk write activity was done,
but tape read was active at 75MB/s for 1h52min.
Bacula reads the whole tape (496.6GB).
I would expect bacula to stop reading tape after
tape file 4 (see JobMedia entries below)

( 496GB * 1024 ) / (75MB/s) = 6772 seconds = 1 hour 52 min

Maybe this is related to latest changes in match_bsr.c.

Restore was done by selecting jobid 10086.
Below are job, media and restore log infos.

Regards
Ulrich


mysql> select * from Job where JobId=10086 \G
*************************** 1. row ***************************
          JobId: 10086
            Job: Backup-leodolter.2008-12-22_08.01.50.57
           Name: Backup-leodolter
           Type: C
          Level: F
       ClientId: 3
      JobStatus: T
      SchedTime: 2008-12-22 08:01:50
      StartTime: 2008-12-21 22:05:00
        EndTime: 2008-12-21 22:32:41
    RealEndTime: 2008-12-22 08:04:04
       JobTDate: 1229895161
   VolSessionId: 30
 VolSessionTime: 1229852609
       JobFiles: 208346
       JobBytes: 4546422690
      JobErrors: 0
JobMissingFiles: 0
         PoolId: 4
      FileSetId: 9
     PriorJobId: 10056
    PurgedFiles: 0
        HasBase: 0
1 row in set (0.00 sec)


mysql> select * from JobMedia where JobId=10086 order by VolIndex;
+------------+-------+---------+------------+-----------+-----------+---------+------------+----------+----------+------+--------+
| JobMediaId | JobId | MediaId | FirstIndex | LastIndex | StartFile | EndFile | StartBlock | EndBlock | VolIndex | Copy | Stripe |
+------------+-------+---------+------------+-----------+-----------+---------+------------+----------+----------+------+--------+
|      40364 | 10086 |     556 |          1 |     77667 |         0 |       0 |          1 |    15499 |        1 |    0 |      0 | 
|      40365 | 10086 |     556 |      77667 |    207239 |         1 |       1 |          0 |    15499 |        2 |    0 |      0 | 
|      40366 | 10086 |     556 |     207239 |    207626 |         2 |       2 |          0 |    15499 |        3 |    0 |      0 | 
|      40367 | 10086 |     556 |     207626 |    207694 |         3 |       3 |          0 |    15499 |        4 |    0 |      0 | 
|      40368 | 10086 |     556 |     207694 |    208346 |         4 |       4 |          0 |     8632 |        5 |    0 |      0 | 
+------------+-------+---------+------------+-----------+-----------+---------+------------+----------+----------+------+--------+


mysql> select * from Media where MediaId=556 \G
*************************** 1. row ***************************
         MediaId: 556
      VolumeName: BACU.003
            Slot: 22
          PoolId: 4
       MediaType: LTO-4
     MediaTypeId: 0
       LabelType: 0
    FirstWritten: 2008-12-22 08:01:50
     LastWritten: 2008-12-23 08:44:24
       LabelDate: 2008-12-22 08:01:50
         VolJobs: 45
        VolFiles: 531
       VolBlocks: 7815542
       VolMounts: 2
        VolBytes: 504196310016
        VolParts: 0
       VolErrors: 0
       VolWrites: 7815543
VolCapacityBytes: 0
       VolStatus: Append
         Enabled: 1
         Recycle: 1
    VolRetention: 15552000
  VolUseDuration: 604800
      MaxVolJobs: 0
     MaxVolFiles: 0
     MaxVolBytes: 0
       InChanger: 1
       StorageId: 2
        DeviceId: 0
 MediaAddressing: 0
     VolReadTime: 4467440271
    VolWriteTime: 1527164013
         EndFile: 530
        EndBlock: 243
      LocationId: 0
    RecycleCount: 0
    InitialWrite: 0000-00-00 00:00:00
   ScratchPoolId: 0
   RecyclePoolId: 0
         Comment: NULL
1 row in set (0.01 sec)


23-Dec 09:36 troll-dir JobId 10203: Start Restore Job
RestoreFiles.2008-12-23_09.36.55.24
23-Dec 09:42 troll-dir JobId 10203: Using Device "Drive-2"
23-Dec 09:43 troll-sd JobId 10203: Ready to read from volume "BACU.003"
on device "Drive-2" (/dev/nst1).
23-Dec 09:43 troll-sd JobId 10203: Forward spacing Volume "BACU.003" to
file:block 0:1.
23-Dec 11:30 troll-sd JobId 10203: Alert: TapeAlert: OK
23-Dec 11:30 troll-dir JobId 10203: Bacula troll-dir 2.5.26 (21Dec08):
23-Dec-2008 11:30:30
  Build OS:               i686-pc-linux-gnu redhat Enterprise release
  JobId:                  10203
  Job:                    RestoreFiles.2008-12-23_09.36.55.24
  Restore Client:         troll-fd
  Start time:             23-Dec-2008 09:36:57
  End time:               23-Dec-2008 11:30:30
  Files Expected:         208,344
  Files Restored:         208,344
  Bytes Restored:         7,184,419,981
  Rate:                   1054.5 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Restore OK

23-Dec 11:30 troll-dir JobId 10203: Begin pruning Jobs.
23-Dec 11:30 troll-dir JobId 10203: No Jobs found to prune.
23-Dec 11:30 troll-dir JobId 10203: Begin pruning Files.
23-Dec 11:30 troll-dir JobId 10203: No Files found to prune.
23-Dec 11:30 troll-dir JobId 10203: End auto prune.



-- 
Ulrich Leodolter <ulrich.leodolter@xxxxxxxx>
OBVSG


------------------------------------------------------------------------------
_______________________________________________
Bacula-devel mailing list
Bacula-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.sourceforge.net/lists/listinfo/bacula-devel


This mailing list archive is a service of Copilotco.