Execution time exceeded threshold Error - In 12.8 smps.log
Article ID: 194940
Updated On:
Products
CA Single Sign On Secure Proxy Server (SiteMinder)
CA Single Sign On Agents (SiteMinder)
CA Single Sign On Federation (SiteMinder)
CA Single Sign On SOA Security Manager (SiteMinder)
SITEMINDER
Issue/Introduction
We're running a Policy Server and we see this one reporting the
following message :
Execution time exceeded threshold.
How can we fix that ?
Cause
Enable the full log and traces (Profiler) on the Policy Server to get
the details of the slow transactions and to see what operation is
culprit.
After doing so, it looks like the backend Active Directory User Store
takes time to answer to the Policy Server and this is what delays the
transactions.
smps.log :
[25818/139869457184512][Mon Jun 22 2020
04:47:02][SmAzMapping.cpp:2617][INFO][sm-log-00000] Execution time
exceeded threshold. (CSmAzMapping::SmValLocateUserEntry, 5072, 5000,
agent=samlsp:mysp client= server= resource=/
action=visit user=)
smtracedefault.log>
[][25818][139869457184512][06/22/2020][04:46:57][04:46:57.892][][][]
[Dequeuing a Normal Priority message, from IP 10.0.0.1 with Port
No 54540. Current count is 0][][][][ThreadPool::Run][CServer.cpp:151
4][][][][][][][]
[][25818][139869457184512][06/22/2020][04:46:57][04:46:57.898][][][]
[Starting DsServerCheckerThread][][][][CSmDsLdapConnMgr::StartCheck]
[SmDsLdapConnMgr.cpp:1099][][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:01][04:47:01.899][][][]
[Binding 'dir' connection to LDAP server bank #1: myuserstore
.mydomain.com:636][][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp:
1326][][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.933][][][]
[Binding 'dir' connection to LDAP server bank #1: myuserstore
.mydomain.com:636][][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp:
1326][][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.948][][][]
[Using Active Directory type][][][][SmldapPs_GetDirVersionPrivate][S
mLdapPs.cpp:1660][][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.948][][][]
[Binding 'user' connection to LDAP server bank #1: myuserstore
.mydomain.com:636][][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp
:1456][][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.962][][][]
[Unable to retrieve a UserObjectFilter attribute for UserDirectory
myuserstore][][][][CSmAzUserDirAttributesCache::Add][SmAzUserDirAttr
ibutesCache.cpp:568][][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.962][][][]
[Unable to retrieve a UserObjectClass attribute for UserDirectory
myuserstore][][][][CSmAzUserDirAttributesCache::Add][SmAzUserDirAttri
butesCache.cpp:580][][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.963][][][]
[Searching for 'Property' object with a search key in one domain][][
][][CSmObjProvider::Search][SmObjProvider.cpp:676][][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
[Search failed][][][][CSmObjProvider::Search][SmObjProvider.cpp:717]
[Object Not Found][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
[attr pwdLastSet][][][][AddAttrValue][SmDsLdapProvider.cpp:1758][][]
[][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
[attr lockoutTime][][][][AddAttrValue][SmDsLdapProvider.cpp:1758][][
][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
[attr accountExpires][][][][AddAttrValue][SmDsLdapProvider.cpp:1758]
[][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
[attr userAccountControl][][][][AddAttrValue][SmDsLdapProvider.cpp:1
758][][][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
[attr objectclass][][][][AddAttrValue][SmDsLdapProvider.cpp:1758][][
][][][][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
[Ldap Search callout succeeds.][][][][CSmDsLdapProvider::Search][SmD
sLdapProvider.cpp:2365][][][][][(Search) Retrieving attributes for:
'CN=jsmith,OU=Users,DC=mydomain,DC=com,
DC=com', Filter: 'objectclass=*'. Status: 1 matching objects.][][]
[][25818][139869457184512][06/22/2020][04:47:02][04:47:02.967][][][]
[LogMessage:INFO:[sm-log-00000] Execution time exceeded threshold. (
CSmAzMapping::SmValLocateUserEntry, 5072, 5000, agent=samlsp:mysp
client= server= resource=/ action=visit user=)]
[][][][][SmAzMapping.cpp:2617][][][][][][][]
[s1/r2][25818][139869457184512][06/22/2020][04:47:02][04:47:02.970][
samlsp:mysp][][SiteMinder|Policy Server|myhost
55441|][** Status: Validated. ][][][][CSm_Auth_Message::SendReply][
Sm_Auth_Message.cpp:4902][][][][][][][]
2020-06-29-smtracedefault.log-TransReport.pdf
11.1. Trans : Time Taken :6 sec
__[06/22/2020][04:46:57.920][25818][139868898326272][ Look up a cach
ed object.][][04:46:57][][][][][][][CSmObjCache::Lookup][SmObjCache.
cpp:779][][][][][][][]
__[06/22/2020][04:47:01.930][25818][139868898326272][ Binding 'dir'
connection to LDAP server bank #2: myuserstore:636][][04:47:01][][][]
[][][][CSmDsLdapProvider::InitDir
][SmDsLdapProvider.cpp:1326][][][][][][][]
__[06/22/2020][04:47:02.310][25818][139868898326272][ Processing Att
ribute [Property = SM_AUTHENTICATIONLEVEL] [Trim Property = SM_AUTHE
NTICATIONLEVEL] [Separator =
^]][][04:47:02][][][][][][][GetPropIndex][SmAuthUser.cpp:2295][][][]
[][][][]
__[06/22/2020][04:47:03.316][25818][139868898326272][ Processing Att
ribute [Property = UUID] [Trim Property = UUID] [Separator = ^]][][0
4:47:03][][][][][][][GetPropIndex][SmAuthUser.cpp:2295][][][][][][][]
__[06/22/2020][04:47:03.374][25818][139868898326272][ MyCustom SAML
2.0 Assertion Plugin: Done customizeAssertion][][04:47:03][][][][]
[Done customizeAssertion][][ServerTrace][SmAuthUser.cpp:782][][][][]
[][][]
__[06/22/2020][04:47:04.349][25818][139868898326272][ IsOk? Yes, Ret
urn 0 responses with 1 attributes added.][][04:47:04][][][][][][][CS
mAz::IsOk][SmAuthorization.cpp:1912][][][][][][][]
11.2. Trans : Time Taken :6 sec
__[06/22/2020][04:46:57.921][25818][139869446686464][ Look up a cach
ed object.][][04:46:57][][][][][][][CSmObjCache::Lookup][SmObjCache.
cpp:779][][][][][][][]
__[06/22/2020][04:47:01.966][25818][139869446686464][ Binding 'dir'
connection to LDAP server bank #3: myuserstore:636][][04:47:01][][]
[][][][][CSmDsLdapProvider::InitDir
][SmDsLdapProvider.cpp:1326][][][][][][][]
__[06/22/2020][04:47:02.310][25818][139869446686464][ Processing Att
ribute [Property = SM_AUTHENTICATIONLEVEL] [Trim Property = SM_AUTHE
NTICATIONLEVEL] [Separator =
^]][][04:47:02][][][][][][][GetPropIndex][SmAuthUser.cpp:2295][][][]
[][][][]
__[06/22/2020][04:47:03.317][25818][139869446686464][ Processing Att
ribute [Property = UUID] [Trim Property = UUID] [Separator = ^]][][0
4:47:03][][][][][][][GetPropIndex][SmAuthUser.cpp:2295][][][][][][][]
__[06/22/2020][04:47:03.376][25818][139869446686464][ MyCustom SAML
2.0 Assertion Plugin: Done customizeAssertion][][04:47:03][][][][]
[Done customizeAssertion][][ServerTrace][SmAuthUser.cpp:782][][][][]
[][][]
__[06/22/2020][04:47:04.338][25818][139869446686464][ IsOk? Yes, Ret
urn 0 responses with 1 attributes added.][][04:47:04][][][][][][][CS
mAz::IsOk][SmAuthorization.cpp:1912][][][][][][][]
11.3. Trans : Time Taken :5 sec
__[06/22/2020][04:46:57.937][25818][139869465577216][ Look up a cach
ed object.][][04:46:57][][][][][][][CSmObjCache::Lookup][SmObjCache.
cpp:779][][][][][][][]
__[06/22/2020][04:47:02.044][25818][139869465577216][ Using LDAP ser
ver bank #2][][04:47:02][][][][][][][CSmDsLdapProvider::InitDir][SmD
sLdapProvider.cpp:1523][][][][][][][]
__[06/22/2020][04:47:02.044][25818][139869465577216][ Look up a cach
ed object.][][04:47:02][][][][][][][CSmObjCache::Lookup][SmObjCache.
cpp:779][][][][][][][]
__[06/22/2020][04:47:03.020][25818][139869465577216][ Binding 'dir'
connection to LDAP server bank #4: myuserstore:636][][04:47:03][][][]
[][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp:1326][][][][]
[][][]
1.5. SrcLine Table ProcessRequest
From SmObjCache.cpp:779 - Look up a cached object.
To SmDsLdapProvider.cpp:1523 - Using LDAP server bank #1
av time: 50,493 ms (min: 0 ms, max: 4118 ms),
From SmObjCache.cpp:779 - Look up a cached object.
To SmDsLdapProvider.cpp:1326 - Binding 'dir' connection to LDAP server bank #2: myuserstore.mydomain.com:636
Called 6 Times av time: 2496,167 ms (min: 918 ms, max: 4081 ms),
From SmDsLdapConnMgr.cpp:1099 - Starting DsServerCheckerThread
To SmDsLdapProvider.cpp:1326 - Binding 'dir' connection to LDAP server bank #1: myuserstore.mydomain.com:636
Called 2 Times av time: 2501,000 ms (min: 1001 ms, max: 4001 ms),
p. 4 - 5
Environment
Policy Server 12.8SP3 on RedHat 6;
User Directory on Active Directory;
Resolution
- Investigate the Active Directory performances;
Feedback
Yes
No
Powered by
