Execution time exceeded threshold errors in Policy Server
Article ID: 274175
Updated On:
Products
SITEMINDER
Issue/Introduction
When running a Policy Server, the smps.log file reports the error:
"Execution time exceeded threshold"
The following functions taking reported as taking time:
| Function | Time | Treashold |
|---------------------------------------+-------+-----------|
| CSm_Auth_Message::LookUpUserInDir | 18740 | 5000 |
| CSm_Auth_Message::ValidateUser | 18747 | 5000 |
| CSm_Auth_Message::ProcessAgentMessage | 18747 | 5000 |
| CSm_Auth_Message::ProcessMessage | 18747 | 5000 |
| CServer::ProcessRequest | 18748 | 5000 |
| CSmAuthUser::AuthenticateUserDir | 8407 | 5000 |
| CSmAz::Process_Response_List | 5738 | 5000 |
| CSmAz::IsOk | 5738 | 5000 |
| CSm_Auth_Message::SetAuthContext | 5741 | 5000 |
| CSm_Auth_Message::AuthenticateUser | 14149 | 5000 |
| CSm_Auth_Message::ProcessAgentMessage | 14149 | 5000 |
| CSm_Auth_Message::AuthenticateUser | 6485 | 5000 |
Resolution
The sm.registry can be used to adjust the time considered a transaction takes time as related (1), the default being 5 seconds.
Very often, a single cause can provoke alerts on many functions above.
The reason is the Policy Server, when handling a transaction, goes through many functions that are nested.
Let's take a look at 1 transaction from smtracedefault.log.
PID 015954 and Thread 139929547953920 takes more than 8 seconds to execute.
The Policy Server traces report those stats:
| Function | Time | Treashold |
|---------------------------------------+------+-----------|
| CServer::ProcessRequest | 8576 | 5000 |
| CSm_Auth_Message::ProcessMessage | 8576 | 5000 |
| CSm_Auth_Message::ProcessAgentMessage | 8576 | 5000 |
| CSm_Auth_Message::AuthenticateUser | 8575 | 5000 |
| CSmAuthUser::AuthenticateUserDir | 8571 | 5000 |
Let's take a look at each of these functions.
They are all related to an LDAP call for which the backend server takes time to reply:
smtracedefault.log:
[09/13/2023][10:05:57.029][15954][139929547953920][Enter function CServer::ProcessRequest][10:05:57][CServer.cpp:6186][CServer::ProcessRequest]
[09/13/2023][10:05:57.029][15954][139929547953920][ Enter function CSm_Auth_Message::ProcessMessage][10:05:57][Sm_Auth_Message.cpp:497][CSm_Auth_Message::ProcessMessage]
[09/13/2023][10:05:57.029][15954][139929547953920][ Enter function CSm_Auth_Message::ProcessAgentMessage][10:05:57][AgentAuth.cpp:38][CSm_Auth_Message::ProcessAgentMessage]
[09/13/2023][10:05:57.030][15954][139929547953920][ Enter function CSm_Auth_Message::AuthenticateUser][10:05:57][Sm_Auth_Message.cpp:748][CSm_Auth_Message::AuthenticateUser]
[09/13/2023][10:05:57.030][15954][139929547953920][ Enter function CSmAuthUser::AuthenticateUserDir][10:05:57][SmAuthUser.cpp:4025][CSmAuthUser::AuthenticateUserDir]
The problem with an LDAP search that takes longer than 5 seconds to execute:
[09/13/2023][10:05:57.030][15954][139929547953920][ search filter is : (uid=<user>)][10:05:57][SmDsLdapProvider.cpp:1906][CSmDsLdapProvider::SearchImpl]
[09/13/2023][10:06:03.018][15954][139929547953920][ LDAP search of (uid=<user>) took 5 seconds and 987536 microseconds][10:06:03][SmDsLdapConnMgr.cpp:1212][CSmDsLdapConn::SearchExts]
And an additional 2 seconds are added to the transaction as the ACE back-end server takes more than 2 seconds to reply:
[09/13/2023][10:06:03.304][15954][139929547953920][ AceInit successful.][10:06:03][SmAuthAceHtml.cpp:1096][SmAuthenticate][][][][<User>][][][][][][][][][][][][][][][][][][][][][][][][SmAuthAceHtml]
[09/13/2023][10:06:05.601][15954][139929547953920][ Leave function SmAuthenticate][10:06:05][SmAuthAceHtml.cpp:1121][SmAuthenticate][][][][][][][][][][][][][Sm_AuthApi_Accept]
Then, many functions will report taking a long time (over 8 seconds):
[09/13/2023][10:06:05.602][15954][139929547953920][ LogMessage:INFO:[sm-log-00000] Execution time exceeded threshold. (CSmAuthUser::AuthenticateUserDir, 8571, 5000, agent=agent client=10.0.0.1 server=https://server.example.com resource=/<application>/ action=GET user=<user>)][10:06:05][SmAuthUser.cpp:5206]
[09/13/2023][10:06:05.605][15954][139929547953920][ LogMessage:INFO:[sm-log-00000] Execution time exceeded threshold. (CSm_Auth_Message::AuthenticateUser, 8575, 5000, agent=agent client=10.0.0.1 server=https://server.example.com resource=/<application>/ action=GET user=<user>)][10:06:05][Sm_Auth_Message.cpp:1968]
[09/13/2023][10:06:05.606][15954][139929547953920][ LogMessage:INFO:[sm-log-00000] Execution time exceeded threshold. (CSm_Auth_Message::ProcessAgentMessage, 8576, 5000, agent=agent client=10.0.0.1 server=https://server.example.com resource=/<application>/ action=GET user=<user>)][10:06:05][AgentAuth.cpp:321]
[09/13/2023][10:06:05.606][15954][139929547953920][ LogMessage:INFO:[sm-log-00000] Execution time exceeded threshold. (CSm_Auth_Message::ProcessMessage, 8576, 5000, agent=agent client=10.0.0.1 server=https://server.example.com resource=/<application>/ action=GET user=<user>)][10:06:05][Sm_Auth_Message.cpp:510]
[09/13/2023][10:06:05.606][15954][139929547953920][ LogMessage:INFO:[sm-log-00000] Execution time exceeded threshold. (CServer::ProcessRequest, 8576, 5000, agent=agent client=10.0.0.1 server=https://server.example.com resource=/<application>/ action=GET user=<user>)][10:06:05][CServer.cpp:6372]
Additional Information
Feedback
Yes
No
Powered by
