title: 15 second delay before first call to database in EF 6
body: <p>After having the C# ASP.NET MVC with EF 6 application in production for about 3 months, we are noticing one call to the database taking considerably longer than it used to.  It started out taking less than one second for the operation.  With no gradual increase, it jumped to 15 seconds.</p>
  
  <p>I have enabled logging on the EF context.  Here is the code.</p>
  
  <pre><code>public async Task&lt;int&gt; SetToProcessing(string[] documentIds, string userName)
  {
      if (documentIds.Count() == 0)
          return 0;
  
      var assigned = 0;
      using (var db = new InvoiceDeliveryContext())
      {
          db.Database.Log = message =&gt; logger.Debug("EF6-" + message);
          foreach (var id in ConvertToLong(documentIds))
          {
              if (id == 0)
                  continue;
              var doc = db.Documents.Find(id);
              if (doc.Status == DocumentStates.Processing)
              {
                  logger.Debug($"Document Id {id} not being set to processed.  Already set to Processing.");
                  continue;
              }
              assigned++;
              doc.AssignedTo = userName;
              doc.Status = DocumentStates.Processing;
              doc.History.Add(new History
              {
                  Audit = "Set back to Processing.",
                  CreatedBy = userName,
                  Document = doc,
              });
  
              logger.Debug($"Assigned Document with ID={id} for Processing to {userName}.");
          }
          try
          {
              await db.SaveChangesAsync();
          }
          catch (Exception e)
          {
              logger.Error(e, "An exception occurred trying to set documents to processing.");
          }
      }
      return assigned;
  }
  </code></pre>
  
  <p>Here is the resulting log.  Notice after the connection is opened, a ~15 second delay occurs.</p>
  
  <pre><code>[5] 2017-07-27 06:47:32.4742 EF6-Opened connection at 7/27/2017 6:47:32 AM -05:00  
  [5] 2017-07-27 06:47:47.0677 EF6-SELECT TOP (2)   
      [Extent1].[DocumentId] AS [DocumentId],   
      [Extent1].[AssignedTo] AS [AssignedTo],   
      [Extent1].[ApprovedBy] AS [ApprovedBy],   
      [Extent1].[AttachmentId] AS [AttachmentId],   
      [Extent1].[FileLocation] AS [FileLocation],   
      [Extent1].[FileSize] AS [FileSize],   
      [Extent1].[Name] AS [Name],   
      [Extent1].[Pages] AS [Pages],   
      [Extent1].[Part] AS [Part],   
      [Extent1].[Parts] AS [Parts],   
      [Extent1].[IsMerged] AS [IsMerged],   
      [Extent1].[ReceivedOn] AS [ReceivedOn],   
      [Extent1].[Status] AS [Status],   
      FROM [InvoiceDelivery].[Documents] AS [Extent1]  
      WHERE [Extent1].[DocumentId] = @p0   
  [5] 2017-07-27 06:47:47.0980 EF6--- p0: '7149' (Type = Int64)  
  [5] 2017-07-27 06:47:47.0980 EF6--- Executing at 7/27/2017 6:47:47 AM -05:00  
  [5] 2017-07-27 06:47:47.1401 EF6--- Completed in 28 ms with result: SqlDataReader
  </code></pre>
  
  <p>I have captured the logs of the above process multiple times and they all show around 15 seconds of delay.  Other queries do not experience this issue.  Any idea why I would see this delay?</p>
  
  <h2>EDIT</h2>
  
  <p>I am unable to reproduce the delay using a new console app.<br>
      <code>private static async Task GoAsync()
       {
           var repo = new InvoiceRepository();
           await repo.SetToProcessing(new[] { "7149" }, "JD Montgomery");
       }</code></p>