Forum Discussion

Sener's avatar
Sener
Level 2
2 months ago

"INF - Waiting for positioning" is waiting for a very long time

Hello,
on my media server, writing from adv disk to tape takes a very long time. when I look at the job details, "INF - Waiting for positioning" is waiting for a very long time. Can you help me?

 

Aug 2, 2024 1:23:38 AM - requesting resource  LCM_lap05nbumedia_LTO7_TLD0 Aug 2, 2024 1:23:45 AM - granted resource  LCM_lap05nbumedia_LTO7_TLD0 Aug 2, 2024 1:23:46 AM - begin Duplicate Aug 2, 2024 1:23:46 AM - started process RUNCMD (pid=1844) Aug 2, 2024 1:23:46 AM - ended process 0 (pid=1844) Aug 2, 2024 1:23:46 AM - requesting resource  lap05nbumedia_LTO7_TLD0 Aug 2, 2024 1:23:46 AM - requesting resource  @aaacZ Aug 2, 2024 1:23:46 AM - reserving resource @aaacZ Aug 2, 2024 1:23:56 AM - awaiting resource lap05nbumedia_LTO7_TLD0. No drives are available. Aug 2, 2024 2:20:45 AM - Info bpduplicate (pid=1844) window close behavior: Suspend Aug 2, 2024 2:20:45 AM - Info bpduplicate (pid=1844) The data-in-transit encryption (DTE) is disabled, as the global DTE mode is set to 'Preferred Off' Aug 2, 2024 2:20:45 AM - Waiting for scan drive stop LTO7_0_9, Media server: lap05nbumedia.int.teb.com.tr Aug 2, 2024 2:20:45 AM - resource @aaacZ reserved Aug 2, 2024 2:20:45 AM - granted resource  LU5399 Aug 2, 2024 2:20:45 AM - granted resource  LTO7_0_9 Aug 2, 2024 2:20:45 AM - granted resource  lap05nbumedia_LTO7_TLD0 Aug 2, 2024 2:20:45 AM - granted resource  MediaID=@aaacZ;DiskVolume=/advol01;DiskPool=ADV01_Pool_lap05nbumedia;Path=/advol01;StorageServer=lap05nbumedia.int.teb.com.tr;MediaServer=lap05nbumedia.int.teb.com.tr Aug 2, 2024 2:20:46 AM - Info bptm (pid=826471) start Aug 2, 2024 2:20:46 AM - started process bptm (pid=826471) Aug 2, 2024 2:20:46 AM - Info bptm (pid=826471) start backup Aug 2, 2024 2:20:46 AM - Info bpdm (pid=826495) started Aug 2, 2024 2:20:46 AM - started process bpdm (pid=826495) Aug 2, 2024 2:20:46 AM - Info bpdm (pid=826495) reading backup image Aug 2, 2024 2:20:46 AM - Info bpdm (pid=826495) using 64 data buffers Aug 2, 2024 2:20:46 AM - Info bpdm (pid=826495) requesting nbjm for media Aug 2, 2024 2:20:46 AM - Info bptm (pid=826471) Waiting for mount of media id LU5399 (copy 2) on server lap05nbumedia.int.teb.com.tr. Aug 2, 2024 2:20:46 AM - started process bptm (pid=826471) Aug 2, 2024 2:20:46 AM - mounting LU5399 Aug 2, 2024 2:20:46 AM - Info bptm (pid=826471) INF - Waiting for mount of media id LU5399 on server lap05nbumedia.int.teb.com.tr for writing. Aug 2, 2024 2:20:47 AM - begin reading Aug 2, 2024 2:21:16 AM - Info bptm (pid=826471) KMS Server Info - Name: nbkms (nbu01master.int.teb.com.tr), Type: NBKMS Aug 2, 2024 2:21:16 AM - Info bptm (pid=826471) media id LU5399 mounted on drive index 15, drivepath /dev/tape/by-path/pci-0000:ca:00.0-fc-0x500507604454ed0c-lun-0-nst, drivename LTO7_0_9, copy 2 Aug 2, 2024 2:21:16 AM - Info bptm (pid=826471) INF - Waiting for positioning of media id LU5399 on server lap05nbumedia.int.teb.com.tr for writing. Aug 4, 2024 8:00:35 PM - Info bptm (pid=826471) waited for full buffer 11 times, delayed 39 times Aug 4, 2024 8:00:40 PM - Info bptm (pid=826471) EXITING with status 0 <---------- Aug 4, 2024 8:00:41 PM - end reading; read time: 65:39:54 Aug 4, 2024 8:00:41 PM - Info bpdm (pid=826495) completed reading backup image Aug 4, 2024 8:00:41 PM - Info bpdm (pid=826495) EXITING with status 0 Aug 4, 2024 8:00:41 PM - end Duplicate; elapsed time 66:36:55 The requested operation was successfully completed.  (0)

  • quebek's avatar
    quebek
    Moderator
    2 months ago

    Hey,

    I would have started with creation of bptm and bpdm logs on this given media server. Than I would bumped the verbosity to at least 3 on this media server. Now wait for new duplication to take place, note pids for bptm and bpdm - grep for the same in the relevant logs. Post these findings. Maybe there are intermittent errors. Also grab some logs from the tape library for this given drive, maybe some clues will be out there too.

    • davidmoline's avatar
      davidmoline
      Level 6
      2 months ago

      Adding to Quebek's suggetion - how large is the backup being duplicated? What about the server itself - what type/speed/RAM/disk etc. 

      Can you confirm the write to tape is confiugured to use encryption? It shouldn't unduly slow the process down as once the KMS key is sent to the drive, the drive hardware does the rest (there would be some penalty, but I don't believe it is significant).

      Finally one issue with tape if the system feeding data to the tape isn't fast enough the tape drive can "shoe-shine" which can cause delays - the logging suggested already will help to identify this. Also review the best options for tape buffers (this article may help in adjusting the tuning - it is Windows related, but there are references to Unix settings in the article as well) https://www.veritas.com/content/support/en_US/article.100030830.html

      Cheers
      David

  • Nicolai's avatar
    Nicolai
    Moderator
    2 months ago

    From the log text it seems this a very small image being duplicated. 

    Is this a general issues on duplication on just this one job ?

    However from the log text alone it's not possible to make a conclusion. 

    My recommendation:

    • Do what Qubeck suggested
    • Look in the syslog / even log for SCSI sense data from the tape drive

     

    What operating system is the media server running ?

    On a general note : You should also bump to NUMBER_DATA_BUFFERS to 256 or 512.

    /Nicolai