2149226 - The elapsed time of an rpc handled by cis can sometimes equal the configured value of 'cis connect timeout' - ASE 15.0.3

• The config parameter 'cis connection timeout' is increased to a high value it will intermittently cause an increase in the elapsed time for an RPC to complete equal to  the value of the config parameter.
• For example:  'cis connect timeout' is set to 10 the elapsed time for a cis handled rpc will be 10 seconds, if set to 100 the elapsed time will be 100.
• This occurs for RPCs where the  source and target releases are 15.0.3 are both on the Aix p6 or p7 platform.  Delays of 13, 15,19,25 and 29 seconds that correspond to the config value for 'cis connect timeout'

   Cis connect timeout                     Start                                              End                         Elapsed time

------------------------------------------------------------------------------------------------------------------------------

           1                          Mar 13 2015  5:56:51:783PM     Mar 13 2015  5:56:52:350PM               0
           2                          Mar 13 2015  5:56:56:400PM     Mar 13 2015  5:56:56:936PM               0
           3                          Mar 13 2015  5:57:00:253PM     Mar 13 2015  5:57:00:820PM               0
           4                          Mar 13 2015  5:57:04:333PM     Mar 13 2015  5:57:04:846PM               0
           5                          Mar 13 2015  5:57:08:596PM     Mar 13 2015  5:57:09:126PM               0
           6                          Mar 13 2015  5:57:12:446PM     Mar 13 2015  5:57:12:973PM               0
           7                          Mar 13 2015  5:57:16:446PM     Mar 13 2015  5:57:16:983PM               0
           8                          Mar 13 2015  5:57:20:433PM     Mar 13 2015  5:57:20:963PM               0
           9                          Mar 13 2015  5:57:24:436PM     Mar 13 2015  5:57:24:983PM               0
          10                         Mar 13 2015  5:57:28:670PM     Mar 13 2015  5:57:29:206PM               0
          11                         Mar 13 2015  5:57:32:656PM     Mar 13 2015  5:57:33:163PM               0
          12                         Mar 13 2015  5:57:36:640PM     Mar 13 2015  5:57:37:183PM               0
          13                         Mar 13 2015  5:57:40:710PM     Mar 13 2015  5:57:54:130PM              13
          14                         Mar 13 2015  5:57:57:740PM     Mar 13 2015  5:57:58:270PM               0
          15                         Mar 13 2015  5:58:01:540PM     Mar 13 2015  5:58:17:030PM              15
          16                         Mar 13 2015  5:58:20:490PM     Mar 13 2015  5:58:21:016PM               0
          17                         Mar 13 2015  5:58:24:513PM     Mar 13 2015  5:58:25:040PM               0
          18                         Mar 13 2015  5:58:28:516PM     Mar 13 2015  5:58:29:060PM               0
          19                         Mar 13 2015  5:58:32:523PM     Mar 13 2015  5:58:52:066PM              19
          20                         Mar 13 2015  5:58:55:896PM     Mar 13 2015  5:58:56:550PM               0
          21                         Mar 13 2015  5:59:00:186PM     Mar 13 2015  5:59:00:746PM               0
          22                         Mar 13 2015  5:59:04:493PM     Mar 13 2015  5:59:05:006PM               0
          23                         Mar 13 2015  5:59:08:516PM     Mar 13 2015  5:59:09:033PM               0
          24                         Mar 13 2015  5:59:12:676PM     Mar 13 2015  5:59:13:220PM               0
          25                         Mar 13 2015  5:59:17:296PM     Mar 13 2015  5:59:42:790PM              25
          26                         Mar 13 2015  5:59:46:483PM     Mar 13 2015  5:59:47:033PM               0
          27                         Mar 13 2015  5:59:50:670PM     Mar 13 2015  5:59:51:183PM               0
          28                         Mar 13 2015  5:59:54:523PM     Mar 13 2015  5:59:55:056PM               0
          29                         Mar 13 2015  5:59:58:906PM     Mar 13 2015  6:00:28:430PM              29
          30                         Mar 13 2015  6:00:32:203PM     Mar 13 2015  6:00:32:750PM               0

• Wait times as seen from the local and remote server while the delay is occurring

Wait event 171 (waiting for ctlib to complete) increases on the local side.

 select * from monProcessWaits where SPID=31
 go

 SPID   KPID        ServerUserID WaitEventID Waits       WaitTime
 ------ ----------- ------------ ----------- ----------- -----------
     31    13959228            1          31           1           0
     31    13959228            1         171           1       74600
     31    13959228            1         214           2           0
     31    13959228            1         250           4           0

(4 rows affected)

 select * from monProcessWaits where SPID=31
 go

 SPID   KPID        ServerUserID WaitEventID Waits       WaitTime
 ------ ----------- ------------ ----------- ----------- -----------
     31    13959228            1          31           1           0
     31    13959228            1         171           1       86700
     31    13959228            1         214           2           0
     31    13959228            1         250           4           0

(4 rows affected)

 select * from monProcessWaits where SPID=31
 go

 SPID   KPID        ServerUserID WaitEventID Waits       WaitTime
 ------ ----------- ------------ ----------- ----------- -----------
     31    13959228            1          31           1           0
     31    13959228            1         171           1       97900
     31    13959228            1         214           2           0
     31    13959228            1         250           4           0

• On the remote side Wait 250 (awaiting command) increases for the remote process.

 select * from monProcessWaits where SPID=27
 go

 SPID        InstanceID KPID        ServerUserID WaitEventID Waits
         WaitTime
 ----------- ---------- ----------- ------------ ----------- -----------
         -----------
          27          0    25886761            1          31           1
                   4
          27          0    25886761            1         250           2
               64510

(2 rows affected)

 select * from monProcessWaits where SPID=27
 go

 SPID        InstanceID KPID        ServerUserID WaitEventID Waits
         WaitTime
 ----------- ---------- ----------- ------------ ----------- -----------
         -----------
          27          0    25886761            1          31           1
                   4
          27          0    25886761            1         250           2
               80942

(2 rows affected)

 select * from monProcessWaits where SPID=27
 go

 SPID        InstanceID KPID        ServerUserID WaitEventID Waits
         WaitTime
 ----------- ---------- ----------- ------------ ----------- -----------
         -----------
          27          0    25886761            1          31           1
                   4
          27          0    25886761            1         250           2
               91332

(2 rows affected)

• Sybase Adaptive Server Enterprise (ASE) 15.0.3
• Sybase Adaptive Server Enterprise (ASE) 15.5
• AIX (6.1) 
• AIX (7.1)

elapsed time, rpc , KBA , omni , BC-SYB-ASE , Sybase ASE Database Platform (non Business Suite) , Problem