Execution time exceeded threshold Error

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;