Forum Discussion

aprocaccino's avatar
aprocaccino
Level 3
3 years ago

Sybase restore take more time than usual

Hello,

Since some days, the refreshs from sybase are taking more time than usually.

Activity monitor logs from this morning is the following : 


Jul 28, 2022 5:18:24 AM - begin Restore
Jul 28, 2022 5:18:25 AM - Info bprd (pid=72446) Found (1) files in (1) images for Restore Job ID 5010796.xxx
Jul 28, 2022 5:18:26 AM - restoring from image vmp-sybase-13_1658964717
Jul 28, 2022 5:18:26 AM - Info bprd (pid=72446) Searched (1) files of (1) files for Restore Job ID 5010796.xxx
Jul 28, 2022 5:18:26 AM - Info bprd (pid=72446) Restoring from copy 1 of image created Thu Jul 28 01:31:57 2022 from policy PRD_DC1_SYB
Jul 28, 2022 5:18:26 AM - requesting resource  @aaafR
Jul 28, 2022 5:18:26 AM - granted resource  MediaID=@aaafR;DiskVolume=dc1backup;DiskPool=DC1-DD9400-01_dc1backup_dp;Path=dc1backup;StorageServer=dc1-dd9400-01-backup.lux.eib.org;MediaServer=vmp-nbums-05.lux.eib.org
Jul 28, 2022 5:18:27 AM - Info bpbrm (pid=2351893) vmt-sybase-40.lux.eib.org is the host to restore to
Jul 28, 2022 5:18:27 AM - Info bpbrm (pid=2351893) reading file list for client
Jul 28, 2022 5:18:27 AM - Info bpbrm (pid=2351893) listening for client connection
Jul 28, 2022 5:18:28 AM - Info bpbrm (pid=2351893) accepted connection from client
Jul 28, 2022 5:18:28 AM - Info dbclient (pid=28172) Restore started
Jul 28, 2022 5:18:28 AM - Info bpbrm (pid=2351893) bptm pid: 2351906
Jul 28, 2022 5:18:29 AM - Info bptm (pid=2351906) start
Jul 28, 2022 5:18:29 AM - started process bptm (pid=2351906)
Jul 28, 2022 5:18:29 AM - Info bptm (pid=2351906) reading backup image
Jul 28, 2022 5:18:29 AM - Info bptm (pid=2351906) using 512 data buffers
Jul 28, 2022 5:18:29 AM - Info bptm (pid=2351906) spawning a child process
Jul 28, 2022 5:18:29 AM - Info bptm (pid=2351906) child pid: 2351908
Jul 28, 2022 5:18:31 AM - begin reading
Jul 28, 2022 5:55:42 AM - Info bptm (pid=2351906) waited for empty buffer 29858 times, delayed 40615 times
Jul 28, 2022 5:55:42 AM - end reading; read time: 0:37:11
Jul 28, 2022 6:21:22 AM - Info bptm (pid=2351906) completed reading backup image
Jul 28, 2022 6:21:22 AM - Info bptm (pid=2351906) EXITING with status 0 <----------
Jul 28, 2022 6:21:22 AM - Info dbclient (pid=28172) done. status: 0
Jul 28, 2022 6:21:22 AM - Info dbclient (pid=28172) done. status: 0: the requested operation was successfully completed
Jul 28, 2022 6:21:22 AM - restored from image vmp-sybase-13_1658964717; restore time: 1:02:56
Jul 28, 2022 6:21:23 AM - end Restore; elapsed time 1:02:59
The requested operation was successfully completed.  (0)

We can see that there is a delay between "end reading; read time: 0:37:11" and "Info bptm (pid=2351906) completed reading backup image"

bptm logs are the following : 

