I think the problem is the VolAddr=0-1239074631492 line in the bsr file. Normally it would be a more precise range, but that range will be slow.
Was bscan used to reload data into the catalog for this volume some in the past? That can cause this problem with VolAddr. __Martin >>>>> On Fri, 1 Sep 2023 10:24:25 +0000, Lionel PLASSE said: > > Ok I don’t have any bsr file made at the backup time. It is an old volume > maybe is not cleanly made. The bsr created by the restore job today is like > this > > > > Storage="TEMP" > > Volume="T1" > > MediaType="TEMP" > > Device="TEMP" > > VolSessionId=34 > > VolSessionTime=1649883149 > > VolAddr=0-1239074631492 > > FileIndex=299750 > > Count=1 > > > > I’ve done a new restore from an recent backup and the forward step is > instantly and I have a lseek in the sd trace (you can see it after the no > lseek trace here) > > > > So how to be sure the lseek will be used. Is it because the volume or device > was not properly configured at the time I made the backup. Or it is because > of the fact there were no bsr file attached to the backup job . Or maybe > other ? > > > > Now It seems my recent job are correct and do a lseek each time . > > > > > > > > The SD trace => no lseek > > > > BUSTER_BKP-sd: job.c:78-0 <dird: JobId=9868 > job=RestoreFiles.2023-09-01_11.59.12_52 job_name=RestoreFiles > client_name=BUSTER_BKP-fd type=82 level=32 FileSet=Full^ASet NoAttr=0 > SpoolAttr=1 FileSetMD5=**Dummy** SpoolData=0 WritePartAfterJob=1 > PreferMountedVols=1 SpoolSize=0 rerunning=0 VolSessionId=0 VolSessionTime=0 > sd_client=0 Authorization=dummy > > BUSTER_BKP-sd: job.c:100-0 rerunning=0 VolSesId=0 VolSesTime=0 > > BUSTER_BKP-sd: job.c:158-9868 >dird jid=9868: 3000 OK Job SDid=227 > SDtime=1690932870 Authorization=DDLI-JNOB-DHHF-JFHC-PEMG-APJP-CCDK-FCNJ > > BUSTER_BKP-sd: dircmd.c:225-9868 <dird: use storage=TEMP media_type=TEMP > pool_name=BACUBAK pool_type=Backup append=0 copy=0 stripe=0 > > BUSTER_BKP-sd: dircmd.c:239-9868 Do command: use storage= > > BUSTER_BKP-sd: reserve.c:286-9868 <dird: use storage=TEMP media_type=TEMP > pool_name=BACUBAK pool_type=Backup append=0 > > copy=0 stripe=0 > > BUSTER_BKP-sd: reserve.c:315-9868 <dird device: use device=TEMP > > BUSTER_BKP-sd: reserve.c:250-9868 Inx=1 mntVol=1 exact=1 chgonly=0 low_use=1 > any=0 > > BUSTER_BKP-sd: reserve.c:466-9868 Start find_suit_dev PrefMnt=1 exact=1 > suitable=0 chgronly=0 any=0 > > BUSTER_BKP-sd: reserve.c:589-9868 search res for TEMP > > BUSTER_BKP-sd: reserve.c:667-9868 Try match res=BACKUP > > BUSTER_BKP-sd: reserve.c:667-9868 Try match res=BACUBAK > > BUSTER_BKP-sd: reserve.c:667-9868 Try match res=TEMP > > BUSTER_BKP-sd: reserve.c:670-9868 Try reserve vol= on device=TEMP > > BUSTER_BKP-sd: reserve.c:726-9868 chk MediaType device=TEMP request=TEMP > > BUSTER_BKP-sd: reserve.c:756-9868 try reserve TEMP > > BUSTER_BKP-sd: block_util.c:170-9868 New block adata=0 len=64512 > block=7fb444070fc0 > > BUSTER_BKP-sd: acquire.c:663-9868 Attach 0x440709a8 to dev "TEMP" (/mnt/TEMP) > > BUSTER_BKP-sd: acquire.c:714-9868 Attach Jid=9868 dcr=7fb4440709a8 size=0 > dev="TEMP" (/mnt/TEMP) > > BUSTER_BKP-sd: reserve.c:138-9868 Inc reserve=1 dev="TEMP" (/mnt/TEMP) > > BUSTER_BKP-sd: reserve.c:850-9868 Read reserved=1 dev_name=TEMP > mediatype=TEMP pool=BACUBAK ok=1 > > BUSTER_BKP-sd: reserve.c:863-9868 >dird: 3000 OK use device device=TEMP > > BUSTER_BKP-sd: reserve.c:681-9868 Device TEMP reserved=1 for read. > > BUSTER_BKP-sd: reserve.c:558-9868 available device found=TEMP > > BUSTER_BKP-sd: reserve.c:573-9868 OK dev found. Vol= > > BUSTER_BKP-sd: dircmd.c:225-9868 <dird: bootstrap > > BUSTER_BKP-sd: dircmd.c:239-9868 Do command: bootstrap > > BUSTER_BKP-sd: dircmd.c:1756-9868 === Bootstrap file === > > BUSTER_BKP-sd: dircmd.c:1758-9868 Storage="TEMP" > > BUSTER_BKP-sd: dircmd.c:1758-9868 Volume="T1" > > BUSTER_BKP-sd: dircmd.c:1758-9868 MediaType="TEMP" > > BUSTER_BKP-sd: dircmd.c:1758-9868 Device="TEMP" > > BUSTER_BKP-sd: dircmd.c:1758-9868 VolSessionId=34 > > BUSTER_BKP-sd: dircmd.c:1758-9868 VolSessionTime=1649883149 > > BUSTER_BKP-sd: dircmd.c:1758-9868 VolAddr=0-1239074631492 > > BUSTER_BKP-sd: dircmd.c:1758-9868 FileIndex=299750 > > BUSTER_BKP-sd: dircmd.c:1758-9868 Count=1 > > BUSTER_BKP-sd: dircmd.c:1762-9868 === end bootstrap file === > > Next : 0x0 > > Root bsr : 0x4406f8d8 > > VolumeName : T1 > > MediaType : TEMP > > Device : TEMP > > Slot : 0 > > SessId : 34 > > SessTime : 1649883149 > > VolAddr : 0-1239074631492 > > FileIndex : 299750 > > count : 1 > > found : 0 > > done : no > > positioning : 1 > > fast_reject : 1 > > BUSTER_BKP-sd: vol_mgr.c:152-9868 add read_vol=T1 JobId=9868 > > BUSTER_BKP-sd: dircmd.c:225-9868 <dird: runBUSTER_BKP-sd: dircmd.c:239-9868 > Do command: run > > BUSTER_BKP-sd: job.c:178-9868 Run_cmd: run > > BUSTER_BKP-sd: job.c:191-9868 sd_calls_client=0 sd_client=0 > > BUSTER_BKP-sd: job.c:213-9868 RestoreFiles.2023-09-01_11.59.12_52 waiting 5 > sec for FD to contact SD key=DDLI-JNOB-DH > > HF-JFHC-PEMG-APJP-CCDK-FCNJ > > BUSTER_BKP-sd: bsock.c:851-0 socket=5 who=client host=192.168.50.54 port=54994 > > BUSTER_BKP-sd: hello.c:147-0 Conn: Hello Bacula SD: Start Job > RestoreFiles.2023-09-01_11.59.12_52 214 > > BUSTER_BKP-sd: hello.c:170-0 Found Client Job > RestoreFiles.2023-09-01_11.59.12_52 > > BUSTER_BKP-sd: hello.c:181-0 fd_version=214 sd_version=0 > > BUSTER_BKP-sd: authenticate.c:164-0 Challenge FD > > BUSTER_BKP-sd: cram-md5.c:69-0 send: auth cram-md5 challenge > <286036779.1693562354@BUSTER_BKP-sd> ssl=0 > > BUSTER_BKP-sd: authenticate.c:168-0 Respond to FD challenge > > BUSTER_BKP-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 > <1762403182.1693562354@BUSTER_BKP-fd> ssl=0 > > BUSTER_BKP-sd: cram-md5.c:157-0 sending resp to challenge: > i+JJMEBgEXsvg+/Bvgl/gD > > BUSTER_BKP-sd: hello.c:206-0 OK Authentication jid=9868 Job > RestoreFiles.2023-09-01_11.59.12_52 > > BUSTER_BKP-sd: hello.c:223-0 === Auth OK, unblock Job > RestoreFiles.2023-09-01_11.59.12_52 jid=9868 sd_ver=0 > > BUSTER_BKP-sd: job.c:231-9868 === Auth=9868 jid=1 canceled=0 errstat=0 > > BUSTER_BKP-sd: job.c:239-9868 Running jid=9868 7fb44406ff98 > > BUSTER_BKP-sd: fd_cmds.c:117-9868 Start run > Job=RestoreFiles.2023-09-01_11.59.12_52 > > BUSTER_BKP-sd: fd_cmds.c:131-9868 ==== JobType=R run_job=9868 sd_client=0 > > BUSTER_BKP-sd: fd_cmds.c:166-9868 Do: do_client_commands > > BUSTER_BKP-sd: fd_cmds.c:212-9868 <filed: read open session = DummyVolume 227 > 1690932870 0 0 0 0 > > BUSTER_BKP-sd: fd_cmds.c:407-9868 read open session = DummyVolume 227 > 1690932870 0 0 0 0 > > BUSTER_BKP-sd: fd_cmds.c:419-9868 read_open_session got: JobId=9868 > Vol=DummyVolume VolSessId=227 VolSessT=1690932870 > > BUSTER_BKP-sd: fd_cmds.c:422-9868 StartF=0 EndF=0 StartB=0 EndB=0 > > BUSTER_BKP-sd: fd_cmds.c:435-9868 >filed: 3000 OK open ticket = 227 > > BUSTER_BKP-sd: fd_cmds.c:212-9868 <filed: read data 227 > > BUSTER_BKP-sd: fd_cmds.c:386-9868 Read data: read data 227 > > BUSTER_BKP-sd: fd_cmds.c:388-9868 <bfiled: read data 227 > > BUSTER_BKP-sd: read.c:50-9868 Start read data. > > BUSTER_BKP-sd: read.c:63-9868 Found 1 volumes names to restore. First=T1 > > BUSTER_BKP-sd: acquire.c:54-9868 Enter: bool acquire_device_for_read(DCR*) > > BUSTER_BKP-sd: acquire.c:58-9868 dcr=7fb4440709a8 dev=7fb44c0039c8 > > BUSTER_BKP-sd: acquire.c:59-9868 MediaType dcr=TEMP dev=TEMP > > BUSTER_BKP-sd: acquire.c:92-9868 Want Vol=T1 Slot=0 > > BUSTER_BKP-sd: acquire.c:106-9868 MediaType dcr=TEMP dev=TEMP > > BUSTER_BKP-sd: acquire.c:183-9868 MediaType dcr=TEMP dev=TEMP > > BUSTER_BKP-sd: acquire.c:200-9868 dir_get_volume_info vol=T1 > > BUSTER_BKP-sd: askdir.c:290-9868 >dird CatReq JobId=9868 GetVolInfo > VolName=T1 write=0 > > BUSTER_BKP-sd: askdir.c:233-9868 <dird n=31 1000 OK VolName=T1 VolJobs=6 > VolFiles=0 VolBlocks=0 VolBytes=1253924729286 VolABytes=0 VolHoleBytes=0 > VolHoles=0 VolMounts=7 VolErrors=0 VolWrites=19059315 > MaxVolBytes=3298534883328 VolCapacityBytes=0 VolStatus=Used Slot=0 > MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=4816416129 > VolWriteTime=657374353 EndFile=292 EndBlock=494255720 VolType=1 LabelType=0 > MediaId=1297 ScratchPoolId=0 VolParts=0 VolCloudParts=0 LastPartBytes=0 > Enabled=1 Recycle=1 > > BUSTER_BKP-sd: askdir.c:255-9868 do_reqest_vol_info return true slot=0 > Volume=T1 MediaId=1297 > > BUSTER_BKP-sd: askdir.c:259-9868 Dir returned VolCatAmetaBytes=1253924729286 > VolCatAdataBytes=0 Status=Used Vol=T1 MediaId=1297 > > BUSTER_BKP-sd: mount.c:636-9868 No swap_dev set. dev->vol=0 > > BUSTER_BKP-sd: mount.c:591-9868 Must load dev="TEMP" (/mnt/TEMP) > > BUSTER_BKP-sd: autochanger.c:105-9868 Device "TEMP" (/mnt/TEMP) is not an > autochanger > > BUSTER_BKP-sd: acquire.c:231-9868 open vol=T1 > > BUSTER_BKP-sd: file_dev.c:138-9868 Enter: virtual bool > file_dev::open_device(DCR*, int) > > BUSTER_BKP-sd: dev.c:113-9868 Enter: virtual bool DEVICE::open_device(DCR*, > int) > > BUSTER_BKP-sd: dev.c:325-9868 Enter: virtual bool DEVICE::mount(int) > > BUSTER_BKP-sd: file_dev.c:184-9868 open disk: mode=OPEN_READ_ONLY > open(/mnt/TEMP/T1, 0x0, 0640) > > BUSTER_BKP-sd: file_dev.c:194-9868 Did open(/mnt/TEMP/T1,OPEN_READ_ONLY,0640) > > BUSTER_BKP-sd: file_dev.c:211-9868 open dev: disk fd=6 opened > > BUSTER_BKP-sd: file_dev.c:214-9868 Leave: virtual bool > file_dev::open_device(DCR*, int) > > BUSTER_BKP-sd: acquire.c:239-9868 opened dev "TEMP" (/mnt/TEMP) OK > > BUSTER_BKP-sd: acquire.c:242-9868 calling read-vol-label > > BUSTER_BKP-sd: label.c:72-9868 Enter: virtual int > DEVICE::read_dev_volume_label(DCR*) > > BUSTER_BKP-sd: label.c:75-9868 Enter read_volume_label adata=0 res=1 > device="TEMP" (/mnt/TEMP) vol=T1 dev_Vol=*NULL* > > BUSTER_BKP-sd: label.c:90-9868 ==== worm=0 ==== > > BUSTER_BKP-sd: file_dev.c:71-9868 Enter: virtual bool DEVICE::rewind(DCR*) > > BUSTER_BKP-sd: label.c:129-9868 Big if statement in read_volume_label > > BUSTER_BKP-sd: block.c:520-9868 Pos for read=0 0 > > BUSTER_BKP-sd: block.c:545-9868 Read() adata=0 vol= nbytes=64512 pos=0 > > BUSTER_BKP-sd: block_util.c:456-9868 set block=7fb444070fc0 adata=0 binbuf=193 > > BUSTER_BKP-sd: block.c:641-9868 adata=0 block_len=217 buf_len=64512 > > BUSTER_BKP-sd: block.c:748-9868 Exit read_block read_len=64512 block_len=217 > binbuf=193 > > BUSTER_BKP-sd: record_read.c:211-9868 Rdata full adata=0 FI=VOL_LABEL > SessId=511 Strm=0 len=181 block=7fb444070fc0 > > BUSTER_BKP-sd: label.c:982-9868 Enter: bool unser_volume_label(DEVICE*, > DEV_RECORD*) > > BUSTER_BKP-sd: label.c:999-9868 reclen=181 recdata=Bacula 1.0 immortal > > BUSTER_BKP-sd: label.c:1001-9868 reclen=181 recdata=Bacula 1.0 immortal > > BUSTER_BKP-sd: label.c:1035-9868 unser_vol_label > > > > Volume Label: > > Adata : 0 > > Id : Bacula 1.0 immortal > > VerNo : 11 > > VolName : T1 > > PrevVolName : > > VolFile : 0 > > LabelType : VOL_LABEL > > LabelSize : 181 > > PoolName : TEMP > > MediaType : TEMP > > PoolType : Backup > > HostName : BUSTER-BKP > > Date label written: 11-mars-2022 15:03 > > BUSTER_BKP-sd: label.c:1039-9868 Leave: bool unser_volume_label(DEVICE*, > DEV_RECORD*) > > BUSTER_BKP-sd: label.c:152-9868 VolHdr.Id OK: Bacula 1.0 immortal > > > > BUSTER_BKP-sd: label.c:191-9868 VolHdr.VerNum=11 OK. > > BUSTER_BKP-sd: label.c:211-9868 Compare Vol names: VolName=T1 hdr=T1 > > > > Volume Label: > > Adata : 0 > > Id : Bacula 1.0 immortal > > VerNo : 11 > > VolName : T1 > > PrevVolName : > > VolFile : 0 > > LabelType : VOL_LABEL > > LabelSize : 181 > > PoolName : TEMP > > MediaType : TEMP > > PoolType : Backup > > HostName : BUSTER-BKP > > Date label written: 11-mars-2022 15:03 > > BUSTER_BKP-sd: label.c:261-9868 Leave read_volume_label() VOL_OK > > BUSTER_BKP-sd: file_dev.c:71-9868 Enter: virtual bool DEVICE::rewind(DCR*) > > BUSTER_BKP-sd: label.c:274-9868 Call reserve_volume=T1 > > BUSTER_BKP-sd: vol_mgr.c:381-9868 enter reserve_volume=T1 drive="TEMP" > (/mnt/TEMP) > > BUSTER_BKP-sd: vol_mgr.c:286-9868 new Vol=T1 slot=0 at 7fb444071bd8 > dev="TEMP" (/mnt/TEMP) > > BUSTER_BKP-sd: vol_mgr.c:548-9868 set in_use. vol=T1 dev="TEMP" (/mnt/TEMP) > > BUSTER_BKP-sd: label.c:289-9868 Leave: virtual int > DEVICE::read_dev_volume_label(DCR*) > > BUSTER_BKP-sd: acquire.c:246-9868 Got correct volume. VOL_OK: T1 > > BUSTER_BKP-sd: acquire.c:354-9868 dcr=7fb4440709a8 dev=7fb44c0039c8 > > BUSTER_BKP-sd: acquire.c:355-9868 MediaType dcr=TEMP dev=TEMP > > BUSTER_BKP-sd: acquire.c:357-9868 Leave: bool acquire_device_for_read(DCR*) > > BUSTER_BKP-sd: read_records.c:436-9868 Enter: BSR* > position_to_first_file(JCR*, DCR*, BSR*) > > BUSTER_BKP-sd: match_bsr.c:231-9868 use_pos=1 repos=1 > > BUSTER_BKP-sd: match_bsr.c:618-9868 OK match_volume=T1 > > BUSTER_BKP-sd: read_records.c:455-9868 Leave: BSR* > position_to_first_file(JCR*, DCR*, BSR*) > > BUSTER_BKP-sd: block.c:520-9868 Pos for read=0 0 > > BUSTER_BKP-sd: block.c:545-9868 Read() adata=0 vol=T1 nbytes=64512 pos=0 > > BUSTER_BKP-sd: block_util.c:456-9868 set block=7fb444070fc0 adata=0 binbuf=193 > > BUSTER_BKP-sd: block.c:641-9868 adata=0 block_len=217 buf_len=64512 > > BUSTER_BKP-sd: block.c:748-9868 Exit read_block read_len=64512 block_len=217 > binbuf=193 > > BUSTER_BKP-sd: read_records.c:174-9868 Read new block at pos=217 > > BUSTER_BKP-sd: read_records.c:224-9868 New record for state= SI=511 > ST=1642266413 > > BUSTER_BKP-sd: read_records.c:227-9868 Before read rec loop. stat= blk=0 > rem=0 invalid=0 > > BUSTER_BKP-sd: read_records.c:232-9868 Block NOT empty > > BUSTER_BKP-sd: record_read.c:211-9868 Rdata full adata=0 FI=VOL_LABEL > SessId=511 Strm=0 len=181 block=7fb444070fc0 > > BUSTER_BKP-sd: read_records.c:241-9868 read-OK. state_bits= blk=0 rem=0 > volume:addr=T1:216 > > BUSTER_BKP-sd: read_records.c:251-9868 recno=1 state_bits= blk=0 SI=511 > ST=1642266413 FI=-2 > > BUSTER_BKP-sd: label.c:982-9868 Enter: bool unser_volume_label(DEVICE*, > DEV_RECORD*) > > BUSTER_BKP-sd: label.c:999-9868 reclen=181 recdata=Bacula 1.0 immortal > > BUSTER_BKP-sd: label.c:1001-9868 reclen=181 recdata=Bacula 1.0 immortal > > BUSTER_BKP-sd: label.c:1035-9868 unser_vol_label > > > > Volume Label: > > Adata : 0 > > Id : Bacula 1.0 immortal > > VerNo : 11 > > VolName : T1 > > PrevVolName : > > VolFile : 0 > > LabelType : VOL_LABEL > > LabelSize : 181 > > PoolName : TEMP > > MediaType : TEMP > > PoolType : Backup > > HostName : BUSTER-BKP > > Date label written: 11-mars-2022 15:03 > > BUSTER_BKP-sd: label.c:1039-9868 Leave: bool unser_volume_label(DEVICE*, > DEV_RECORD*) > > BUSTER_BKP-sd: read_records.c:490-9868 Volume Label Record: VolSessionId=511 > VolSessionTime=1642266413 JobId=0 DataLen=181 > > BUSTER_BKP-sd: read_records.c:236-9868 !read-break. state_bits=Nohdr,empty > blk=0 rem=0 > > BUSTER_BKP-sd: read_records.c:365-9868 After end recs in block. pos=217 > > BUSTER_BKP-sd: block.c:520-9868 Pos for read=217 217 > > BUSTER_BKP-sd: block.c:545-9868 Read() adata=0 vol=T1 nbytes=64512 pos=217 > > BUSTER_BKP-sd: block_util.c:456-9868 set block=7fb444070fc0 adata=0 > binbuf=64488 > > BUSTER_BKP-sd: block.c:641-9868 adata=0 block_len=64512 buf_len=64512 > > BUSTER_BKP-sd: block.c:748-9868 Exit read_block read_len=64512 > block_len=64512 binbuf=64488 > > BUSTER_BKP-sd: read_records.c:174-9868 Read new block at pos=64729 > > BUSTER_BKP-sd: read_records.c:227-9868 Before read rec loop. stat=Nohdr,empty > blk=1 rem=0 invalid=0 > > BUSTER_BKP-sd: read_records.c:232-9868 Block NOT empty > > BUSTER_BKP-sd: record_read.c:211-9868 Rdata full adata=0 FI=SOS_LABEL > SessId=511 Strm=6266 len=173 block=7fb444070fc0 > > BUSTER_BKP-sd: read_records.c:241-9868 read-OK. state_bits= blk=1 rem=0 > volume:addr=T1:64728 > > BUSTER_BKP-sd: read_records.c:251-9868 recno=1 state_bits= blk=1 SI=511 > ST=1642266413 FI=-4 > > BUSTER_BKP-sd: label.c:1048-9868 Enter: bool > unser_session_label(SESSION_LABEL*, DEV_RECORD*) > > BUSTER_BKP-sd: label.c:1089-9868 Leave: bool > unser_session_label(SESSION_LABEL*, DEV_RECORD*) > > BUSTER_BKP-sd: read_records.c:490-9868 Begin Session Record: VolSessionId=511 > VolSessionTime=1642266413 JobId=6266 DataLen=173 > > BUSTER_BKP-sd: record_read.c:211-9868 Rdata full adata=0 FI=1 SessId=511 > Strm=UATTR len=99 block=7fb444070fc0 > > BUSTER_BKP-sd: read_records.c:241-9868 read-OK. state_bits= blk=1 rem=0 > volume:addr=T1:64728 > > BUSTER_BKP-sd: read_records.c:251-9868 recno=2 state_bits= blk=1 SI=511 > ST=1642266413 FI=1 > > BUSTER_BKP-sd: match_bsr.c:498-9868 Enter match_all > > BUSTER_BKP-sd: match_bsr.c:618-9868 OK match_volume=T1 > > BUSTER_BKP-sd: match_bsr.c:508-9868 OK bsr match bsr_vol=T1 read_vol=T1 > > BUSTER_BKP-sd: match_bsr.c:706-9868 match_voladdr: saddr=0 > eaddr=1239074631492 recaddr=64728 sfile=0 efile=288 recfile=0 > > BUSTER_BKP-sd: match_bsr.c:709-9868 OK match voladdr=64728 > > BUSTER_BKP-sd: match_bsr.c:521-9868 Fail on sesstime. bsr=1649883149 > rec=1642266413 > > BUSTER_BKP-sd: match_bsr.c:608-9868 Leave match all 0 > > BUSTER_BKP-sd: read_records.c:302-9868 match_bsr=0 bsr->reposition=0 > > BUSTER_BKP-sd: read_records.c:309-9868 BSR no match: clear rem=0 FI=1 before > set_eof pos 64729 > > BUSTER_BKP-sd: match_bsr.c:228-9868 No nxt_bsr use_pos=1 repos=0 > > BUSTER_BKP-sd: read_records.c:391-9868 nextbsr=0 mount_next_volume=0 > > BUSTER_BKP-sd: record_read.c:211-9868 Rdata full adata=0 FI=1 SessId=511 > Strm=DATA len=695 block=7fb444070fc0 > > BUSTER_BKP-sd: read_records.c:241-9868 read-OK. state_bits= blk=1 rem=0 > volume:addr=T1:64728 > > BUSTER_BKP-sd: read_records.c:251-9868 recno=3 state_bits= blk=1 SI=511 > ST=1642266413 FI=1 > > BUSTER_BKP-sd: match_bsr.c:498-9868 Enter match_all > > BUSTER_BKP-sd: match_bsr.c:618-9868 OK match_volume=T1 > > BUSTER_BKP-sd: match_bsr.c:508-9868 OK bsr match bsr_vol=T1 read_vol=T1 > > BUSTER_BKP-sd: match_bsr.c:706-9868 match_voladdr: saddr=0 > eaddr=1239074631492 recaddr=64728 sfile=0 efile=288 recfile=0 > > BUSTER_BKP-sd: match_bsr.c:709-9868 OK match voladdr=64728 > > BUSTER_BKP-sd: match_bsr.c:521-9868 Fail on sesstime. bsr=1649883149 > rec=1642266413 > > BUSTER_BKP-sd: match_bsr.c:608-9868 Leave match all 0 > > > > > > > > The SD trace for a newer backup job restored instantly : > > > > BUSTER_BKP-sd: label.c:191-9867 VolHdr.VerNum=11 OK. > > BUSTER_BKP-sd: label.c:211-9867 Compare Vol names: VolName=HEBDO1 hdr=HEBDO1 > > > > Volume Label: > > Adata : 0 > > Id : Bacula 1.0 immortal > > VerNo : 11 > > VolName : HEBDO1 > > PrevVolName : > > VolFile : 0 > > LabelType : VOL_LABEL > > LabelSize : 184 > > PoolName : DIFF > > MediaType : USB > > PoolType : Backup > > HostName : BUSTER-BKP > > Date label written: 14-janv.-2022 19:58 > > BUSTER_BKP-sd: label.c:261-9867 Leave read_volume_label() VOL_OK > > BUSTER_BKP-sd: file_dev.c:71-9867 Enter: virtual bool DEVICE::rewind(DCR*) > > BUSTER_BKP-sd: label.c:274-9867 Call reserve_volume=HEBDO1 > > BUSTER_BKP-sd: vol_mgr.c:381-9867 enter reserve_volume=HEBDO1 drive="BACKUP" > (/BKP/bacubak) > > BUSTER_BKP-sd: vol_mgr.c:286-9867 new Vol=HEBDO1 slot=0 at 7fb444071538 > dev="BACKUP" (/BKP/bacubak) > > BUSTER_BKP-sd: vol_mgr.c:548-9867 set in_use. vol=HEBDO1 dev="BACKUP" > (/BKP/bacubak) > > BUSTER_BKP-sd: label.c:289-9867 Leave: virtual int > DEVICE::read_dev_volume_label(DCR*) > > BUSTER_BKP-sd: acquire.c:246-9867 Got correct volume. VOL_OK: HEBDO1 > > BUSTER_BKP-sd: acquire.c:354-9867 dcr=7fb444070378 dev=7fb44c001318 > > BUSTER_BKP-sd: acquire.c:355-9867 MediaType dcr=USB dev=USB > > BUSTER_BKP-sd: acquire.c:357-9867 Leave: bool acquire_device_for_read(DCR*) > > BUSTER_BKP-sd: read_records.c:436-9867 Enter: BSR* > position_to_first_file(JCR*, DCR*, BSR*) > > BUSTER_BKP-sd: match_bsr.c:231-9867 use_pos=1 repos=1 > > BUSTER_BKP-sd: match_bsr.c:618-9867 OK match_volume=HEBDO1 > > BUSTER_BKP-sd: read_records.c:451-9867 pos_to_first_file from addr=0 to > 3634588568 > > BUSTER_BKP-sd: file_dev.c:107-9867 ===== lseek to 3634588568 > > BUSTER_BKP-sd: read_records.c:455-9867 Leave: BSR* > position_to_first_file(JCR*, DCR*, BSR*) > > BUSTER_BKP-sd: block.c:520-9867 Pos for read=3634588568 3634588568 > > BUSTER_BKP-sd: block.c:545-9867 Read() adata=0 vol=HEBDO1 nbytes=256000 > pos=3634588568 > > BUSTER_BKP-sd: block_util.c:456-9867 set block=7fb44406fc40 adata=0 > binbuf=255976 > > > > > > De : Radosław Korzeniewski <rados...@korzeniewski.net> > Envoyé : jeudi 31 août 2023 18:30 > À : Lionel PLASSE <pla...@cofiem.fr> > Cc : Martin Simmons <mar...@lispworks.com>; bacula-users@lists.sourceforge.net > Objet : Re: [Bacula-users] Restore job forward space volume - usb file volume > > > > Hi, > > > > pon., 28 sie 2023 o 10:13 Lionel PLASSE <pla...@cofiem.fr > <mailto:pla...@cofiem.fr> > napisał(a): > > You're right, I say it was slow from my own apreciation. > The Volume file is 1 TB. And the restoration job was 65 GB. > > And unfortunately, I don't have the exact timing for each steps , but I was > stuck in the "forwarding spacing " for half an hour before I stopped watching. > > > > Could you share a restore BSR file for this restore? At this file you can > check what parts of the volume will be "fast-forwarded" which for a file on a > block device (usb disk) means Bacula just executes lseek(2) which takes > almost "no time"; and what Bacula will read block by block. > > > > best regards > > -- > > Radosław Korzeniewski > rados...@korzeniewski.net <mailto:rados...@korzeniewski.net> > > _______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
