Policy Server :: Odbc Delays : it takes time to write to the ODBC Store

Document ID : KB000097332
Last Modified Date : 22/05/2018
Show Technical Document Details
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.