Performance Issue with Projection

Hi,

I'm running into a fairly strange performance issue when using Lightspeed. I have the following linq statement:

var transactionQuery = unitOfWork.Transactions;

// Only add if transactionTypeId is passed through
if (transactionTypeId.HasValue)
    transactionQuery = transactionQuery.Where(x => x.TransactionTypeId == transactionTypeId);

var transactionInfoQuery = from transaction in transactionQuery 
                           join transactionType in unitOfWork.TransactionTypes on transaction.TransactionTypeId equals transactionType.Id
                           join invoice in unitOfWork.Invoices on transaction.Id equals invoice.TransactionId into outer
                           from invoice in outer.DefaultIfEmpty()
                           where transaction.AccountBranchId == accountBranchId && transaction.Date >= fromDate && transaction.Date <= toDate
                           orderby transaction.Date descending
                           select new TransactionInfo
                           {
                             Id = transaction.Id,
                             Date = transaction.Date,
                             DocumentNumber = transaction.DocumentNumber,
                             Amount = transaction.Amount,
                             Type = transactionType.Name,
                             HasInvoice = (invoice != null),
                             Url = (invoice == null) ?? invoice.Url, 
                           };

I basically return an IQueryable on which I then do paging via:

list.AddRange(transactionInfoQuery.Skip(skip).Take(take));

This produces reasonably nice sql (there is more columns that I need for my select, but it isn't a terrible query):

DECLARE @p0 int = 0,
        @p1 int = 30,
        @p2 int = 4439,
        @p3 datetime = '2012-03-04T00:00:00',
        @p4 datetime = '2012-06-02T00:00:00'

SELECT
  [t0].*
FROM
  (
    SELECT
      [t0].[Id] AS [t0.Id],
      [t0].[AccountBranchId] AS [t0.AccountBranchId],
      [t0].[Amount] AS [t0.Amount],
      [t0].[Date] AS [t0.Date],
      [t0].[DocumentNumber] AS [t0.DocumentNumber],
      [t0].[FreightAmount] AS [t0.FreightAmount],
      [t0].[NetAmount] AS [t0.NetAmount],
      [t0].[PaymentType] AS [t0.PaymentType],
      [t0].[StatementId] AS [t0.StatementId],
      [t0].[TaxAmount] AS [t0.TaxAmount],
      [t0].[TransactionTypeId] AS [t0.TransactionTypeId],
      [t1].[Id] AS [t1.Id],
      [t1].[Name] AS [t1.Name],
      [t2].[Id] AS [t2.Id],
      [t2].[CustomerName] AS [t2.CustomerName],
      [t2].[CustomerOrder] AS [t2.CustomerOrder],
      [t2].[DeliveryAddressLine1] AS [t2.DeliveryAddressLine1],
      [t2].[DeliveryAddressLine2] AS [t2.DeliveryAddressLine2],
      [t2].[DeliveryAddressLine3] AS [t2.DeliveryAddressLine3],
      [t2].[DeliveryAddressLine4] AS [t2.DeliveryAddressLine4],
      [t2].[Freight] AS [t2.Freight],
      [t2].[FreightCost] AS [t2.FreightCost],
      [t2].[IssueDate] AS [t2.IssueDate],
      [t2].[PostalAddressLine1] AS [t2.PostalAddressLine1],
      [t2].[PostalAddressLine2] AS [t2.PostalAddressLine2],
      [t2].[PostalAddressLine3] AS [t2.PostalAddressLine3],
      [t2].[PostalAddressLine4] AS [t2.PostalAddressLine4],
      [t2].[SpecialInstruction1] AS [t2.SpecialInstruction1],
      [t2].[SpecialInstruction2] AS [t2.SpecialInstruction2],
      [t2].[SpecialInstruction3] AS [t2.SpecialInstruction3],
      [t2].[SpecialInstruction4] AS [t2.SpecialInstruction4],
      [t2].[TransactionId] AS [t2.TransactionId],
      [t2].[Url] AS [t2.Url],
      ROW_NUMBER() OVER(ORDER BY [t0].[Date] DESC) as RowNumber
    FROM
      [Transaction] [t0]
    INNER JOIN
      [TransactionType] [t1]
    ON
      [t0].[TransactionTypeId] = [t1].[Id]
    LEFT OUTER JOIN
      [Invoice] [t2]
    ON
      [t0].[Id] = [t2].[TransactionId]
    WHERE
      (([t0].[AccountBranchId] = @p2 AND [t0].[Date] >= @p3) AND [t0].[Date] <= @p4)
  )
  [t0]
WHERE
  RowNumber > @p0 AND
  RowNumber <= @p1 

And in the output window (with a trace enabled on the context), I see reasonably small timings (under 10ms). If I run this query in SQL Management Studio, I get a similarly quick response. There are a significant amount of records in the tables (approx ~500k).

Now where I run into problems is on my website. I have MiniProfiler setup (as per the blog post instructions) and I get a noticeable 900-1100ms timing for this query (and the page does take this long - it's not an error in reporting). I've attached a partial screenshot to demonstrate this.

Is there something I'm doing stupid that could be causing these performance issues? Is there any options I can set to tune this query? I basically don't need any caching - I simply want to results into my TransactionInfo objects so I can show info on a page.

Cheers & thanks,

-Brad

Are you connecting to the same database server in all cases?

From your troubleshooting it sounds like you've eliminated everything except connection and network overhead to the database server. Or you could be running low on RAM on the web server and this page is thrashing the disk.

Can you do a .ToList() on the query or do you really need to append?

I'm definitely pointing to the same database - what's strange is that the Output window in VS is showing a query time of 4ms for one particular query - but the mini profiler (and a System.Diagnostics.Wtopwatch instance which I've wrapped around the execution of the query) are both showing 950ms+ (for the same query). SQL Profiler is showing 2ms for that instance of the query.

I've tried taking off the Take() & Skip(), and have removed the AddRange() from my original post. Unfortunately, this didn't make any positive difference.

It shouldn't be this expensive, but could you check how the performance is when you turn off the logging on the LightSpeedContext?

Historically this has been an area where some folks experience perf problems because logging is actually relatively expensive compared to a query. It's just a guess at this stage without seeing a code snippet to reproduce it :-)

Let me know if that helps,

John-Daniel

I turned off all logging. I'm still getting very similar timings (it's slightly better at around 850ms to 950ms) which is still around 800ms to 900ms longer than it should be. Looks like it's time to try and reproduce in a solution I can share with you guys. :-(

Cheers & thanks,

Brad

minor point [especially as I don't use/understand the ORM product!] I notice that your original C# constructor has a trailing comma. HTH Dick

Hi Brad,

If you are able to reproduce the same timings in a console/windows application rather than a web application then that sounds like the cost would be in handling the response from the database and performing the object materialization, which would be slow unless we are talking about a very large number of objects.

If that is the case would you be able to send through the console/windows application version which would allow us to reproduce the problem here and have a look into what is going on.

Jeremy