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