Internet Explorer se cuelga por algunos segundos

A diferencia de los otros casos descritos, en esta oportunidad quien estaba en problemas era yo mismo, con un síntoma que seguro a alguno de ustedes le ha ocurrido antes. Veamos de que se trata.


Síntomas


Cada vez que abría una nueva instancia de Internet Explorer, como también al abrir una nueva pestaña de una instancia que ya llevase corriendo, algunas veces se demoraba una buena cantidad de segundos (entre 10 y 15 segundos) en quedar disponible para poder usarla. Si bien el proceso se creaba y se pintaba rápidamente (menos de 1 segundo), quedaba como “esperando” algo.


Esta es una ventana del navegador en ese estado intermedio de espera.



Una vez que la espera termina, el navegador funciona como se espera. Sin embargo, si se deja pasar un tiempo sin hacer nada en la ventana de éste, al tratar de usarlo nuevamente, ya sea creando un tabulador nuevo o incluso cerrando el proceso, otra vez debo esperar una cantidad de segundos similar a la anterior.


En resumen, mientras esté usando la ventana (haciendo clics), todo bien. Dejo de usarla un rato, hay que esperar para que reaccione.


Intención de detección del problema


Aunque sabía que no sería nada fácil encontrar el problema, hice mi intento usando [windbg] y atachándome al proceso una vez creara un nuevo tab mientras estaba “esperando”.


Un listado de los threads relevantes (0 y 5) y sus stacks correspondientes en el momento de espera mostraba lo siguiente.





   0  Id: 12f0.123c Suspend: 1 Teb: 7efdd000 Unfrozen
ChildEBP RetAddr
002ce690 7d4e286c ntdll!NtWaitForMultipleObjects+0x15
002ce738 7d94d299 kernel32!WaitForMultipleObjectsEx+0x11a
002ce794 02596029 user32!RealMsgWaitForMultipleObjectsEx+0x152
002ce7b4 0259632d ieui!CoreSC::Wait+0x49
002ce7dc 025960d8 ieui!CoreSC::WaitMessage+0x54
002ce7e8 4640994d ieui!WaitMessageEx+0x33
002ce818 463fabcc ieframe!CBrowserFrame::FrameMessagePump+0x199
002ce824 463fbc3b ieframe!BrowserThreadProc+0x3f
002ce848 463fbb89 ieframe!BrowserNewThreadProc+0x7b
002cf8b8 463fba39 ieframe!SHOpenFolderWindow+0x188
002cfae8 00401464 ieframe!IEWinMain+0x2d9
002cff2c 004012ff iexplore!wWinMain+0x2c1
002cffc0 7d4e7d2a iexplore!_initterm_e+0x1b1
002cfff0 00000000 kernel32!BaseProcessStart+0x28

