timeouts on SQLServer with SQLTrace_Lock

Question

Post reply

timeouts on SQLServer with SQLTrace_Lock

Pyman

SSChampion

Points: 13830
More actions
November 10, 2011 at 10:37 am

#246044

The system has encountered difficulty:

SQL Command Failed; SQL = gw_LookupURI

---------------------------------------

This message originates

in FillDataSetFromStoredProc(),

in the w3wp process on the server

WEBSERVER:

AppDomain = /LM/W3SVC/4/ROOT/EZMed-1-129652918758885483

---------------------------------------

System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.

at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)

at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)

at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)

at System.Data.SqlClient.TdsParserStateObject.ReadSni(DbAsyncResult asyncResult, TdsParserStateObject stateObj)

at System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket()

at System.Data.SqlClient.TdsParserStateObject.ReadBuffer()

at System.Data.SqlClient.TdsParserStateObject.ReadByte()

at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)

at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()

at System.Data.SqlClient.SqlDataReader.get_MetaData()

at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)

at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)

at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)

at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)

at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)

at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)

at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader(CommandBehavior behavior)

at System.Data.Common.DbDataAdapter.FillInternal(DataSet dataset, DataTable[] datatables, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)

at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)

at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet)

at company.OnDemand.Data.DBBaseUtils.FillDataSetFromStoredProc(String sql, String[] parameterNames, Object[] parameterValues, DataSet ds) in C:\Company Source\SageOnDemand\EzMedASP\SystemClassLibraries\DataLib\DBBaseUtils.cs:line 753

The above SQLTimeout is happening when the WEBServer is making call to a storedproc. Since I don’t know when this error occurs I am using a monitor table that logs all the events happening on the databases for every 1 minute. When I query this monitor table at that time I see the waittype as sqltrace_lock with a wait time around 600.

I need your valuable inputs. Thanks a ton in advance.

“If your actions inspire others to dream more, learn more, do more and become more, you are a leader.” -- John Quincy Adams

Viewing 7 posts - 1 through 6 (of 6 total)

You must be logged in to reply to this topic. Login to reply

Jared SSC Guru Points: 61793 More actions · Answer 1

Sapen (11/10/2011)

The system has encountered difficulty:

SQL Command Failed; SQL = gw_LookupURI

---------------------------------------

This message originates

in FillDataSetFromStoredProc(),

in the w3wp process on the server

WEBSERVER:

AppDomain = /LM/W3SVC/4/ROOT/EZMed-1-129652918758885483

---------------------------------------

System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.

at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)

at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)

at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)

at System.Data.SqlClient.TdsParserStateObject.ReadSni(DbAsyncResult asyncResult, TdsParserStateObject stateObj)

at System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket()

at System.Data.SqlClient.TdsParserStateObject.ReadBuffer()

at System.Data.SqlClient.TdsParserStateObject.ReadByte()

at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)

at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()

at System.Data.SqlClient.SqlDataReader.get_MetaData()

at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)

at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)

at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)

at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)

at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)

at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)

at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader(CommandBehavior behavior)

at System.Data.Common.DbDataAdapter.FillInternal(DataSet dataset, DataTable[] datatables, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)

at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)

at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet)

at company.OnDemand.Data.DBBaseUtils.FillDataSetFromStoredProc(String sql, String[] parameterNames, Object[] parameterValues, DataSet ds) in C:\Company Source\SageOnDemand\EzMedASP\SystemClassLibraries\DataLib\DBBaseUtils.cs:line 753

The above SQLTimeout is happening when the WEBServer is making call to a storedproc. Since I don’t know when this error occurs I am using a monitor table that logs all the events happening on the databases for every 1 minute. When I query this monitor table at that time I see the waittype as sqltrace_lock with a wait time around 600.

I need your valuable inputs. Thanks a ton in advance.