05:55:42.794 [2351906] <2> read_data: read short block, bytes = 819200, remainder = 0
05:55:42.794 [2351906] <2> read_data: waited for empty buffer 29858 times, delayed 40615 times
05:55:42.812 [2351906] <2> ConnectionCache::connectAndCache: Acquiring new connection for host bck-srv, query type 1
05:55:42.815 [2351906] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
05:55:42.874 [2351906] <2> vnet_proxy_protocol_from_legacy_ex: remote_proxy_version = 4
05:55:42.875 [2351906] <2> logconnections: PROXY CONNECT FROM 172.19.151.22.58627 TO 172.26.88.130.1556 fd = 19
05:55:42.875 [2351906] <2> logconnections: BPDBM CONNECT FROM 127.0.0.1.36799 TO 127.0.0.1.52298 fd = 19
05:55:42.924 [2351906] <2> db_end: Need to collect reply
05:55:42.933 [2351906] <2> closeConnection: Caching connection for query type 1 for reuse
05:55:42.933 [2351906] <4> report_throughput: VBRT 2 2351906 4 1 dc1backup @aaafR 0 1 0 106439456 106439456 1528 180476 612496 1561757 29858 40615 15 103946 512 (../bptm.c.11992)
[...]
06:21:22.399 [2351908] <2> get_next_file: [2351906] received string: (EXIT STATUS 0)
06:21:22.400 [2351908] <2> terminate_restore: [2351906] waited for full buffer 43 times, delayed 17066 times
06:21:22.400 [2351908] <2> terminate_restore: [2351906] sent 1 directories/files to client vmt-sybase-40.lux.eib.org
06:21:22.402 [2351908] <8> JobdSockList::~JobdSockList: 1 socket left.
06:21:22.402 [2351908] <4> JobdSockList::UnregisterSocket: Unregister socket (1).
06:21:22.402 [2351908] <2> put_length_bytes_nonblocking: cannot write data to network: Bad file descriptor (9)
06:21:22.402 [2351908] <2> job_disconnect: Failed to send request
06:21:22.402 [2351908] <2> vnet_proxy_get_logs: fstat(1) failed: 9
06:21:22.444 [2351906] <2> ConnectionCache::connectAndCache: Acquiring new connection for host bck-srv, query type 1
06:21:22.447 [2351906] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
06:21:22.502 [2351906] <2> vnet_proxy_protocol_from_legacy_ex: remote_proxy_version = 4
06:21:22.503 [2351906] <2> logconnections: PROXY CONNECT FROM 172.19.151.22.37405 TO 172.26.88.130.1556 fd = 19
06:21:22.503 [2351906] <2> logconnections: BPDBM CONNECT FROM 127.0.0.1.51745 TO 127.0.0.1.34094 fd = 19
06:21:22.548 [2351906] <2> db_end: Need to collect reply
06:21:22.557 [2351906] <2> closeConnection: Caching connection for query type 1 for reuse
06:21:22.557 [2351906] <4> read_backup: successfully read (restore) backup id vmp-sybase-13_1658964717, copy 1, fragment 1, 106439456 Kbytes at 47705.219 Kbytes/sec
06:21:22.558 [2351906] <2> notify: executing - /usr/openv/netbackup/bin/restore_notify bptm vmp-sybase-13_1658964717 restore
06:21:22.563 [2351906] <2> Media_dispatch_signal: calling child_wait (../common.c:4234) delay 0 seconds
06:21:22.563 [2351906] <2> bptm: Calling tpunmount for media @aaafR
06:21:22.563 [2351906] <2> send_MDS_msg: MEDIA_DONE 0 5010796 0 @aaafR 373 0 {F1CAC1CA-0E23-11ED-9443-B56714432736}
06:21:22.563 [2351906] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 5010796 0 @aaafR 373 0 {F1CAC1CA-0E23-11ED-9443-B56714432736})
06:21:22.563 [2351906] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 5010796 copyNum 0 mediaId @aaafR mediaKey 373 unloadDelay 0 allocId {F1CAC1CA-0E23-11ED-9443-B56714432736}
06:21:22.563 [2351906] <2> packageBptmResourceDoneMsg: returns 0
06:21:22.569 [2351906] <2> JobInst::sendIrmMsg: returning
06:21:22.569 [2351906] <2> bptm: EXITING with status 0 <----------

 

An old refresh was like that : 


