Top Products report timeout

[sloDavid]

Any ideas on an Exception starting out of nowhere? We have not customized the Top Products report at all. Started all of a sudden on Friday night. In addition to the error below, sometimes we also get, on the same page, with no accompanying stack trace. Any ideas? (We have plenty of CPU & memory.)

Exception information:
Exception type: HttpException
Exception message: Request timed out.

OTHER ERROR:

Event code: 3005
Event message: An unhandled exception has occurred.
Event time: 7/28/2014 3:52:37 PM
Event time (UTC): 7/28/2014 10:52:37 PM
Event ID: 21bc3698c0d346728d589876f25ce062
Event sequence: 14399
Event occurrence: 5
Event detail code: 0

Application information:
Application domain: /LM/W3SVC/1/ROOT-1-130510064194482058
Trust level: Full
Application Virtual Path: /
Application Path: C:\inetpub\wwwroot\
Machine name: WEBSERVER1

Process information:
Process ID: 3724
Process name: w3wp.exe
Account name: IIS APPPOOL\AbleCommerce

Exception information:
Exception type: TargetInvocationException
Exception message: Exception has been thrown by the target of an invocation.

Request information:
Request URL: https://www.mysite.com:443/Admin/Report ... ducts.aspx
Request path: /Admin/Reports/TopProducts.aspx
User host address: XX.XXX.XX.X
User: XXXXXXXXX
Is authenticated: True
Authentication Type: Forms
Thread account name: IIS APPPOOL\AbleCommerce

Thread information:
Thread ID: 24
Thread account name: IIS APPPOOL\AbleCommerce
Is impersonating: False
Stack trace: at System.RuntimeMethodHandle._InvokeMethodFast(Object target, Object[] arguments, SignatureStruct& sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture, Boolean skipVisibilityChecks)
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
at System.Web.UI.WebControls.ObjectDataSourceView.InvokeMethod(ObjectDataSourceMethod method, Boolean disposeInstance, Object& instance)
at System.Web.UI.WebControls.ObjectDataSourceView.QueryTotalRowCount(IOrderedDictionary mergedParameters, DataSourceSelectArguments arguments, Boolean disposeInstance, Object& instance)
at System.Web.UI.WebControls.ObjectDataSourceView.ExecuteSelect(DataSourceSelectArguments arguments)
at System.Web.UI.DataSourceView.Select(DataSourceSelectArguments arguments, DataSourceViewSelectCallback callback)
at System.Web.UI.WebControls.DataBoundControl.PerformSelect()
at Admin_Reports_TopProducts.BindReport()
at Admin_Reports_TopProducts.Page_Load(Object sender, EventArgs e)
at System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr fp, Object o, Object t, EventArgs e)
at System.Web.Util.CalliEventHandlerDelegateProxy.Callback(Object sender, EventArgs e)
at System.EventHandler.Invoke(Object sender, EventArgs e)
at System.Web.UI.Control.OnLoad(EventArgs e)
at System.Web.UI.Control.LoadRecursive()
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)

[sloDavid]

The report seems to have recovered on its own. Strange.

[sloDavid]

... and it's broken again. We have plenty of available RAM & CPU on both the application & DB server.

[sloDavid]

After running a trace on the database in SQL Profiler, I found a query that was taking two minutes to run:

Code: Select all

exec sp_executesql N'
SELECT COUNT(*) AS ProductCount 
FROM (
	SELECT DISTINCT P.ProductId 
	FROM (ac_Orders O INNER JOIN ac_OrderItems OI ON O.OrderId = OI.OrderId) 
		INNER JOIN ac_Products P ON OI.ProductId = P.ProductId 
	WHERE O.StoreId = @storeId AND (
			O.OrderStatusId = @orderStatusId0 
			OR O.OrderStatusId = @orderStatusId1 
			OR O.OrderStatusId = @orderStatusId2 
			OR O.OrderStatusId = @orderStatusId3 
			OR O.OrderStatusId = @orderStatusId4 
			OR O.OrderStatusId = @orderStatusId5 
			OR O.OrderStatusId = @orderStatusId6 
			OR O.OrderStatusId = @orderStatusId7 
			OR O.OrderStatusId = @orderStatusId8 
			OR O.OrderStatusId = @orderStatusId9 
			OR O.OrderStatusId = @orderStatusId10 
			OR O.OrderStatusId = @orderStatusId11 
			OR O.OrderStatusId = @orderStatusId12 
			OR O.OrderStatusId = @orderStatusId13 
			OR O.OrderStatusId = @orderStatusId14 
			OR O.OrderStatusId = @orderStatusId15 
			OR O.OrderStatusId = @orderStatusId16
		) 
		AND O.OrderDate >= @startDate 
		AND O.OrderDate <= @endDate
) AS UniqueProducts'
,N'@storeId int
,@orderStatusId0 int
,@orderStatusId1 int
,@orderStatusId2 int
,@orderStatusId3 int
,@orderStatusId4 int
,@orderStatusId5 int
,@orderStatusId6 int
,@orderStatusId7 int
,@orderStatusId8 int
,@orderStatusId9 int
,@orderStatusId10 int
,@orderStatusId11 int
,@orderStatusId12 int
,@orderStatusId13 int
,@orderStatusId14 int
,@orderStatusId15 int
,@orderStatusId16 int
,@startDate datetime
,@endDate datetime'
,@storeId=1
,@orderStatusId0=1
,@orderStatusId1=2
,@orderStatusId2=3
,@orderStatusId3=4
,@orderStatusId4=7
,@orderStatusId5=8
,@orderStatusId6=9
,@orderStatusId7=10
,@orderStatusId8=11
,@orderStatusId9=12
,@orderStatusId10=13
,@orderStatusId11=14
,@orderStatusId12=15
,@orderStatusId13=16
,@orderStatusId14=17
,@orderStatusId15=18
,@orderStatusId16=19
,@startDate='2014-01-01 08:00:00'
,@endDate='2014-08-06 07:59:59'

The part of the query causing the slowdown was the DISTINCT keyword. Since the query is black-boxed and I have no access to modify it, I added a UNIQUE INDEX on the ProductID field on the Products table. That seems to have cleared the symptom.