5 Id: 12f0.12e8 Suspend: 1 Teb: 7efa9000 Unfrozen
ChildEBP RetAddr
02fee038 7d4d8c82 ntdll!ZwWaitForSingleObject+0x15
02fee0a8 7da3936a kernel32!WaitForSingleObjectEx+0xac
02fee0c4 7da3ba11 rpcrt4!UTIL_WaitForSyncIO+0x20
02fee0e8 7da3b9eb rpcrt4!UTIL_GetOverlappedResultEx+0x1d
02fee104 7da3b9a9 rpcrt4!UTIL_GetOverlappedResult+0x17
02fee124 7da3ad05 rpcrt4!NMP_SyncSendRecv+0x73
02fee14c 7da3af2d rpcrt4!OSF_CCONNECTION::TransSendReceive+0x7d
02fee1d4 7da3aea2 rpcrt4!OSF_CCONNECTION::SendFragment+0x2ae
02fee22c 7da3b1b9 rpcrt4!OSF_CCALL::SendNextFragment+0x1e2
02fee274 7da3b834 rpcrt4!OSF_CCALL::FastSendReceive+0x148
02fee290 7da3b7b7 rpcrt4!OSF_CCALL::SendReceiveHelper+0x5b
02fee2c0 7da37d3e rpcrt4!OSF_CCALL::SendReceive+0x41
02fee2cc 7da37cf0 rpcrt4!I_RpcSendReceive+0x24
02fee2e0 7dac01b6 rpcrt4!NdrSendReceive+0x2b
02fee6c8 71c4b685 rpcrt4!NdrClientCall2+0x22e
02fee6e0 71c4b644 netapi32!NetrLogonGetTrustRid+0x1c
02fee720 7da4af08 netapi32!I_NetlogonGetTrustRid+0x1e
02fee768 7da4ae60 rpcrt4!GetMachineAccountSid+0xcb
02fee780 7da3f97e rpcrt4!NormalizeAccountSid+0x4c
02fee88c 7da4aaa4 rpcrt4!LRPC_CASSOCIATION::OpenLpcPort+0x1e9
02feeb88 7da4a40b rpcrt4!LRPC_CASSOCIATION::CreateBackConnection+0x74
02feebc4 7da456fb rpcrt4!LRPC_CASSOCIATION::ActuallyDoBinding+0x32
02feec3c 7da3843a rpcrt4!LRPC_CASSOCIATION::AllocateCCall+0x190
02feec70 7da38366 rpcrt4!LRPC_BINDING_HANDLE::AllocateCCall+0x1f2
02feec9c 7da37a1c rpcrt4!LRPC_BINDING_HANDLE::NegotiateTransferSyntax+0xd3
02feecb4 7778c956 rpcrt4!I_RpcGetBufferWithObject+0x5b
02feecf8 7778c629 ole32!CRpcChannelBuffer::ClientGetBuffer+0x31c
02feed08 776c0e9e ole32!CRpcChannelBuffer::GetBuffer+0x20
02feed28 776c0f7a ole32!CAptRpcChnl::GetBuffer+0x209
02feed8c 7dac0fda ole32!CCtxComChnl::GetBuffer+0x1e5
02feeda8 7dac0f89 rpcrt4!NdrProxyGetBuffer+0x47
02fef190 776a3717 rpcrt4!NdrClientCall2+0x173
02fef1a8 7778b6e4 ole32!IClassFactory_RemoteCreateInstance_Proxy+0x1c
02fef1c4 776ad8ac ole32!IClassFactory_CreateInstance_Proxy+0x41
02fef24c 776aaf7e ole32!CServerContextActivator::CreateInstance+0x175
02fef28c 776ad9b6 ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7
02fef2e0 776ad92d ole32!CApartmentActivator::CreateInstance+0x110
02fef300 776acb27 ole32!CProcessActivator::CCICallback+0x6d
02fef320 776acad8 ole32!CProcessActivator::AttemptActivation+0x2c
02fef35c 776ada17 ole32!CProcessActivator::ActivateByContext+0x4f
02fef384 776aaf7e ole32!CProcessActivator::CreateInstance+0x49
02fef3c4 776aaf19 ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7
02fef614 776aaf7e ole32!CClientContextActivator::CreateInstance+0x8f
02fef654 776ab10f ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7
02fefe08 776a679a ole32!ICoCreateInstanceEx+0x3f8
02fefe3c 776a6762 ole32!CComActivator::DoCreateInstance+0x6a
02fefe60 776a6963 ole32!CoCreateInstanceEx+0x23
02fefe90 4635a747 ole32!CoCreateInstance+0x3c
02fefec0 4638f691 ieframe!SHCoCreateInstanceAC+0x9e
02feff08 463c167a ieframe!WinList_RegisterPending+0x2c
02feff4c 463ee4b9 ieframe!CTabWindow::_RegisterPendingWindow+0x149
02feffb8 7d4dfe21 ieframe!CTabWindow::_TabWindowThreadProc+0x99
02feffec 00000000 kernel32!BaseThreadStart+0x34


El thread 0 es el thread principal y aparentemente no está haciendo mucho, salvo esperar que el kernel le avise que ciertos eventos han ocurrido.


Sin embargo, el thread 5 sí está haciendo algo y es exactamente lo que yo le había pedido. Crear un tabulador. Esto lo puedo inferir por las llamadas a las funciones con nombres acordes, como se puede apreciar ahora





<cortado …>
02feff4c 463ee4b9 ieframe!CTabWindow::_RegisterPendingWindow+0x149
02feffb8 7d4dfe21 ieframe!CTabWindow::_TabWindowThreadProc+0x99
02feffec 00000000 kernel32!BaseThreadStart+0x34

Ok, tenemos el thread que crea el tabulador. ¿qué más?