How are you writing to this monitor table? Via a trace? (That's where your lock is coming from I believe) Have you tried looking at the sp gw_LookupURI to see what is wrong with it?

Thanks,

Jared

Jared
CE - Microsoft

Pyman SSChampion Points: 13830 More actions · Answer 2

Its not a trace but a job that inserts into the monitor table. Infact, I created this table and the job just to track the cause for this timeout error. I have the below script in my job and I have scheduled it to run every minute.



Insert into my monitor_table

SELECT T.text, P.query_plan, S.host_name, S.program_name, S.client_interface_name, S.login_name, R.*

FROM sys.dm_exec_requests R

JOIN sys.dm_exec_sessions S on S.session_id=R.session_id

CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS T

CROSS APPLY sys.dm_exec_query_plan(plan_handle) As P

GO

Yes that's the sp "gw_LookupURI". It was in place for a very long time. And I am experiencing these errors very recently. The developers claim that this proc will run very frequently. So they want to know why only in certain times are we seeing these timeouts which never even occured in the past.

“If your actions inspire others to dream more, learn more, do more and become more, you are a leader.” -- John Quincy Adams

Jared SSC Guru Points: 61793 More actions · Answer 3

Sapen (11/10/2011)

Its not a trace but a job that inserts into the monitor table. Infact, I created this table and the job just to track the cause for this timeout error. I have the below script in my job and I have scheduled it to run every minute.

Insert into my monitor_table SELECT T.text, P.query_plan, S.host_name, S.program_name, S.client_interface_name, S.login_name, R.* FROM sys.dm_exec_requests R JOIN sys.dm_exec_sessions S on S.session_id=R.session_id CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS T CROSS APPLY sys.dm_exec_query_plan(plan_handle) As P GO

Yes that's the sp "gw_LookupURI". It was in place for a very long time. And I am experiencing these errors very recently. The developers claim that this proc will run very frequently. So they want to know why only in certain times are we seeing these timeouts which never even occured in the past.

Well the lock you were seeing is from traces, but without other wait_stats it is hard to say if that is causing a large issue. I don't think monitoring it will help, you need to look at the sp and see what is going on. Has your data become more frequent and larger; maybe updating statistics will help. Is there just a lot more data and not properly indexed columns? Are the indexes fragmented? There are many causes, but start at the SP and look at the code to make sure it is optimized, then look at the table design, then fragmentation, finally see if updating statistics helps. Monitoring in this way will not show you what the issue is and will just hog resources.

Jared

Jared
CE - Microsoft

Pyman SSChampion Points: 13830 More actions · Answer 4

Thanks Jared I will start digging into these

Also, In the sql server error log I am seeing the below errors at the same time when the timeouts occurred.

Process 0:0:0 (0x864) Worker 0x00000000805381A0 appears to be non-yielding on Scheduler 0. Thread creation time: 12965206737741. Approx Thread CPU Used: kernel 0 ms, user 0 ms. Process Utilization 0%. System Idle 96%. Interval: 70102 ms.

“If your actions inspire others to dream more, learn more, do more and become more, you are a leader.” -- John Quincy Adams

Jared SSC Guru Points: 61793 More actions · Answer 5

Sapen (11/10/2011)

Thanks Jared I will start digging into these

Also, In the sql server error log I am seeing the below errors at the same time when the timeouts occurred.

Process 0:0:0 (0x864) Worker 0x00000000805381A0 appears to be non-yielding on Scheduler 0. Thread creation time: 12965206737741. Approx Thread CPU Used: kernel 0 ms, user 0 ms. Process Utilization 0%. System Idle 96%. Interval: 70102 ms.

I'm not 100% sure, but I think that is what happens after the timeout has released resources back.

Jared

Jared
CE - Microsoft

Pyman SSChampion Points: 13830 More actions · Answer 6

Pyman

SSChampion

Points: 13830

November 10, 2011 at 2:36 pm

#1406025

OK Thanks

“If your actions inspire others to dream more, learn more, do more and become more, you are a leader.” -- John Quincy Adams