Jul 19, 2022 5:18:18 AM - begin Restore
Jul 19, 2022 5:18:18 AM - Info bprd (pid=98862) Found (1) files in (1) images for Restore Job ID 4870118.xxx
Jul 19, 2022 5:18:19 AM - restoring from image vmp-sybase-13_1658187148
Jul 19, 2022 5:18:19 AM - Info bprd (pid=98862) Searched (1) files of (1) files for Restore Job ID 4870118.xxx
Jul 19, 2022 5:18:19 AM - Info bprd (pid=98862) Restoring from copy 1 of image created Tue Jul 19 01:32:28 2022 from policy PRD_DC1_SYB
Jul 19, 2022 5:18:19 AM - requesting resource  @aaafR
Jul 19, 2022 5:18:19 AM - granted resource  MediaID=@aaafR;DiskVolume=dc1backup;DiskPool=DC1-DD9400-01_dc1backup_dp;Path=dc1backup;StorageServer=dc1-dd9400-01-backup.lux.eib.org;MediaServer=vmp-nbums-05.lux.eib.org
Jul 19, 2022 5:18:21 AM - Info bpbrm (pid=1983908) vmt-sybase-40.lux.eib.org is the host to restore to
Jul 19, 2022 5:18:21 AM - Info bpbrm (pid=1983908) reading file list for client
Jul 19, 2022 5:18:21 AM - Info bpbrm (pid=1983908) listening for client connection
Jul 19, 2022 5:18:22 AM - Info bpbrm (pid=1983908) accepted connection from client
Jul 19, 2022 5:18:22 AM - Info dbclient (pid=20498) Restore started
Jul 19, 2022 5:18:22 AM - Info bpbrm (pid=1983908) bptm pid: 1983918
Jul 19, 2022 5:18:22 AM - Info bptm (pid=1983918) start
Jul 19, 2022 5:18:22 AM - started process bptm (pid=1983918)
Jul 19, 2022 5:18:23 AM - Info bptm (pid=1983918) reading backup image
Jul 19, 2022 5:18:23 AM - Info bptm (pid=1983918) using 512 data buffers
Jul 19, 2022 5:18:23 AM - Info bptm (pid=1983918) spawning a child process
Jul 19, 2022 5:18:23 AM - Info bptm (pid=1983918) child pid: 1983920
Jul 19, 2022 5:18:25 AM - begin reading
Jul 19, 2022 5:46:20 AM - Info bptm (pid=1983918) waited for empty buffer 7364 times, delayed 17401 times
Jul 19, 2022 5:46:20 AM - end reading; read time: 0:27:55
Jul 19, 2022 5:47:57 AM - Info bptm (pid=1983918) completed reading backup image
Jul 19, 2022 5:47:57 AM - Info bptm (pid=1983918) EXITING with status 0 <----------
Jul 19, 2022 5:47:57 AM - Info dbclient (pid=20498) done. status: 0
Jul 19, 2022 5:47:57 AM - Info dbclient (pid=20498) done. status: 0: the requested operation was successfully completed
Jul 19, 2022 5:47:57 AM - restored from image vmp-sybase-13_1658187148; restore time: 0:29:38
Jul 19, 2022 5:47:58 AM - end Restore; elapsed time 0:29:40
The requested operation was successfully completed.  (0)

 

Here, there is almost no delay between "end reading" and "Info bptm (pid=1983918) completed reading backup image"

