Ayuda para solucionar problemas de SqlException: Tiempo de espera expirado en la conexión, en una situación sin carga

StackOverflow https://stackoverflow.com/questions/1421978

Pregunta

Tengo un servidor que aloja un sitio web mío que tiene casi cero tráfico.
Algunas personas (& Lt; 20) ingresan al sitio todos los días, y algunos lectores RSS están suscritos a algunas fuentes que publicamos.

Casi todas las noches, un lector de RSS nos golpeará en medio de la noche y obtendrá una excepción de que el sitio web no puede conectarse al SQL Server debido a un tiempo de espera en la conexión. Los detalles son extremadamente raros, así que estoy buscando ayuda sobre cuál podría ser el problema, ya que no sé por dónde empezar a buscar más.

Estamos utilizando ASP.Net MVC, Entity Framework y SQL Server 2008 sobre Windows Server 2008. La máquina es una caja dedicada que obtuvimos de un proveedor no exactamente de primer nivel, por lo que las cosas podrían configurarse de manera no óptima, o quién sabe qué más.
La caja también es bastante pequeña y tiene solo 1 Gb de RAM, pero debería soportar el tipo de carga que tenemos por ahora ...

Estoy copiando la pila de llamadas completa a continuación, pero primero, algunas de las cosas que sabemos:

  • El error siempre ocurre cuando iTunes consulta nuestro sitio. Creo que esto no debería tener nada que ver con nada, pero la verdad es que solo lo obtenemos de iTunes. Mi mejor conjetura es que esto sucede porque solo iTunes nos consulta a esa hora de la noche cuando nadie más nos está golpeando.
  • Una de nuestras teorías es que SQL Server e IIS están luchando por la memoria, y una de ellas está siendo paginada en el disco para que no se use, y cuando alguien & "; la despierta &"; , lleva demasiado tiempo volver a leer todo, desde el disco a la memoria. ¿Es esto algo que podría suceder potencialmente? (Estoy descartando esto porque suena como un problema de diseño en SQL Server si fuera posible)
  • También pensé en la posibilidad de que tengamos fugas de conexiones, ya que es posible que no estemos eliminando las entidades de EF de manera adecuada ( vea mi pregunta aquí ). Esto es lo único que pude encontrar buscando en Google el problema. Estoy descartando esto dada la carga extremadamente baja que tenemos.
  • Esto siempre sucede durante la noche, por lo que es muy probable que esté relacionado con el hecho de que no pasó nada por un tiempo. Por ejemplo, estoy bastante seguro de que cuando llegan estas solicitudes, el proceso del servidor web se recicla y se está iniciando / volviendo a JITAR todo. Sin embargo, el re-JITting no explica el tiempo de espera de SQL.

ACTUALIZACIÓN: adjuntamos un generador de perfiles como se sugirió, y pasó bastante tiempo antes de que tuviéramos una nueva excepción. Estas son las novedades que conocemos:

  • Tener el generador de perfiles adjunto enormemente redujo la cantidad de errores que obtuvimos. De hecho, después de obtener normalmente varios por día, tuvimos que esperar 3 o 4 días para que esto suceda UNA VEZ. Una vez que detuvimos el generador de perfiles, volvió a la frecuencia de error normal (o incluso peor). Por lo tanto, el generador de perfiles tiene un efecto algún que oculta este problema hasta cierto punto, pero no completamente.
  • Al observar el seguimiento del generador de perfiles junto al registro de solicitudes de IIS, se espera una correspondencia 1-1 entre solicitudes y consultas. Sin embargo, de vez en cuando, veo que se ejecutan MUCHAS consultas que no tienen ninguna correlación con el registro de IIS. De hecho, justo antes de que se registrara el error real, recibí 750 consultas en un período de 3 minutos , todas las cuales no tenían relación alguna con los registros de IIS. El texto de la consulta se parece al tipo de basura ilegible que genera EF, y no son todos iguales, y todos se parecen a las consultas que provienen del sitio web: Mismo nombre de aplicación, usuario, etc. Para dar una idea de lo ridículo que es esto es decir, el sitio recibió alrededor de 370 solicitudes de IIS que llegaron a la base de datos, en el transcurso de 2 días
  • Estas consultas inexplicables no provienen del mismo ClientProcessID que las páginas web anteriores, aunque aún pueden provenir del sitio webe, si el proceso se recicló mientras tanto. Hubo casi una hora sin actividad entre la última consulta explicada y la primera sin explicación.
  • Una de estas largas rachas de consultas que no sé de dónde provienen llegó justo antes del error que logré registrar, así que creo que esta es la pista que deberíamos seguir.
  • Como esperaba originalmente, cuando se ejecutó la consulta que arrojó el error, provenía de un ClientProcessID diferente al anterior (8 minutos más tarde que el anterior sin explicación, y casi exactamente una hora más tarde que el IIS anterior ) Esto significa, para mí, que el proceso de trabajo se había reciclado.
  • Esto es algo que absolutamente no entiendo. El registro de IIS muestra que un minuto antes de las solicitudes de error, 4 se atendieron perfectamente, aunque las consultas para aquellos no aparecen en la traza. De hecho, después de los 4 que salieron bien, tuve 4 excepciones lanzadas en rápida sucesión, esos 4 TAMBIÉN no aparecen en la traza (lo cual tiene sentido ya que si hubo un Tiempo de espera en la conexión, la consulta nunca debería haberse ejecutado, pero tampoco veo los intentos de conexión en la traza)

