Running the Policy Server traces analyser, we discovered that when the
Normal Queue is piling up, the Policy Server has problem to handle the
DB queue. In this sample, it takes 10 seconds to process a single ODBC
request :
TransReport.pdf
The execution of the ODBC statement starts at 15:59:28.148
[04/24/2016][15:59:28.148][26911][73][ Executing statement'']
[15:59:28][SmDsOdbcProvider.cpp:987][SmDsOdbcProvider::Search][][][][][][]
[][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]
[][][][][][][select ATTR1,ATTR2,ATTR3,NAME,USER_ID from SM_USERS_VIEW where
Name=? and DOMAIN='MYDOMAIN']
[][][][][][][][]
[04/24/2016][15:59:28.148][26911][73][ Enter function CSmDbServerSession::GetConnection]
[15:59:28][CSmDbServerSession.cpp:347][CSmDbServerSession::GetConnection][][][][][][]
[][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]
[][][][][][][][][][]
[04/24/2016][15:59:28.148][26911][73][ Report connections status for data source
'mydatasource' and user 'myadmin'][15:59:28][CSmDbServerSession.cpp:594]
[CSmDbServerSession::GetConnection][][][][][][][][][][][][][][][][][][][]
[50 connections, 49 active with 49 sessions, 0 available, 0 hung, 1 starting.][][][][][]
[][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]
[04/24/2016][15:59:28.148][26911][73][ Leave function CSmDbServerSession::GetConnection]
[15:59:28][CSmDbServerSession.cpp:622][CSmDbServerSession::GetConnection][][][][][][][][][][][][][-
1024][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]
[][][00:00:00.000481][]
And here it takes to 10 seconds to process the Queued Request :
[04/24/2016][15:59:28.165][26911][73][ Queueing request.][15:59:28]
[CSmDbUtilities.cpp:862][CSmDbWaiter::Wait][][][][][][][][][][][]
[][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]
[04/24/2016][15:59:28.165][26911][73][ Waiting for Queued Request.][15:59:28]
[CSmDbUtilities.cpp:878][CSmDbWaiter::Wait][][][][][][][][][][][][][][][][][][][][][][][][][]
[][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]
[04/24/2016][15:59:38.745][26911][73][ Queued request completed successfully.][15:59:38]
[CSmDbUtilities.cpp:898][CSmDbWaiter::Wait][][][][][][][][][][][][][][][][][][][][][][][][][]
[][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]
How can we solve this and avoid those delays ?
The cause of this behavior is that the traces are printed very regularly
during the DB connection processing, and these ones are under Lock synchronization,
which lead to delays.
We modified the code to move the traces out from Lock() section.
We modified also the tracing component from Internal to
SmOdbcComponent::Monitor so that only needed critical info can be
traced.