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?

Answer 1

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.