Entonces, en resumen, no tengo ni idea de esto. No puedo encontrar una razón para esos cientos de consultas que se ejecutan en rápida sucesión, pero creo que deben tener algo que ver con el problema.
Tampoco sé cómo diagnosticar los problemas de conexión ...
O cómo puede faltar el seguimiento de Profiler algunas consultas que según IIS pasaron bien ...

¿Alguna idea?

Esta es la información de excepción: 

System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.

System.Data.EntityException: The underlying provider failed on Open. ---> System.Data.SqlClient.SqlException: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
   at System.Data.ProviderBase.DbConnectionPool.GetConnection(DbConnection owningObject)
   at System.Data.ProviderBase.DbConnectionFactory.GetConnection(DbConnection owningConnection)
   at System.Data.ProviderBase.DbConnectionClosed.OpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory)
   at System.Data.ProviderBase.DbConnectionClosed.OpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory)
   at System.Data.SqlClient.SqlConnection.Open()
   at System.Data.EntityClient.EntityConnection.OpenStoreConnectionIf(Boolean openCondition, DbConnection storeConnectionToOpen, DbConnection originalConnection, String exceptionCode, String attemptedOperation, Boolean& closeStoreConnectionOnFailure)
   at System.Data.EntityClient.EntityConnection.OpenStoreConnectionIf(Boolean openCondition, DbConnection storeConnectionToOpen, DbConnection originalConnection, String exceptionCode, String attemptedOperation, Boolean& closeStoreConnectionOnFailure)
   --- End of inner exception stack trace ---
   at System.Data.EntityClient.EntityConnection.OpenStoreConnectionIf(Boolean openCondition, DbConnection storeConnectionToOpen, DbConnection originalConnection, String exceptionCode, String attemptedOperation, Boolean& closeStoreConnectionOnFailure)
   at System.Data.EntityClient.EntityConnection.Open()
   at System.Data.Objects.ObjectContext.EnsureConnection()
   at System.Data.Objects.ObjectQuery`1.GetResults(Nullable`1 forMergeOption)
   at System.Data.Objects.ObjectQuery`1.System.Collections.Generic.IEnumerable<T>.GetEnumerator()
   at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source)
   at System.Data.Objects.ELinq.ObjectQueryProvider.<GetElementFunction>b__1[TResult](IEnumerable`1 sequence)
   at System.Data.Objects.ELinq.ObjectQueryProvider.ExecuteSingle[TResult](IEnumerable`1 query, Expression queryRoot)
   at System.Data.Objects.ELinq.ObjectQueryProvider.System.Linq.IQueryProvider.Execute[S](Expression expression)
   at System.Linq.Queryable.FirstOrDefault[TSource](IQueryable`1 source)
   at MyProject.Controllers.SitesController.Feed(Int32 id) in C:\...\Controller.cs:line 38
   at lambda_method(ExecutionScope , ControllerBase , Object[] )
   at System.Web.Mvc.ReflectedActionDescriptor.Execute(ControllerContext controllerContext, IDictionary`2 parameters)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionMethod(ControllerContext controllerContext, ActionDescriptor actionDescriptor, IDictionary`2 parameters)
   at System.Web.Mvc.ControllerActionInvoker.<>c__DisplayClassa.<InvokeActionMethodWithFilters>b__7()
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionMethodFilter(IActionFilter filter, ActionExecutingContext preContext, Func`1 continuation)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionMethodWithFilters(ControllerContext controllerContext, IList`1 filters, ActionDescriptor actionDescriptor, IDictionary`2 parameters)
   at System.Web.Mvc.ControllerActionInvoker.InvokeAction(ControllerContext controllerContext, String actionName)
   at System.Web.Mvc.Controller.ExecuteCore()
   at System.Web.Mvc.MvcHandler.ProcessRequest(HttpContextBase httpContext)
   at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

Cualquier idea será enormemente apreciada.

¿Fue útil?

Solución

Memoria insuficiente

Es muy probable que sea un problema de memoria, quizás agravado o desencadenado por otras cosas, pero que sigue siendo un problema de memoria. existen otras dos posibilidades (menos probables) que debe verificar y eliminar primero (porque es fácil hacerlo):

Posibilidades fáciles de verificar:

  1. Puede tener " Cierre automático " habilitado: el cierre automático puede tener exactamente este comportamiento, sin embargo, es raro que se active. Para verificar esto, en SSMS, haga clic con el botón derecho en la base de datos de su aplicación, seleccione & Quot; Propiedades & Quot ;, y luego seleccione & Quot; Opciones & Quot; cristal. Mire el & Quot; Cierre automático & Quot; entrada y asegúrese de que esté configurado en False. Compruebe tempdb también.

  2. Los trabajos del Agente SQL pueden estar causándolo: Verifique el Registro del Historial del Agente para ver si hubo algún trabajo ejecutándose constantemente durante los eventos. Recuerde verificar también los trabajos de mantenimiento, ya que cosas como los índices de reconstrucción se mencionan frecuentemente como problemas de rendimiento mientras se ejecutan. Estos son candidatos poco probables ahora, solo porque normalmente no se verían afectados por el generador de perfiles.

Por qué parece un problema de memoria:

Si no muestran nada, entonces debe verificar si hay problemas de memoria. Sospecho que la memoria es la causa en su caso porque:

  • Tiene 1 GB de memoria: aunque técnicamente está por encima del mínimo para SQL Server, está muy por debajo de lo recomendado para SQL Server, y muy por debajo de lo que, en mi experiencia, es aceptable para la producción, incluso para un poco servidor cargado.

  • Está ejecutando IIS y SQL Server en el mismo cuadro: esto no se recomienda por sí solo, en gran parte debido a la disputa por la memoria que resulta, pero con solo 1 GB de memoria resulta en IIS, el aplicación, SQL Server, el sistema operativo y cualquier otra tarea y / o mantenimiento, todos luchando por muy poca memoria. La forma en que Windows maneja esto es dando memoria a los procesos activos quitándolos agresivamente de los procesos no activos. Puede llevar muchos segundos, o incluso minutos, que un proceso grande como SQL Server recupere suficiente memoria para poder atender completamente una solicitud en esta situación.

  • Profiler hizo que el 90% del problema desapareciera: esta es una gran pista de que la memoria es probablemente el problema, porque normalmente, cosas como Profiler tienen exactamente este efecto en este problema en particular: la tarea Profiler mantiene el SQL Server solo un little bit activo todo el tiempo. Con frecuencia, esta actividad es suficiente para mantenerla fuera del sistema operativo & "; Scavenger &"; lista, o al menos reduce un poco su impacto.

Cómo verificar la memoria como el culpable:

  1. Apague el generador de perfiles: está teniendo un efecto Heisenberg sobre el problema, por lo que debe apagarlo o no podrá ver el problema de manera confiable.

  2. Ejecute un Monitor de sistema (perfmon.exe) desde otro cuadro, que se conecta de forma remota al servicio de recopilación de rendimiento en el cuadro en el que se ejecutan su SQL Server e IIS. puede hacerlo más fácilmente eliminando primero las tres estadísticas predeterminadas (son solo locales) y luego agregue las estadísticas necesarias (a continuación), pero asegúrese de cambiar el nombre de la computadora en el primer menú desplegable para conectarse a su SQL cuadro.

  3. Envíe los datos recopilados a un archivo creando un " Counter Log " en perfmon. Si no está familiarizado con esto, lo más fácil es probablemente recopilar los datos en una pestaña o archivo separado por comas que pueda abrir con Excel para analizar.

  4. Configure su perfmon para recopilar en un archivo y agregue los siguientes contadores:

    - Procesador \% Tiempo de procesador [Total]

    - Disco físico \% Tiempo de inactividad [ para cada disco ]

    - Disco físico \ Promedio Longitud de la cola de disco [ para cada disco ]

    - Memoria \ Páginas / seg.

    - Memoria \ Page Reads / sec

    - Memoria \ MBytes disponibles

    - Interfaz de red \ Bytes total / seg [ para cada interfaz en uso ]

    - Proceso \% de tiempo de procesador [ ver abajo ]

    - Proceso \ Fallos de página / seg [ ver abajo ]

    - Proceso \ Conjunto de trabajo [ ver abajo ]

  5. Para los contadores de proceso (arriba), desea incluir el proceso sqlserver.exe, cualquier proceso de IIS y cualquier proceso de aplicación estable. Tenga en cuenta que esto SOLO funcionará para & Quot; estable & Quot; procesos. Los procesos que se vuelven a crear continuamente según sea necesario, no se pueden capturar de esta manera porque no hay forma de especificarlos antes de que existan.

  6. Ejecute esta colección en un archivo durante el tiempo que el problema ocurre con más frecuencia. Establezca el intervalo de recolección en algo cercano a 10-15 segundos. (esto recopila una gran cantidad de datos, pero necesitará esta resolución para seleccionar los eventos separados).

  7. Después de tener uno o más incidentes, detenga la recopilación y luego abra su archivo de datos recopilados con Excel. Probablemente tendrá que volver a formatear la columna de marca de tiempo para que sea visible y muestre horas, minutos y segundos. Use su registro de IIS para encontrar la hora exacta de los incidentes, luego mire los datos de perfmon para ver qué sucedía antes y después del incidente. En particular, desea ver si su conjunto de trabajo era pequeño antes y era grande después, con muchas fallas de página en el medio. Esa es la señal más clara de este problema.

SOLUCIONES:

Separe IIS y SQL Server en dos cuadros diferentes (preferido) o agregue más memoria al cuadro. Creo que 3-4 GB debería ser un mínimo.

¿Qué pasa con esas cosas extrañas de EF?

El problema aquí es que lo más probable es que sea periférico o que solo contribuya a su problema principal. Recuerde que Profiler hizo que el 90% de sus incidentes desaparecieran, así que lo que queda, puede ser un problema diferente, o puede ser solo el agravante más extremo del problema. Debido a su comportamiento, supongo que está cambiando su caché o hay algún otro mantenimiento en segundo plano de los procesos del servidor de aplicaciones.

Otros consejos

Compararía la marca de tiempo del tiempo de espera con el tiempo de ejecución de su copia de seguridad nocturna. Si coinciden, puede configurar su feed RSS para que sea estático durante ese tiempo.

Otra cosa para probar (aunque no es exactamente una respuesta) es ejecutar inmediatamente sp_who cuando obtiene una excepción de tiempo de espera. No atrapará todo (el proceso ofensivo podría realizarse para cuando ejecute esto) pero puede tener suerte.

También puede iniciar SQL Profiler cuando se dirija a casa por la noche y realice la actividad a la mañana siguiente si vuelve a ver el error. Solo asegúrese de no ejecutarlo desde el servidor (estoy bastante seguro de que le recuerda esto cuando se inicia).

EDITAR: Abordar su actualización.

¿EF está actualizando / creando su caché? Podría explicar la abundancia de consultas a la vez y por qué no hubo consultas en la base de datos más tarde.

Aparte de eso, parece que tienes un heisenbug. Lo único que puedo pensar para agregar es mucho más registro (a un archivo o al registro de eventos).

Huele una cosa cronificada que se ejecuta al mismo tiempo. Como dice RBarryYoung ... alguna copia de seguridad nocturna o podría ser otra cosa ¿Tiene acceso de root al servidor? ¿Puedes ver los crontabs?

¿Podría ser algún complemento de indexación de texto completo en la parte superior del servidor SQL que ejecuta sus procedimientos de reindexación cerca del momento en que experimenta los problemas?

En mi caso, cuando instalé sqlserver 2008 r2 sp3, el problema desaparece.

Servidor: Windows 7 + SqlServer 2008 R2 (edición de desarrollador) cliente: Raspberrypi 3B +, Asp.net Core + EF Core

Licenciado bajo: CC-BY-SA con atribución
No afiliado a StackOverflow
scroll top