05:46:20.084 [1983918] <2> read_data: read short block, bytes = 360448, remainder = 0
05:46:20.085 [1983918] <2> read_data: waited for empty buffer 7364 times, delayed 17401 times
05:46:20.104 [1983918] <2> ConnectionCache::connectAndCache: Acquiring new connection for host bck-srv, query type 1
05:46:20.107 [1983918] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
05:46:20.163 [1983918] <2> vnet_proxy_protocol_from_legacy_ex: remote_proxy_version = 4
05:46:20.164 [1983918] <2> logconnections: PROXY CONNECT FROM 172.19.151.22.34583 TO 172.26.88.130.1556 fd = 19
05:46:20.164 [1983918] <2> logconnections: BPDBM CONNECT FROM 127.0.0.1.36963 TO 127.0.0.1.49226 fd = 19
05:46:20.211 [1983918] <2> db_end: Need to collect reply
05:46:20.217 [1983918] <2> closeConnection: Caching connection for query type 1 for reuseroot.071922_00001.log
05:46:20.217 [1983918] <4> report_throughput: VBRT 2 1983918 4 1 dc1backup @aaafR 0 1 0 105617760 105617760 4389 1326 264181 1358602 7364 17401 15 103144 512 (../bptm.c.11992)
05:47:57.122 [1983920] <2> get_next_file: [1983918] received string: (EXIT STATUS 0)
05:47:57.122 [1983920] <2> terminate_restore: [1983918] waited for full buffer 11309 times, delayed 16489 times
05:47:57.122 [1983920] <2> terminate_restore: [1983918] sent 1 directories/files to client vmt-sybase-40.lux.eib.org
05:47:57.124 [1983920] <8> JobdSockList::~JobdSockList: 1 socket left.
05:47:57.124 [1983920] <4> JobdSockList::UnregisterSocket: Unregister socket (1).
05:47:57.124 [1983920] <2> put_length_bytes_nonblocking: cannot write data to network: Bad file descriptor (9)
05:47:57.124 [1983920] <2> job_disconnect: Failed to send request
05:47:57.124 [1983920] <2> vnet_proxy_get_logs: fstat(1) failed: 9
05:47:57.163 [1983918] <2> ConnectionCache::connectAndCache: Acquiring new connection for host bck-srv, query type 1
05:47:57.166 [1983918] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
05:47:57.181 [1983918] <2> vnet_proxy_protocol_from_legacy_ex: remote_proxy_version = 4
05:47:57.183 [1983918] <2> logconnections: PROXY CONNECT FROM 172.19.151.22.43387 TO 172.26.88.130.1556 fd = 19
05:47:57.183 [1983918] <2> logconnections: BPDBM CONNECT FROM 127.0.0.1.36963 TO 127.0.0.1.49256 fd = 19
05:47:57.231 [1983918] <2> db_end: Need to collect reply
05:47:57.238 [1983918] <2> closeConnection: Caching connection for query type 1 for reuse
05:47:57.238 [1983918] <4> read_backup: successfully read (restore) backup id vmp-sybase-13_1658187148, copy 1, fragment 1, 105617760 Kbytes at 63059.972 Kbytes/sec
05:47:57.238 [1983918] <2> notify: executing - /usr/openv/netbackup/bin/restore_notify bptm vmp-sybase-13_1658187148 restore
05:47:57.244 [1983918] <2> Media_dispatch_signal: calling child_wait (../common.c:4234) delay 0 seconds
05:47:57.244 [1983918] <2> bptm: Calling tpunmount for media @aaafR
05:47:57.244 [1983918] <2> send_MDS_msg: MEDIA_DONE 0 4870118 0 @aaafR 373 0 {703272B6-0711-11ED-B5E1-81C675697DE0}
05:47:57.244 [1983918] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 4870118 0 @aaafR 373 0 {703272B6-0711-11ED-B5E1-81C675697DE0})
05:47:57.244 [1983918] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 4870118 copyNum 0 mediaId @aaafR mediaKey 373 unloadDelay 0 allocId {703272B6-0711-11ED-B5E1-81C675697DE0}
05:47:57.244 [1983918] <2> packageBptmResourceDoneMsg: returns 0
05:47:57.250 [1983918] <2> JobInst::sendIrmMsg: returning
05:47:57.250 [1983918] <2> bptm: EXITING with status 0 <----------

 

