SagePay (payment gateway) notification return taking long time in ASP.Net MVC application

Question

We are experiencing performance issues within our website related to high cpu usage. When using a profiler we have identified a particular method that is taking ~35 seconds to return from.

This is a call back method when using a payment gateway called SagePay.

I have copied the two methods that are part of this call below:

 public void SagePayNotificationReturn()
    {
        string vendorTxCode = Request.Form["vendortxcode"];

        var sagePayTransaction = this.sagePayTransactionManager.GetTransactionByVendorTxCode(vendorTxCode);
        if (sagePayTransaction == null)
        {
            // Cannot find the order, so log an error and return error response
            int errorId = this.exceptionManager.LogException(System.Web.HttpContext.Current.Request, new Exception(string.Format("Could not find SagePay transaction for order {0}.", vendorTxCode)));
            ReturnResponse(System.Web.HttpContext.Current, StatusEnum.ERROR, string.Format("{0}home/error/{1}", GlobalSettings.SiteURL, errorId), string.Format("Received notification for {0} but the transaction was not found.", vendorTxCode));
        }
        else
        {
            // Store the response and respond immediately to SagePay
            sagePayTransaction.NotificationValues = sagePayTransactionManager.FormValuesToQueryString(Request.Form);
            this.sagePayTransactionManager.Save(sagePayTransaction);
            ReturnResponse(System.Web.HttpContext.Current, StatusEnum.OK, string.Format("{0}payment/processtransaction/{1}", GlobalSettings.SiteURL, vendorTxCode), string.Empty);
        }
    }

 private void ReturnResponse(HttpContext context, StatusEnum status, string redirectUrl, string statusDetail)
    {
        context.Response.Clear();
        context.Response.ContentEncoding = Encoding.UTF8;
        using (StreamWriter streamWriter = new StreamWriter(context.Response.OutputStream))
        {
            streamWriter.WriteLine(string.Concat("Status=", status.ToString()));
            streamWriter.WriteLine(string.Concat("RedirectURL=", redirectUrl));
            streamWriter.WriteLine(string.Concat("StatusDetail=", HttpUtility.HtmlEncode(statusDetail)));
            streamWriter.Flush();
            streamWriter.Close();
        }

        context.ApplicationInstance.CompleteRequest();
    }

The GetTransactionByVendorTxCode method is a simple Entity Framework call, so I've ruled that out.

Has anybody any experience in this or can they see anything glaringly wrong with the code that could cause such an issue?

EDIT: Looking at the breakdown table provided by the profiler, it says that 99.6% time is spent in System.Web.Mvc.MvcHandler.BeginProcessRequest().

EDIT: Using the profiling tool New Relic, it says that 22% of all processing time is spent in the this.sagePayTransactionManager.GetTransactionByVendorTxCode(vendorTxCode) method. This is simply containing an EF6 call to a repository. The call does contain a predicate parameter though, rather than pre-defined condition. Could it be that the query is not being pre-compiled?

"a simple Entity Framework call" - Are you sure? what is the code for this? — Tim B James, Dec 10 '14 at 12:35
Take a look at this question/answer, and add the debug writeline code to the Application_BeginRequest: http://stackoverflow.com/a/17073158/82333 — C Bauer, Dec 10 '14 at 12:57
Change the GetTransactionByVendorTxCode call for a dummy data construct and see if response time changes drastically. If it does there you have the bottleneck, if it doesn't is time to look on other place. — Bardo, Dec 10 '14 at 13:59
I am just curious, why do you have streamWriter.Flush(); streamWriter.Close();? Wouldn't that be taken care by using statement? — Ahuman, Dec 13 '14 at 01:32
Kindly profile the db queries part also. May be EF generates a huge query with union etc. This can give some insight — Saravanan, Dec 13 '14 at 08:02
Is Aynchronus operation available for service call? If yes then can you do things in callback? Asynchronus operation can tell you what is exact time service is taking from begin request to request complete. — Amit, Dec 16 '14 at 07:08
Have you tried flushing the Query Plan Cache on the database? — Martin Brown, Dec 17 '14 at 10:25

score 2 · Answer 1 · answered Dec 16 '14 at 18:32

Here's my first step of getting to the solution:

Put in a timer start before this statement then stop it when it completes. Tell us the timespan.

var sagePayTransaction = this.sagePayTransactionManager.GetTransactionByVendorTxCode(vendorTxCode);

Put in another timer for this code block: Tell us the relative time compared to method above.

   using (StreamWriter streamWriter = new StreamWriter(context.Response.OutputStream))
    {
        streamWriter.WriteLine(string.Concat("Status=", status.ToString()));
        streamWriter.WriteLine(string.Concat("RedirectURL=", redirectUrl));
        streamWriter.WriteLine(string.Concat("StatusDetail=", HttpUtility.HtmlEncode(statusDetail)));
        streamWriter.Flush();
        streamWriter.Close();
    }

Finally put another timer here:

context.ApplicationInstance.CompleteRequest();

Post the information back to us and I'll guide you to the next step. What we are doing above is getting metrics that will span both local and remote access to find the major problem. We'll pick that off first then progress further if needed. Just tell us what the measurements are.

The class to use for this kind of timing is System.Diagnostics.Stopwatch.StartNew() as it often gets a much more accurate timing than using DateTime.Now() — Martin Brown, Dec 17 '14 at 10:23

score 1 · Answer 2 · answered Dec 16 '14 at 09:29

There are a number of things you may need to consider here.

If GetTransactionByVendorTxCode is responsible for 22% of total processing time, then you will need to streamline everything that method touches but then still go on to fish other bottlenecks in the overall processing pipeline.

You say that method abstracts a call to EF6 and that it passes in a predicate expression that gets used in the Where clause to build up the final query.

If the query is a complex one, have you considered delegating to a StoredProcedure? Since you are returning an Entity, you can hang it off of the DbSet. (In the case of a DTO, it will hang off the Database property of the DbContext).

Also, you will need to look at the indices on the columns used in your predicate. What is the current record count? Are your queries resulting in seeks or scans? You will need to look at the resulting query plans; if using SQL Server run your queries Database Engine Tuning Advisor.

Perhaps a little more detail about your current setup will assist in providing better guidance.

SagePay (payment gateway) notification return taking long time in ASP.Net MVC application

2 Answers2