Timeout expired error

Hi all,

  I'm running into a really strange issue with Lightspeed 1.2, and I could use a bit of help.  I'm using the following call to return a count of all possible records for paging.

   return Repository.Count<Track>(query);

However, whenever I execute this I always receive the error message from IIS that my request is timing out.  My laptop sounds as if it's getting ready for take off and everything maxes out at 100%.  Initially I thought this could be a data issue, a lack of indexing etc.  As such I turned on trace SQL logging, and I execute the SQL in my SQL Server Manager query tool.  The query only takes 500 ms to return.  I've included it below.  Any ideas on how I can begin to troubleshoot this?  The only difference between the generated query and the one below is that I cast the datetime since I have no way of inserting the actual datetime object.

MSSQL 2005, Lightspeed 1.2.

Thanks,

Todd

SELECT count(*)

FROM Tracks WHERE ((((Tracks.RecordedByUserId = '3097e3cb-88c7-4223-896d-791132884405' OR EXISTS

( SELECT TrackViewers.* FROM TrackViewers
WHERE TrackViewers.TrackId = Tracks.Id
AND TrackViewers.ViewerId = '3097e3cb-88c7-4223-896d-791132884405' ))
OR Tracks.OrganisationId = '15baaaf4-f6fc-4af0-92e6-f61821b44fe9')
AND Tracks.CreatedDate >= CAST('2008-11-30 13:00:00' AS DATETIME))
AND Tracks.CreatedDate <= CAST('2008-12-31 13:00:00' AS DATETIME))

 Here's the stack trace

[SqlException (0x80131904): Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.]
   System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection) +1948826
   System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection) +4844747
   System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj) +194
   System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj) +2392
   System.Data.SqlClient.SqlDataReader.ConsumeMetaData() +33
   System.Data.SqlClient.SqlDataReader.get_MetaData() +83
   System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString) +297
   System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async) +954
   System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result) +162
   System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method) +32
   System.Data.SqlClient.SqlCommand.ExecuteScalar() +139
   Mindscape.LightSpeed.Data.<>c__DisplayClass1.<ExecuteScalar>b__0() +64
   Mindscape.LightSpeed.Data.CommandRunner.Execute(IDbCommand command, CommandExecHandler handler) +382
   Mindscape.LightSpeed.Data.CommandRunner.ExecuteScalar(IDbCommand command) +148
   Mindscape.LightSpeed.UnitOfWork.Calculate(String calculation, String attribute, Query query) +298
   Mindscape.LightSpeed.Repository.Calculate(String calculation, String attribute, Query query) +126
   Mindscape.LightSpeed.Repository.Count(Query query) +96
   Mindscape.LightSpeed.Repository.Count(Query query) +149
   WebModel.Services.CurrentUserService.CountMyTracks(FindMyTracksCriteria criteria) in C:\spidertracks\WebModel\Services\CurrentUserService.cs:367

Hi Todd,

The LightSpeed log message should also tell you how long the query took when LightSpeed ran it.  Could you have a look and let us know what that value is?  (Use LightSpeedContext.Logger, *NOT* the SQL profiler logger.)

Does your build of LightSpeed have a VerboseLogging option on the LightSpeedContext?  (We added this fairly late in the 1.2 lifecycle I think, so you may not have it.)  If so, could you also turn that on and verify that the parameter values are what you expect.

It would also be useful if you could step through in the debugger and verify that the infinite loop (or whatever it is) is happening within the Repository.Count method (i.e. that LightSpeed never returns from the Repository.Count call).

Assuming this is the case, could you provide us with the following:

- Your Query object setup code
- The SQL CREATE TABLE statements for the relevant tables (Tracks and TrackViewers)
- A rough indication of how many rows in each of these tables
- What you roughly expect the result of the count query to be

It would also be useful if you could so some "poor man's profiling" for us: run the code in the debugger and, when it starts spinning, randomly press the Pause button a few times, and send us the contents of the Call Stack window.  (This obviously isn't as informative as real profiling, but if we're stuck in a particular function, it can be a quicker way of finding out!)

Hmm, okay, ignore much of the previous message.  I'm still interested in the LightSpeed log (including verbose logging), but forget the rest of it for now.

Can you check using Task Manager which process is hoovering up all the CPU please?  Is it SQL Server or IIS?

This is functionally equivalent and works without returning an error, but his horribly inefficient.

IList<Track> results = Repository.Find<Track>(query);

return (results != null) ? results.Count : 0;

 Sorry, I just saw your post.  The process is the MSSQL server that is eating my CPU.  I don't get any CPU spikes if I return the entire resultset instead of the count.  I get the message "In a sleep, wait, or join" in the call stack, but I don't get any other information.  I have the following in my web.config

    loggerClass="Mindscape.LightSpeed.Logging.TraceLogger, Mindscape.LightSpeed"

But that's the only configuration option I have on the LightSpeed class.  Do you guys support log4net?  I tried setting all Mindscape.LightSpeed classed to DEBUG, but I'm not getting anything in the log.

We don't support log4net directly though you could easily write an ILogger implementation that backed onto log4net.  That TraceLogger should be outputting to the Visual Studio Output window when you run it in the debugger: if that doesn't work, try throwing together a little console app that reproduces the problem, and set LightSpeedContext.Logger = new ConsoleLogger().

However given that SQL Server is the process that's spiking I think this may be a SQL Server issue.  I'm not sure why you don't see it when you try the same SQL through the management UI.  I'm wondering if it's something to do with running it inside a transaction?  Have you tried different isolation levels, or performing the count outside a transaction?

Here is another thing to try which, if it works, would be more efficient than loading the entire result set.  I am not very familiar with LightSpeed 1.x so I am not sure of exact syntax or even whether this is supported in the build you have but I'll mention it anyway.  If you have a Calculate method on Repository, try using that to count the IDs, e.g. Repository.Calculate<Track>("COUNT", "Id", query).  Perhaps that will fool SQL Server into trying a different query plan.
 

I've just talked to JD about this and he tells me there have been similar issues before on your live box.  Can you clarify whether this is happening on the live server or on your development box?  I understand the issue may relate to connections not being released and the SQL Server connection pool being exhausted.  Can you check how many connections are outstanding in SQL Server?  Thanks!

 Hi Ian.

  I agree this appears to be a SQL server issue.  Upon rebooting, my issue no longer occurs.  I can execute the query for a while, then I begin to get the time out again.   It doesn't seem to make any difference as to the current number of connections.  My application's DB user always has 2 open connections.  When it dies it's always < the maximum if my query below is correct.  With every page load if I execute the following query

select @@MAX_CONNECTIONS as max, @@CONNECTIONS as connections

My current connections size increases by 2 every time, which makes sense since only 2 connections are present.  However when i check how many connections are currently open by my applications login

 sp_who 'spidertracksdev'

I am only returned 2 connections.  Is there any other data I can provide?