Any idea why there can be a delay ? How can I investigate ?

  • Hamza_H's avatar
    Hamza_H
    Moderator
    3 years ago

    Hello,

    based on details that you provided, there is a difference between the throughput in both jobs.

    for slow job, the throughput was : 47705.219 Kbytes/sec

    faster job: 63059.972 Kbytes/sec

     

    I am not saying this is the absolute root cause but I recommend to check that first.

    because data buffers are the same (512), you may want to make some changes there and re-run a new test restore to verify if you want..

    also can you do a restore of the same image that you used in the faster job to compare?

     

    good luck

     

    BR.

    • aprocaccino's avatar
      aprocaccino
      Level 3
      3 years ago

      Hello Hamza,

      Thanks for your answer.

      Yes the speed rate is a little bit slower on the impacted job, but I don't think it's relevant because, as you can see in the logs, there is a delay of almost 30min between two operations

      Jul 28, 2022 5:18:31 AM - begin reading
      Jul 28, 2022 5:55:42 AM - Info bptm (pid=2351906) waited for empty buffer 29858 times, delayed 40615 times
      Jul 28, 2022 5:55:42 AM - end reading; read time: 0:37:11
      Jul 28, 2022 6:21:22 AM - Info bptm (pid=2351906) completed reading backup image
      Jul 28, 2022 6:21:22 AM - Info bptm (pid=2351906) EXITING with status 0 <----------

      While the delay is unsignificant on the correct job

      Jul 19, 2022 5:18:25 AM - begin reading
      Jul 19, 2022 5:46:20 AM - Info bptm (pid=1983918) waited for empty buffer 7364 times, delayed 17401 times
      Jul 19, 2022 5:46:20 AM - end reading; read time: 0:27:55
      Jul 19, 2022 5:47:57 AM - Info bptm (pid=1983918) completed reading backup image
      Jul 19, 2022 5:47:57 AM - Info bptm (pid=1983918) EXITING with status 0 <----------

       

  • Nicolai's avatar
    Nicolai
    Moderator
    3 years ago

    hi aprocaccino 

    I would say it's bandwidth issues to the client

    Slow job :  waited for empty buffer 29858 times

    Meaning disk was ready to read more backup data from disk, but the Netbackup restore buffers where all used up. Restore data is ready in memory and waiting transfer to client. Iperf3 is a good tool to test network connections, I would try that first.

    Normal job : Info bptm (pid=1983918) waited for empty buffer 7364 times

    Best Regards
    Nicolai

     

    • aprocaccino's avatar
      aprocaccino
      Level 3
      3 years ago

      Hello Nicolai,

      Problem is that I have this behaviour even when the job is not waiting for buffer at all.

      Here is status of last restore : 

      Jul 30, 2022 5:18:25 AM - begin Restore
      Jul 30, 2022 5:18:25 AM - Info bprd (pid=95544) Found (1) files in (1) images for Restore Job ID 5042886.xxx
      Jul 30, 2022 5:18:26 AM - restoring from image vmp-sybase-13_1659147448
      Jul 30, 2022 5:18:26 AM - requesting resource  @aaafR
      Jul 30, 2022 5:18:26 AM - granted resource  MediaID=@aaafR;DiskVolume=dc1backup;DiskPool=DC1-DD9400-01_dc1backup_dp;Path=dc1backup;StorageServer=dc1-dd9400-01-backup.lux.eib.org;MediaServer=dc1-bck-srv
      Jul 30, 2022 5:18:27 AM - Info bprd (pid=95544) Searched (1) files of (1) files for Restore Job ID 5042886.xxx
      Jul 30, 2022 5:18:27 AM - Info bprd (pid=95544) Restoring from copy 1 of image created Sat Jul 30 04:17:28 2022 from policy PRD_DC1_SYB
      Jul 30, 2022 5:18:27 AM - Info bpbrm (pid=95567) vmt-sybase-40.lux.eib.org is the host to restore to
      Jul 30, 2022 5:18:27 AM - Info bpbrm (pid=95567) reading file list for client
      Jul 30, 2022 5:18:27 AM - Info bpbrm (pid=95567) listening for client connection
      Jul 30, 2022 5:18:28 AM - Info bpbrm (pid=95567) accepted connection from client
      Jul 30, 2022 5:18:28 AM - Info dbclient (pid=13595) Restore started
      Jul 30, 2022 5:18:28 AM - Info bpbrm (pid=95567) bptm pid: 95571
      Jul 30, 2022 5:18:28 AM - Info bptm (pid=95571) start
      Jul 30, 2022 5:18:28 AM - started process bptm (pid=95571)
      Jul 30, 2022 5:18:28 AM - Info bptm (pid=95571) reading backup image
      Jul 30, 2022 5:18:28 AM - Info bptm (pid=95571) using 512 data buffers
      Jul 30, 2022 5:18:28 AM - Info bptm (pid=95571) spawning a child process
      Jul 30, 2022 5:18:28 AM - Info bptm (pid=95571) child pid: 95575
      Jul 30, 2022 5:18:30 AM - begin reading
      Jul 30, 2022 6:56:03 AM - Info bptm (pid=95571) waited for empty buffer 0 times, delayed 0 times
      Jul 30, 2022 6:56:03 AM - end reading; read time: 1:37:33
      Jul 30, 2022 7:22:44 AM - Info bptm (pid=95571) completed reading backup image
      Jul 30, 2022 7:22:44 AM - Info bptm (pid=95571) EXITING with status 0 <----------
      Jul 30, 2022 7:22:44 AM - Info dbclient (pid=13595) done. status: 0
      Jul 30, 2022 7:22:44 AM - Info dbclient (pid=13595) done. status: 0: the requested operation was successfully completed
      Jul 30, 2022 7:22:44 AM - restored from image vmp-sybase-13_1659147448; restore time: 2:04:18
      Jul 30, 2022 7:22:44 AM - end Restore; elapsed time 2:04:19
      The requested operation was successfully completed.  (0)

      There is no wait for buffers, but again NBU is waiting almost 30min between the two operations. So i'm wondering, what happen between 

      Jul 30, 2022 6:56:03 AM - end reading; read time: 1:37:33

      and

      Jul 30, 2022 7:22:44 AM - Info bptm (pid=95571) completed reading backup image

  • Nicolai's avatar
    Nicolai
    Moderator
    3 years ago

    How big was the previous read image ? If "waited for empty buffers 0 times", it is likely a very small image. It does not explain the long reading time however.

    Try running : 

    vxlogview -p 51216 -X "jobid=5042886" 

    This should report ALL debug messages from the restore job, maybe it gives you a hint.

    /Nicolai

     

    • aprocaccino's avatar
      aprocaccino
      Level 3
      3 years ago

      The size of the file was almost 107Gb.

      The vxlogview command doesn't return anything

      [sybase@vmt-sybase-40 bin]$ ./vxlogview -p 51216 -X "jobid=5042886"
      V-1-1-12 There are no records to be displayed.
      V-1-1-13 NOTE: There were 19 corrupted log records.

      The fact that all jobs now wait around 27min looks like a timeout, but all my values are different than this one.

  • Michal_Mikulik1's avatar
    Michal_Mikulik1
    Moderator
    3 years ago

    Hello,

    what about Sybase end between "end reading" and "completed reading", what is it doing? DB still loading & showing progress, or loading and appearing stucked, or loading completed?

    I think this long interval is rather some logical problem, rather than performance bottleneck.

    Regards

    Michal

     

    • aprocaccino's avatar
      aprocaccino
      Level 3
      3 years ago

      Hello,

      I've increased the bptm logs, and here is what I can see : 

      05:52:22.953 [116733] <2> bp_sts_close_image: close image is done
      05:52:22.953 [116733] <2> wait_for_sigcld: waiting for child to exit, timeout is 3600
      05:52:22.953 [116733] <2> child_wait: waitpid returned zero, no children waiting (../common.c:6279)
      05:52:23.953 [116733] <2> child_wait: waitpid returned zero, no children waiting (../common.c:6279)
      05:52:24.953 [116733] <2> child_wait: waitpid returned zero, no children waiting (../common.c:6279)
      05:52:25.953 [116733] <2> child_wait: waitpid returned zero, no children waiting (../common.c:6279)

      [...]

      06:19:03.522 [116733] <2> child_wait: waitpid returned zero, no children waiting (../common.c:6279)
      06:19:04.522 [116733] <2> child_wait: waitpid returned zero, no children waiting (../common.c:6279)
      06:19:05.188 [116738] <2> get_next_file: [116733] received string: (EXIT STATUS 0)
      06:19:05.189 [116738] <2> terminate_restore: [116733] waited for full buffer 54536 times, delayed 112646 times
      06:19:05.189 [116738] <2> terminate_restore: [116733] sent 1 directories/files to client vmt-sybase-40.lux.eib.org

    • aprocaccino's avatar
      aprocaccino
      Level 3
      3 years ago

      Hello Michal,

      I was waiting for the logs on sybase side.

      Indeed it seems there is still activities during this gap. For example, restore of this morning : 

      Aug 4, 2022 5:18:40 AM - begin reading
      Aug 4, 2022 5:45:56 AM - Info bptm (pid=3617335) waited for empty buffer 8586 times, delayed 20932 times
      Aug 4, 2022 5:45:56 AM - end reading; read time: 0:27:16
      Aug 4, 2022 6:12:08 AM - Info bptm (pid=3617335) completed reading backup image
      Aug 4, 2022 6:12:08 AM - Info bptm (pid=3617335) EXITING with status 0 <----------
      Aug 4, 2022 6:12:08 AM - Info dbclient (pid=3070) done. status: 0
      Aug 4, 2022 6:12:08 AM - Info dbclient (pid=3070) done. status: 0: the requested operation was successfully completed

      And during this time, on the sybase client (2hours of delay must be added):

      2022-08-04T03:18:04.6098290Z 2> LOAD DATABASE trm_test15 from 'sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13'
      2022-08-04T03:18:32.8743106Z Backup Server session id is: 32. Use this value when executing the 'sp_volchanged' system stored procedure after
      2022-08-04T03:18:32.8745127Z fulfilling any volume change request from the Backup Server.
      2022-08-04T03:18:32.8746037Z Backup Server: 4.132.1.1: Attempting to open byte stream device:
      2022-08-04T03:18:32.8749205Z 'sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000'
      2022-08-04T03:18:38.8980706Z Backup Server: 6.28.1.1: Dumpfile name '_prod102221601589' section number 1 mounted on byte stream
      2022-08-04T03:18:38.9022380Z 'sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000'
      2022-08-04T03:18:38.9023774Z Backup Server: 4.166.1.1: Using dbiosize of 2097152 bytes for device
      2022-08-04T03:18:38.9025236Z sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000.
      2022-08-04T03:18:38.9026627Z Backup Server: 4.165.1.1: Using iocount of 12 for device
      2022-08-04T03:18:38.9027882Z sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000.
      2022-08-04T03:18:38.9028829Z Backup Server: 4.166.1.2: Using zonesize of 25165824 bytes for device
      2022-08-04T03:18:38.9030036Z sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000.
      2022-08-04T03:18:38.9031298Z Backup Server: 4.166.1.3: Using blocksize of 65536 bytes for device
      2022-08-04T03:18:38.9032614Z sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000.
      2022-08-04T03:18:38.9033421Z Backup Server: 4.165.1.2: Using numzones of 5 for device
      2022-08-04T03:18:38.9034371Z sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000.
      2022-08-04T03:18:38.9034953Z Backup Server: 4.165.1.3: Using archcnt of 1 for device
      2022-08-04T03:18:38.9035765Z sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000.
      2022-08-04T03:18:38.9036235Z Backup Server: 4.165.1.4: Using dbdevcnt of 14 for device
      2022-08-04T03:18:38.9036932Z sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000.
      2022-08-04T03:18:38.9037445Z Backup Server: 4.166.1.4: Using pagesize of 8192 bytes for device
      2022-08-04T03:18:38.9038217Z sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000.
      2022-08-04T03:19:31.1940819Z Backup Server: 4.188.1.1: Database trm_test15: 13680750 kilobytes (1%) LOADED.
      [...]
      2022-08-04T04:12:05.8806261Z Backup Server: 4.188.1.1: Database trm_test15: 676440966 kilobytes (100%) LOADED.
      2022-08-04T04:12:06.8823719Z Backup Server: 4.125.1.1: Archive API information for
      2022-08-04T04:12:06.8825327Z device='sybackup::SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55 -CLIENT vmp-sybase-13::000': Vendor
      2022-08-04T04:12:06.8826029Z application name='Veritas NetBackup for SYBASE, Library version=910000, Message=Restore is successful
      2022-08-04T04:12:06.8826580Z (SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55).
      2022-08-04T04:12:06.8826917Z Backup Server: 3.42.1.1: LOAD is complete (database trm_test15).
      2022-08-04T04:12:06.9427354Z Started estimating recovery log boundaries for database 'trm_test15'.
      2022-08-04T04:12:07.3882996Z Database 'trm_test15', checkpoint=(50499529, 34), first=(50499529, 34), last=(50512520, 65).
      2022-08-04T04:12:07.3884522Z Completed estimating recovery log boundaries for database 'trm_test15'.
      2022-08-04T04:12:07.3885083Z Started ANALYSIS pass for database 'trm_test15'.
      2022-08-04T04:12:07.4609772Z Completed ANALYSIS pass for database 'trm_test15'.
      2022-08-04T04:12:07.4611188Z Started REDO pass for database 'trm_test15'. The total number of log records to process is 700553.
      2022-08-04T04:12:07.6469553Z Redo pass for database 'trm_test15': 35027 records done (4%); 665526 records left.
      [...]
      2022-08-04T04:12:09.1103611Z Redo pass for database 'trm_test15': 700540 records done (99%); 13 records left.
      2022-08-04T04:12:09.1104315Z Redo pass of recovery has processed 53654 committed and 4714 aborted transactions.
      2022-08-04T04:12:09.1104834Z Completed REDO pass for database 'trm_test15'.
      2022-08-04T04:12:10.1668868Z Use the ONLINE DATABASE command to bring this database online; ASE will not bring it online automatically.
      2022-08-04T04:12:40.7635067Z 1>
      2022-08-04T04:12:40.7635618Z 2> SELECT getdate()
      2022-08-04T04:12:40.7639080Z
      2022-08-04T04:12:40.7640177Z -------------------------------
      2022-08-04T04:12:40.7640449Z Aug 4 2022 6:12AM
      2022-08-04T04:12:40.7640554Z
      2022-08-04T04:12:40.7640993Z (1 row affected)
      2022-08-04T04:12:40.7641155Z 1>
      2022-08-04T04:12:40.7641349Z 2> ONLINE DATABASE trm_test15
      2022-08-04T04:12:40.7694397Z Started estimating recovery log boundaries for database 'trm_test15'.
      2022-08-04T04:12:41.3002027Z Database 'trm_test15', checkpoint=(50499529, 34), first=(50499529, 34), last=(50512520, 65).
      2022-08-04T04:12:41.3002993Z Completed estimating recovery log boundaries for database 'trm_test15'.
      2022-08-04T04:12:41.3003569Z Started ANALYSIS pass for database 'trm_test15'.
      2022-08-04T04:12:41.3710643Z Completed ANALYSIS pass for database 'trm_test15'.
      2022-08-04T04:12:41.3711524Z Recovery of database 'trm_test15' will undo incomplete nested top actions.
      2022-08-04T04:12:44.0326158Z Checking external objects.
      2022-08-04T04:12:44.1044917Z Database 'trm_test15' is now online.
      2022-08-04T04:12:44.1045637Z 1>
      2022-08-04T04:12:44.1046002Z 2> sp_dboption trm_test15, "abort tran on log full", true
      2022-08-04T04:12:44.1401559Z Database option 'abort tran on log full' turned ON for database 'trm_test15'.
      2022-08-04T04:12:44.1418406Z Running CHECKPOINT on database 'trm_test15' for option 'abort tran on log full' to take effect.
      2022-08-04T04:12:44.1489348Z (return status = 0)
      2022-08-04T04:12:44.1489698Z 1>
      2022-08-04T04:12:44.1489954Z 2> sp_dboption trm_test15, "select into", true
      2022-08-04T04:12:44.1555321Z Database option 'select into/bulkcopy/pllsort' turned ON for database 'trm_test15'.
      2022-08-04T04:12:44.1556186Z Running CHECKPOINT on database 'trm_test15' for option 'select into/bulkcopy/pllsort' to take effect.
      2022-08-04T04:12:44.1614243Z (return status = 0)
      2022-08-04T04:12:44.1614446Z 1>
      2022-08-04T04:12:44.1614661Z 2> DUMP TRANSACTION trm_test15 with no_log
      2022-08-04T04:12:46.4717059Z ##[section]Finishing: DB - Load the dump SYB_TRM_PROD10.trm_prod10.D.0.32748.04-08-2022.01:31:55

      I'm waiting confirmation from sybase guy but everything would indicate that it comes from client (and not Netbackup)

  • Michal_Mikulik1's avatar
    Michal_Mikulik1
    Moderator
    3 years ago

    If there is an ongoing Sybase load between  "end reading" and "completed reading", then probably yes.

    Regards

    Michal