Mirando el stack, se puede observar creación de objetos COM, posiblemente una creación de contexto de COM o una reutilización de uno existente (no estoy del todo seguro de cual opción), una llamada RPC, interacción con el sub-sistema de Windows (kernel32.dll) y el kernel (ntdll.dll).


A diferencia de una revisión de aplicaciones como asp.net o asp tradicional, donde uno espera encontrar código del cliente que no está optimizado y que consume recursos, en esta oportunidad no había código de terceros. El camino se veía difícil.


Golpes de suerte


Con dos sucesivos golpes de suerte logré dar con el problema, pero jamás podría haberlo detectado sin un post de Mark Russinovich, donde él experimentó un problema similar. El primer golpe de suerte fue elegir alguna función que pareciese sospechosa y luego, livear en internet. La función elegida fue GetMachineAccountSid y la búsqueda retornó este post en primera opción.


http://blogs.technet.com/markrussinovich/archive/2006/08/31/453100.aspx
The Case of the Process Startup Delays


Con ese título del post, claramente estábamos enfrentando el mismo problema. Eso sí, la diferencia es que Mark sabe reconocer el problema, pero uno debe apelar a la suerte y a los buscadores de internet. [:)]


Haciendo pruebas similares a las del post mencionado, obtuve respuestas similares.



Bien. Traté de atacharme a lsass.exe (local security authority subsystem) con nefastos resultados. Una vez atachado windbg a lsass, hice una mala maniobra y windbg dejó de responder, haciendo que el sistema quedase medianamente bloqueado (respondía muy lento) ya que muchos procesos depende de lsass.exe. Como no hubo más opción que matar windbg, esto traería como consecuencia que el proceso que se estaba debugueando también moriría. Y si muere lsass.exe, el sistema operativo te pide amablemente reiniciar, con una pantalla similar a la pantalla del virus que atacaba XP antes de SP2 y que te daba 48 segundos para cerrar todo.


La consecuencia.



Como dirían en algunos programas de televisión; “niños, no traten de hacer esto en casa,” o mejor dicho, no lo hagan mientras visitan a un cliente y deben trabajar con su equipo.


Resolución


A diferencia del post de Mark, en donde el causante del problema era Defender, en este caso no había un tercer involucrado que remover del sistema.


La solución no fue la más elegante, pero no tuve más alternativa que ejecutar Internet Explorer en el contexto de un usuario local de la máquina, para así evitar que se trate de obtener información desde el dominio, el cual no puede ser alcanzado.


Lamentablemente esto trajo como consecuencia que no pudiese accesar a mi historial ni favoritos. Espero que cuando logre conectarme al dominio se acaben los problemas.


Saludos,
Patrick

Signos vitales de un servidor: Parte III (disco)

Después de unos días de descanso debido a las fiestas ampliamente conocidas, continuamos con la tercera entrega de la serie de monitoreo de signos vitales de un servidor, en la cual presentaremos la información necesaria para detectar problemas de rendimiento en las unidades lógicas de disco de un servidor.


Si bien es posible determinar problemas en unidades físicas, las diferentes configuraciones físicas de arreglos RAID 0, 1, 5, 1+0 y 0+1 y la creación posterior de unidades lógicas en el arreglo, hace muy difícil, si es que no imposible, el determinar si es o no un disco físico específico.


Antes de comenzar, hago un mini corte para recomendar este link de una presentación de David Solomon sobre cómo maneja la memoria Windows y como hacer un troubleshooting básico de los problemas. Además, se da tiempo de romper algunos mitos. Definitivamente un video imperdible. Está en inglés y dura 1 hora y 37 minutos.


http://www.microsoft.com/uk/technet/itsshowtime/sessionh.aspx?videoid=64


Diferentes caminos


Para la verificación de los contadores de disco, existen dos caminos conocidos. Uno de ellos el difícil y otro mucho más simple y agnóstico del hardware.


El primer camino, el cual NO veremos aquí corresponde a obtener información de los IOs de los discos, calcular la cantidad de operaciones de lectura y escritura que se realizan por cada tipo de RAID, la cantidad de discos físicos (ejes) involucrados en el RAID y hacer una cantidad importantes de cálculos y asumir con poca certeza algunas constantes o valores.


