Five New Optimizely Certifications are Here! Validate your expertise and advance your career with our latest certification exams. Click here to find out more
AI OnAI Off
SQL timeout when clicking any scheduled task when running local IIS
Ah, god way to go Valdis!
Found what procedure is taking so long:
exec netSchedulerList
Takes 38 seconds to excute, and there for of course time out on the web?
But why?
SO I started to look into it:
select * from tblScheduledItem
takes 38 seconds
select top 1 * from tblScheduledItem
works like a charm so I started to try get them one by one and finnaly found that it is the Episerver Find Content Indexing Job that was the problem.
select * from tblScheduledItem where pkID = '0132574D-1FCC-4604-A717-41BFED360F40'
takes 38 seconds.
So I started to get column by column:
select pkId from tblScheduledItem where pkID = '0132574D-1FCC-4604-A717-41BFED360F40'
and so on and finally ended up with this:
select LastText from tblScheduledItem where pkID = '0132574D-1FCC-4604-A717-41BFED360F40'
that one takes 38 seconds. The column LastText had more that 43000 characters, there for the query against that table took to long.
update tblScheduledItem set lasttext = null where pkID = '0132574D-1FCC-4604-A717-41BFED360F40'
and we are back on track again.
Do you think this is something that should be reported to Episerver?
/Kristoffer
Jun 24, 2017 13:02
Good searching.. I think it's definitely worth noting them. Don't think that those thousands symbols are even visible somewhere in UI. Even trimming might help here..
Jun 24, 2017 18:40
That's a good investigation Kristoffer. However I'm surprised that 43000 characters can screw up performance like that. I actually tried with 80KB and it was fine. Something must be wrong ...
Jun 25, 2017 20:49
I agree, it should be fine. Also the tblScheduledItemLog had to be cleared for the current indexing job for the scheduled item to load.
Any ideas how I can investegate further? A select against the database, as above, with one row of data should work just fine. But I'm not sure where to look from here?
Thanks Quan!
/Kristoffer
Jun 25, 2017 20:53
in SQL Profiler - there is a button that needs to be toggled before execution of the query
Jun 25, 2017 21:58
Now this is strange. I inserted the same text and it worked just fine. I then added five times as much text, 250kb, and that worked as a charm as well.
Hmm, why can this be? Some kind of lock on the table or something?
I'm confused! :-)
Jun 25, 2017 22:05
Small correction: It's SQL Server Management Studio, not SQL Profiler
Without being able to reproduce the issue, I'd guess it was probably caused by a bad execution plan, or some faulty pages by SQL Server. However that will remain a mystery. :)
Jun 26, 2017 7:33
So I still got the problem when loading an scheduled task since the same problem occurs in tblScheduledItemLog so I managed to get an execution plan.
Does this say anything?
<?xml version="1.0" encoding="utf-16"?>
<ShowPlanXML xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" Version="1.5" Build="13.0.1728.2" xmlns="http://schemas.microsoft.com/sqlserver/2004/07/showplan">
<BatchSequence>
<Batch>
<Statements>
<StmtSimple StatementCompId="1" StatementEstRows="27.2966" StatementId="1" StatementOptmLevel="TRIVIAL" CardinalityEstimationModelVersion="120" StatementSubTreeCost="0.443095" StatementText="select * from tblScheduledItemLog where fkScheduledItemId = '0132574D-1FCC-4604-A717-41BFED360F40'" StatementType="SELECT" ParameterizedText="(@1 varchar(8000))SELECT * FROM [tblScheduledItemLog] WHERE [fkScheduledItemId]=@1" QueryHash="0x317432974C49833C" QueryPlanHash="0x6857EFFC68F5AC93" RetrievedFromCache="true" SecurityPolicyApplied="false">
<StatementSetOptions ANSI_NULLS="true" ANSI_PADDING="true" ANSI_WARNINGS="true" ARITHABORT="true" CONCAT_NULL_YIELDS_NULL="true" NUMERIC_ROUNDABORT="false" QUOTED_IDENTIFIER="true" />
<QueryPlan CachedPlanSize="24" CompileTime="0" CompileCPU="0" CompileMemory="128">
<MemoryGrantInfo SerialRequiredMemory="0" SerialDesiredMemory="0" />
<OptimizerHardwareDependentProperties EstimatedAvailableMemoryGrant="206670" EstimatedPagesCached="51667" EstimatedAvailableDegreeOfParallelism="2" />
<RelOp AvgRowSize="4336" EstimateCPU="0.0066371" EstimateIO="0.436458" EstimateRebinds="0" EstimateRewinds="0" EstimatedExecutionMode="Row" EstimateRows="27.2966" LogicalOp="Clustered Index Scan" NodeId="0" Parallel="false" PhysicalOp="Clustered Index Scan" EstimatedTotalSubtreeCost="0.443095" TableCardinality="5891">
<OutputList>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="pkID" />
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="fkScheduledItemId" />
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Exec" />
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Status" />
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Text" />
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Duration" />
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Server" />
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Trigger" />
</OutputList>
<IndexScan Ordered="false" ForcedIndex="false" ForceScan="false" NoExpandHint="false" Storage="RowStore">
<DefinedValues>
<DefinedValue>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="pkID" />
</DefinedValue>
<DefinedValue>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="fkScheduledItemId" />
</DefinedValue>
<DefinedValue>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Exec" />
</DefinedValue>
<DefinedValue>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Status" />
</DefinedValue>
<DefinedValue>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Text" />
</DefinedValue>
<DefinedValue>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Duration" />
</DefinedValue>
<DefinedValue>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Server" />
</DefinedValue>
<DefinedValue>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="Trigger" />
</DefinedValue>
</DefinedValues>
<Object Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Index="[PK_tblScheduledItemLog]" IndexKind="Clustered" Storage="RowStore" />
<Predicate>
<ScalarOperator ScalarString="[Designonline.CmsBeta].[dbo].[tblScheduledItemLog].[fkScheduledItemId]=CONVERT_IMPLICIT(uniqueidentifier,[@1],0)">
<Compare CompareOp="EQ">
<ScalarOperator>
<Identifier>
<ColumnReference Database="[Designonline.CmsBeta]" Schema="[dbo]" Table="[tblScheduledItemLog]" Column="fkScheduledItemId" />
</Identifier>
</ScalarOperator>
<ScalarOperator>
<Identifier>
<ColumnReference Column="ConstExpr1002">
<ScalarOperator>
<Convert DataType="uniqueidentifier" Style="0" Implicit="true">
<ScalarOperator>
<Identifier>
<ColumnReference Column="@1" />
</Identifier>
</ScalarOperator>
</Convert>
</ScalarOperator>
</ColumnReference>
</Identifier>
</ScalarOperator>
</Compare>
</ScalarOperator>
</Predicate>
</IndexScan>
</RelOp>
<ParameterList>
<ColumnReference Column="@1" ParameterCompiledValue="'0132574D-1FCC-4604-A717-41BFED360F40'" />
</ParameterList>
</QueryPlan>
</StmtSimple>
</Statements>
</Batch>
</BatchSequence>
</ShowPlanXML>
/Kristoffer
Jun 28, 2017 23:01
Interesting...
Execution plan basically shows that clustered index scan is happening - basically reading all 272'966 records. It looks for all records for particular scheduled job (fkScheduledItemId). Interesting would be to see Database Engine Tuning Advisor output as well..
As far as I can see - there is no index on scheduled item Id column (it just plays role in foreign key constraint). Just for fun - try to create index for this column (yes, it's not "allowed" and is not supported officially). But just try and see execution plan results. Should be index seek insted of index lookup.
Jun 29, 2017 7:41
This topic was created over six months ago and has been resolved. If you have a similar question, please create a new topic and refer to this one.
Hi!
As soon as I click a scheduled task I get an SQL timeout. Everything else works just fine. All parts of Epi edit och Epi admin works just fine except when I click on any scheduled task. Strange!?
Server Error in '/' Application. The wait operation timed out Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code. Exception Details: System.ComponentModel.Win32Exception: The wait operation timed out Source Error: An unhandled exception was generated during the execution of the current web request. Information regarding the origin and location of the exception can be identified using the exception stack trace below. Stack Trace: [Win32Exception (0x80004005): The wait operation timed out] [SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.] System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction) +110 System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) +345 System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error) +697 System.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync() +224 System.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket() +126 System.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer() +101 System.Data.SqlClient.TdsParserStateObject.TryReadUInt32(UInt32& value) +50 System.Data.SqlClient.TdsParserStateObject.TryReadPlpLength(Boolean returnPlpNullIfNull, UInt64& lengthLeft) +129 System.Data.SqlClient.TdsParser.TryReadPlpUnicodeChars(Char[]& buff, Int32 offst, Int32 len, TdsParserStateObject stateObj, Int32& totalCharsRead) +498 System.Data.SqlClient.TdsParser.TryReadSqlStringValue(SqlBuffer value, Byte type, Int32 length, Encoding encoding, Boolean isPlp, TdsParserStateObject stateObj) +319 System.Data.SqlClient.TdsParser.TryReadSqlValue(SqlBuffer value, SqlMetaDataPriv md, Int32 length, TdsParserStateObject stateObj, SqlCommandColumnEncryptionSetting columnEncryptionOverride, String columnName) +701 System.Data.SqlClient.SqlDataReader.TryReadColumnInternal(Int32 i, Boolean readHeaderOnly) +729 System.Data.SqlClient.SqlDataReader.TryReadColumn(Int32 i, Boolean setTimeout, Boolean allowPartiallyReadColumn) +109 System.Data.SqlClient.SqlDataReader.GetValueInternal(Int32 i) +41 System.Data.SqlClient.SqlDataReader.GetValue(Int32 i) +78 EPiServer.DataAccess.Internal.SchedulerDB.CreateJob(IDataRecord reader) +543 EPiServer.DataAccess.Internal.<>c__DisplayClass7_0.b__0() +199 EPiServer.Data.Providers.Internal.<>c__DisplayClass31_0`1.b__0() +56
EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute(Func`1 method) +777
EPiServer.DataAbstraction.Internal.DefaultScheduledJobRepository.List() +41
EPiServer.DataAbstraction.Internal.DefaultScheduledJobRepository.Get(String method, String typeName, String assemblyName) +45
EPiServer.UI.Admin.DatabaseJob.OnLoad(EventArgs e) +577
System.Web.UI.Control.LoadRecursive() +68
System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) +1436
Version Information: Microsoft .NET Framework Version:4.0.30319; ASP.NET Version:4.6.1637.0
Has anyone seen this before, this is new for me!
On the production server all links works fine and quick except the link for the Episerver Find Content Indexing Job, that takes a very long time to load and I doesn't load all times. Find issue?
Any ideas?
/Kristoffer