Symantec Access Management

Tech Tip : CA Single Sign-On : Policy Server :: Odbc Delays : it takes time to write to the ODBC Store

  • 1.  Tech Tip : CA Single Sign-On : Policy Server :: Odbc Delays : it takes time to write to the ODBC Store

    Broadcom Employee
    Posted May 22, 2018 03:58 AM

    Issue:


    We see the Policy Server taking almost 1 second to write the data in
    the Session Store.

     

    FWSTrace.log

     

    [02/15/2018][05:53:46][20196][2209453824][244a3dbe-1d0b7b94-c3e35038-7bec437a-86d63dfd-a24][FWSBase.java][authenticateUser][Passing response message through login call [CHECKPOINT = SSO_RESPONSEMESSAGEINLOGIN_REQ]] 

     

    [02/15/2018][05:53:48][20196][2209453824][244a3dbe-1d0b7b94-c3e35038-7bec437a-86d63dfd-a24][FWSBase.java][authenticateUser][result code from AgentAPI login call: 1]

     

     

    smtracedefault.log

     

     

    The Policy Server handle the request, process SmAuthLimit module
    within less than 100 msecs :

     

    [02/15/2018][05:53:47.263][05:53:47][21892][3649657744][SmAuthorization.cpp:1748][CSmAz::IsOk][][][][][][][][][onauthaccept][][][][][][][][][][][][Policy is applicable. Rule is applicable. Get Responses.][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:47.265][05:53:47][21892][3649657744][SmAuthUser.cpp:700][ServerTrace][][][][][][][][][][][][][][][][][][][][Starting.][SmLimitAuthLogin: Starting.][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:47.267][05:53:47][21892][3649657744][SmDsUser.cpp:647][CSmDsUser::SetProp][][][][][][][][][][][][][][][][][][][PropName 'smlimitauth' for user 'uid=jsmith,dc=trainig,dc=com' in dir 'myldapdir'][][Start of call SetUserProp.][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:47.278][05:53:47][21892][3649657744][SmAuthUser.cpp:700][ServerTrace][][][][][][][][][][][][][][][][][][][][About to flush the cache for uid=jsmith,dc=trainig,dc=com][SmLimitAuthLogin: About to flush the cache for uid=jsmith,dc=trainig,dc=com][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:47.282][05:53:47][21892][3649657744][smldaputils.cpp:1849][SmAddLDAP][][][][][][][][][][][][][][][][][][][Handle='0xdd80af0', DN='smAgentCommandOID4=14-00044662-206b-1a85-aa18-48440a42f028, ou=PolicySvr4,ou=SiteMinder,ou=Netegrity,o=mypstore'][][Start of call ldap_add_s:Add LDAP.][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:47.293][05:53:47][21892][3649657744][SmAuthUser.cpp:700][ServerTrace][][][][][][][][][][][][][][][][][][][][Flushed User Cache.][SmLimitAuthLogin: Flushed User Cache.][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:47.294][05:53:47][21892][3649657744][SmActiveExpr.cpp:995][CSmActiveExprLibrary::GetActiveValue][][][][][][][][][][][][Active Expression GetActiveAttr;SmLimitAuth;Login;smlimitauth returned NULL][][][][][][][][][Leave function CSmActiveExprLibrary::GetActiveValue][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:47.294][05:53:47][21892][3649657744][SmAuthorization.cpp:2333][CSmAz::IsOkGlobal][][][][][][][][][][][][][][][][][][][][][Evaluating OnAuthAccept global policies in the realm.][][][][][][uid=jsmith,dc=trainig,dc=com][][][][][][][][][OnAuthAccept]

     

    But at time to write data into the DB Session Store, then it adds
    almost 1 second to the processing :

     

    [02/15/2018][05:53:47.295][05:53:47][21892][3649657744][Sm_Auth_Message.cpp:4281][CSm_Auth_Message::SetAuthContext][][][][][][][][][][][][][][][][][][][][][Leave function CSm_Auth_Message::SetAuthContext][][][][][][][][][][][][][][00:00:00.035525][]

     

    [02/15/2018][05:53:47.297][05:53:47][21892][3649657744][CSmDbODBC.cpp:2587][CSmDbConnectionODBC::ExecuteSQL][][][][][][][][][][][][][][][][][][][][][Allocated statement handle 507481248 on session 421423328.][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:47.458][05:53:47][21892][3649657744][CSmDbServerSession.cpp:594][CSmDbServerSession::GetConnection][][][][][][][][][][][][][][][][][][][][32 connections, 4 active with 4 sessions, 28 available, 0 hung, 0 starting.][Report connections status for data source 'Session Data Source' and user 'myuser'][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:47.771][05:53:47][21892][3649657744][SmSSProvider.cpp:898][CSmSSProvider::SetVariable][][][][][][][][][][][][][][0][][][][][][][Leave function CSmSSProvider::SetVariable][][][][][][][WbTKXdsadas7KqxZ6enNxZgmUDqUs6I/w=][][][][][][][][]

     

    [02/15/2018][05:53:48.002][05:53:48][21892][3649657744][SmSSProvider.cpp:898][CSmSSProvider::SetVariable][][][][][][][][][][][][][][0][][][][][][][Leave function CSmSSProvider::SetVariable][][][][][][][WbTKXdsadas7KqxZ6enNxZgmUDqUs6I/w=][][][][][][][][]

     

    then it ends the transaction :

     

     

    [02/15/2018][05:53:48.002][05:53:48][21892][3649657744][Sm_Auth_Message.cpp:101][][][][][][][][][][][][][][][][][][][][][Cleaning up][SmSamlDataContext::~SmSamlDataContext: Cleaning up][][][][][][][][][][][][][][][]

     

    [02/15/2018][05:53:48.006][05:53:48][21892][3649657744][Sm_Auth_Message.cpp:4630][CSm_Auth_Message::SendReply][s1244/r109][][][][][][][][][][][][][][][][][][][][** Status: Authenticated. ][][][][][][uid=jsmith,dc=trainig,dc=com][][][][][][][][][]

     

    [02/15/2018][05:53:48.008][05:53:48][21892][3649657744][CServer.cpp:5891][CServer::ProcessRequest][][][][][][][][][][][][][][3481][][][][][][][Leave function CServer::ProcessRequest][][][][][][][][][][][][][][00:00:01.045298][]

     

     

    How can we solve this ?

     

    Cause:

     

    The Policy Server at 02/15/2018 05:53:47 does many operations on the
    ODBC Session Store. If we look at this second, 58 threads handle ODBC
    connections. We counted more than 5000 lines during that second
    including key word "CSmDbConnection" from

    smtracedefault.log.

     

    The Policy Server code before 12.52SP1CR06 writes logs in the code
    portion where the DB connection processing is under Lock
    synchronization. This leads to delays in processing the SQL
    statement. And this reflects what we've seen in the sample from your
    logs. SQL statement gets delayed.

     

    DE166084 Performance issues were observed in Policy Server during
    the DB connection processing requests.

     

    https://docops.ca.com/ca-single-sign-on/12-52-sp1/en/release-notes/cumulative-releases/defects-fixed-in-12-52-sp1-cr06#DefectsFixedin12.52SP1CR06-PolicyServer

     

     

    As such, you'll need to apply the CR08, which is the latest CR for
    12.52SP1 series in order to benefit from this fix.

    Resolution:

     

    Upgrade Policy Server to 12.52SP1CR06 or above to fix this issue.


    KB : KB000097332