El segundo camino, mucho más simple, es agnóstico del tipo de RAID, la cantidad de discos y otras variables. ¿Qué es lo que mide? muy simple y básico:


¿Cuánto tiempo se demora el sistema de discos en realizar una operación de escritura o lectura?


Si se demora “mucho,” hay un problema. Si se demora “poco,” estamos bien. Si tienes picos elevados constantes, podemos estar en presencia de algún inconveniente o escasez de capacidad de procesamiento.


Además de la información relacionada con escrituras y lecturas, se debe complementar con información general del disco como el porcentaje de tiempo disponible y largo de la cola de requerimientos.


Veamos los contadores y contra qué compararlos, es decir, que es “bueno” y “malo.”


Nota: Antes de comenzar aclaro que cuando digo disco “malo,” no estoy mencionando que el disco está malo físicamente o que presenta alguna falla sino que realmente me refiero a que el disco no responde de acuerdo a lo que es espera de él, generalmente producto de una tasa muy elevada de requerimientos.


Contadores


Los contadores a medir del objeto Logical Disk, para la instancia específica (c:, d:, etc.), son los siguientes:




  • Avg Disk Sec/read: milisegundos en que una operación de lectura es llevada a cabo.



  • Avg disk Sec/write: milisegundos en que una operación de escritura es llevada a cabo.



  • % Idle time: porcentaje de tiempo que el disco está desocupado.



  • Avg disk queue length: largo promedio de la cola de requerimientos del disco



  • Current disk queue length: largo actual de la cola de requerimientos del disco


¿Contra que los comparamos?


Los dos primeros contadores se comparan contra la misma tabla de valores, la cual despliego a continuación:















Valor medido Significado
entre 1 milisegundo y 15 milisegundos Perfecto estado
entre 16 milisegundos y 25 milisegundos Se debe monitorear
más de 25 milisegundos Disco degradado

Se deben considerar valores promedios. Es esperable que un disco tenga picos por sobre los 25 milisegundos pero el valor promedio debe ser bajo.


Nota: Si tienes un storage con caché de escritura, deberás ser más estricto en las comparaciones y reducir un poco los valores. Esto se debe a que el caché de escritura mejora sustancialmente el rendimiento. Si antes 15 ms era el tope para considerar el valor como perfecto, entonces si mides 15 ms y tienes caché habilitado, no estarás dentro del grupo de perfecto estado sino que el rendimiento será medio y deberás monitorear la actividad.


Anécdota: El valor más alto que he presenciado en algunos casos ha sido de más de 900 milisegundos. Por supuesto, el servicio que se estaba exponiendo estaba severamente afectado, con tiempos de respuesta muy bajos.


El contador del tiempo porcentaje de tiempo disponible es simple también. Más de 50%, perfecto estado. Entre 20% y 50%, se deberá monitorear y menor a 20%, el disco está degradado.


Por último, para los contadores de largo de cola de requerimientos promedio y actual, estos dos valores se comparan y calculan de la misma forma. Si la cantidad de discos físicos que componen el arreglo de discos es conocida, se deberá comparar contra el valor medido menos la cantidad de discos y dividirlo por dos.


Por ejemplo: Si el valor medido del largo promedio de la cola de requerimientos es 25 y tengo 10 discos en el arreglo, la formula nos retorna: (25-10)/2 = 7,5.


Este valor es menor a 1, el rendimiento es excelente. Entre 1 y 3, se deberá monitorear. Mayor a 3, crítico o degradado.


Por supuesto, la formula presenta inconvenientes cuando los valores medidos son menores a la cantidad de discos, pero en ese caso el disco claramente no tiene problemas.


¿Qué sucede si no conozco la cantidad de discos? y bueno, en ese caso se recomienda dividir por 2 el valor medido en el contador y aplicar la misma regla de comparación. Entendemos que no es un valor fidedigno, pero tampoco es “tan errado.” Para el mismo ejemplo, 25/2  es 12,5, un valor mayor a 7,5, pero igual de malo de acuerdo a el parámetro de comparación.


Como pueden ver, monitorear un disco es muy simple. Si no responde en tiempos breves, claramente le estamos pidiendo más de lo que puede dar.


Queda pendiente una o dos entregas más de signos vitales, las que llegarán espero durante este mes.


Saludos,
Patrick