AI OnAI Off

SQL timeout when clicking any scheduled task when running local IIS

Kristoffer Lindén
Kristoffer Lindén
Vote:
 

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

#179840
Jun 22, 2017 21:14
valdis
valdis
Vote:
 

What do you see in SQL Profiler?

#179886
Jun 24, 2017 7:07
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

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

#179892
Jun 24, 2017 13:02
valdis
valdis
Vote:
 

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..

#179893
Jun 24, 2017 18:40
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

Reported!

#179900
Jun 25, 2017 16:54
Quan Mai
Quan Mai
Vote:
 

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 ... 

#179903
Jun 25, 2017 20:49
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

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

#179904
Jun 25, 2017 20:53
valdis
valdis
Vote:
 

Can you paste please execution plan for the bad query?

#179905
Jun 25, 2017 21:50
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

How do I get the execution plan?

#179906
Jun 25, 2017 21:51
valdis
valdis
Vote:
 

in SQL Profiler - there is a button that needs to be toggled before execution of the query

#179907
Jun 25, 2017 21:58
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

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! :-)

#179908
Jun 25, 2017 22:05
Quan Mai
Quan Mai
Vote:
 

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. :)

#179910
Jun 26, 2017 7:33
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

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

#180039
Jun 28, 2017 23:01
valdis
valdis
Vote:
 

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.

#180044
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.
* You are NOT allowed to include any hyperlinks in the post because your account hasn't associated to your company. User profile should be updated.