We have a native C++ COM application for controlling our production lines. The application is using ADO to access a MS SQL server. Server part of application is ruing on Windows Server 2003 and Clients XP. Recently we switched from SQL SERVER 2005 to SQL SERVER 2012 (but database remaining in 2005 compatibility modus). The migration was quite smooth (just 1/2 downtime). Old server and clients are in same domain, new server is in a different domain (of course trusted). Authentication is done by SQL Server authentication. However now i got complaints about a sporadic performance degration on a specific action on a packaging client station. By putting some debug output into the code, i could find the involved code and this code executes a "select count(*) from TableX where col = ?" query (not prepared). The table has max. of some thousand entries and where column is indexed. Isolation level is committed read. Blocking should not be an issue because there are only updates and inserts of single lines. But even mass updates should not be an issue with some thousand rows.
This query performs in milliseconds most of the time but sometimes it needs around 10 seconds. Here is the code block used to execute SQL statements.
HRESULT CCxADORecordset::OpenSQL(CString strSQL, CursorTypeEnum eCursorType, LockTypeEnum eLockType)
{
HRESULT hr = S_OK;
CCxDataLogger dataLogger("CxDBServerLib");
CString strDebug;
strDebug.Format("CCxADORecordset::OpenSQL2: BeforeGetRecordSet (%s)n", strSQL);
OutputDebugString(strDebug);
SET_SUCC_HR(hr, GetRecordset());
COleVariant varSQL(strSQL);
bool fFinished = false;
long lRetryCount = 1;
do
{
OutputDebugString("CCxADORecordset::OpenSQL2: BeforeOpe");
SET_SUCC_HR(hr, m_pIRecordset->Open(varSQL, g_varEmpty, eCursorType, eLockType, adCmdText));
OutputDebugString("CCxADORecordset::OpenSQL2: BeforeGetExecuteRetryn");
LockType and CursorType could be configured by registry entries and are set to adLockOptimistic and adOpenKeyset.
This is some sample debug output
01308272 13:46:24.701 [2964] CCxADORecordset::OpenSQL: BeforeGetDefaultCursorType
01308273 13:46:24.701 [2964] CCxADORecordset::OpenSQL: BeforeGetDefaultLockType
01308274 13:46:24.701 [2964] CCxADORecordset::OpenSQL: BeforeOpenSQL2
01308275 13:46:24.701 [2964] CCxADORecordset::OpenSQL2: BeforeGetRecordSet (SELECT Count(*) As lCount FROM ProdArtikel WHERE lWTNr = -2)
01308276 13:46:24.701 [2964] CCxADORecordset::OpenSQL2: BeforeOpen
01308277 13:46:33.717 [2964] CCxADORecordset::OpenSQL2: BeforeGetExecuteRetry
01308278 13:46:33.717 [2964] CCxADORecordset::OpenSQL2: AfterGetExecuteRetry
01308279 13:46:33.717 [2964] CCxADORecordset::OpenSQL: AfterOpenSQL2
01308280 13:46:33.717 [2964] CommonHelper::isWTEmpty() Before getFieldValue
01308281 13:46:33.717 [2964] CommonHelper::isWTEmpty() Before Close
and only milliseconds later
01308300 13:46:33.732 [2964] CCxADORecordset::OpenSQL: BeforeGetDefaultCursorType
01308301 13:46:33.732 [2964] CCxADORecordset::OpenSQL: BeforeGetDefaultLockType
01308302 13:46:33.732 [2964] CCxADORecordset::OpenSQL: BeforeOpenSQL2
01308303 13:46:33.732 [2964] CCxADORecordset::OpenSQL2: BeforeGetRecordSet (SELECT Count(*) As lCount FROM ProdArtikel WHERE lWTNr = -2)
01308304 13:46:33.732 [2964] CCxADORecordset::OpenSQL2: BeforeOpen
01308305 13:46:33.748 [2964] CCxADORecordset::OpenSQL2: BeforeGetExecuteRetry
01308306 13:46:33.748 [2964] CCxADORecordset::OpenSQL2: AfterGetExecuteRetry
01308307 13:46:33.748 [2964] CCxADORecordset::OpenSQL: AfterOpenSQL2
01308308 13:46:33.748 [2964] CommonHelper::isWTEmpty() Before getFieldValue
01308309 13:46:33.748 [2964] CommonHelper::isWTEmpty() Before Close
It seems to only this query having the performance issues sometimes.
I activated the snapshot isolation level for the database which didn't help.I activated SQL server extended events (with blocked process treshold set to 5 seconds) to produce a blocked process report. It didn't create any output.
I run SQL Server trace. It shows the same SQL execution time of 0 ms for both the first and second execution of the statement.
SQL:BatchStarting SELECT Count(*) As lCount FROM ProdArtikel WHERE lWTNr = -2 CxFrame 2964 DEL10 sigma 256 2016-04-28 13:46:25.697 LINIE10-4 16 22078966 1 0XAF4C8D9B17C7A24FB9D948FA565A9898 0 ZDELINESQL2DEPRODUCTION sigma 0
SQL:StmtCompleted 0 2016-04-28 13:46:25.697 SELECT Count(*) As lCount FROM ProdArtikel WHERE lWTNr = -2 CxFrame 0 2964 DEL10 sigma 2 256 2016-04-28 13:46:25.697 0 LINIE10-4
SQL:BatchCompleted 0 2016-04-28 13:46:25.697 SELECT Count(*) As lCount FROM ProdArtikel WHERE lWTNr = -2 CxFrame 0 2964 DEL10 sigma 2 256 2016-04-28 13:46:25.697 0 LINIE10-4 16 0 - OK 22078967 1 0XAF4C8D9B17C7A24FB9D948FA565A9898 0 1 ZDELINESQL2DEPRODUCTION sigma 0
SQL:BatchStarting SELECT Count(*) As lCount FROM ProdArtikel WHERE lWTNr = -2 CxFrame 2964 DEL10 sigma 256 2016-04-28 13:46:34.743 LINIE10-4 16 22079361 1 0XAF4C8D9B17C7A24FB9D948FA565A9898 0 ZDELINESQL2DEPRODUCTION sigma 0
SQL:StmtCompleted 0 2016-04-28 13:46:34.747 SELECT Count(*) As lCount FROM ProdArtikel WHERE lWTNr = -2 CxFrame 0 2964 DEL10 sigma 2 256 2016-04-28 13:46:34.747 0 LINIE10-4
SQL:BatchCompleted 0 2016-04-28 13:46:34.743 SELECT Count(*) As lCount FROM ProdArtikel WHERE lWTNr = -2 CxFrame 0 2964 DEL10 sigma 2 256 2016-04-28 13:46:34.743 0 LINIE10-4 16 0 - OK 22079362 1 0XAF4C8D9B17C7A24FB9D948FA565A9898 0 1 ZDELINESQL2DEPRODUCTION sigma 0
I'm out of my possibilities now. I doesn't know what to do. I can't change back to SQL SERVER 2005 of course. I don't suspect netwerk issues because clients didn't change and the new SERVER is also located in the same datacenter as the old one. Both old and new server are virtualized on VMWare.
What can i do? The users live now about 6 weeks with this problems (very patient). Can i further debug the ->Open ADO call? Will a network monitor help? Please suggest?
Greetings, Jörg