Alto consumo de memoria y cursores de datos

Sorpresas te llevas en la vida, siempre. A pesar de lo que parezca, hoy no ando sermoneador ni nada por el estilo. Es sólo que no se me ocurre como comenzar este post así que escribo lo primero que se me ocurre [:)]. Total, lo interesante viene ahora.


Viaje de emergencia, aplicación ASP con [OOM], servicio interrumpido.
Resumen: problemas… un poco de entretención para unos meses muy aburridos.


Síntomas


Como mencionaba, tenemos una aplicación ASP que de vez en cuando lanza excepciones por falta de memoria, mas conocidos como error 500 ASP 147. Obviamente con el reinicio del proceso, todo vuelve a la normalidad, pero luego de la calma, llega la tormenta.


Como ya es costumbre, se capturaron algunos dumps de memoria cuando se estaba produciendo el error y se analizaron. Los resultados fueron sorprendentes, los que pasan a ser mostrados ahora.


Lo primero muy interesante es que el dump apenas sobrepasaba los 100 megabytes. Un dump contiene, sin entrar en grandes detalles, los datos privados del proceso y las librerías cargadas entre otras cosas. Si son un poco más de 100 megabytes, ¿cómo es posible que haya falta de memoria?. El administrador de tareas confirmaba que el proceso estaba utilizando algo más de 100 megabytes en working set y un poco menos en memoria privada


¿Entonces?


[windbg] entra a ayudarnos. Revisando el estado de cada heap, nos encontramos con lo que muestra el bloque de más abajo. Hay muchas columnas y muchos datos, pero fijemos la atención en las columnas que hacen mención a la memoria reservada y comprometida.


Recordemos que en un sistema operativo Windows, la memoria puede estar en tres estados: libre, reservada y comprometida. Para que una aplicación la pueda utilizar necesita primero reservarla, y luego comprometerla. Después de usarla, la debe des-comprometer (fea palabra, lo sé) y luego liberar (des-reservar, también es fea).





  Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock  Fast
(k) (k) (k) (k) length blocks cont. heap
—————————————————————————–
00080000 00000002 15360 13424 14512 2362 514 137 0 9d L
External fragmentation 17 % (514 free blocks)
00180000 00008000 64 12 12 10 1 1 0 0
002b0000 00001002 22080 9560 17536 1629 231 124 25 5b L
External fragmentation 17 % (231 free blocks)
Virtual address fragmentation 45 % (124 uncommited ranges)
00550000 00000002 1024 20 20 2 1 1 0 0 L
00690000 00001002 256 32 32 2 1 1 0 0 L
01bb0000 00001002 256 12 12 4 1 1 0 0 L
01bf0000 00001002 39872 11200 29608 722 62 60 0 7 LFH
01c30000 00001002 256 12 12 4 1 1 0 0 L
01c70000 00001002 256 12 12 4 1 1 0 0 L
<recortado>
02630000 00001002 256 12 12 2 1 1 0 0 L
02670000 00001002 256 12 12 4 1 1 0 0 L
02730000 00001002 64 32 32 4 1 1 0 0 L
02a20000 00001002 3328 2084 2396 110 23 16 0 0 LFH
02a60000 00001002 19968 7164 8076 35 6 10 21 0 LFH
02f60000 00001003 1280 1152 1152 2 1 1 0 bad
03470000 00001003 1280 512 512 1 1 1 0 bad
034b0000 00001003 1280 524 524 2 1 1 0 bad
034f0000 00001003 256 96 96 0 0 1 0 bad
03730000 00001003 1280 356 356 1 1 1 0 bad
03970000 00001003 1280 264 264 0 0 1 0 bad
049b0000 00001003 256 204 204 3 1 1 0 bad
049f0000 00001003 130304 128 300 63 11 12 0 bad
04a30000 00001003 441600 112 188 101 11 12 0 bad <-éste
04a70000 00001003 167204 352 424 264 49 67 0 bad
04ab0000 00001003 465716 128 36532 103 20 27 0 bad
04af0000 00001003 469708 164 1696 92 13 32 0 bad
04b30000 00001003 46312 324 328 254 47 65 0 bad
04b70000 00001003 9700 372 372 348 62 64 0 bad
039c0000 00001002 64 16 16 2 1 1 0 0 L
04c30000 00001003 256 148 148 92 36 1 0 bad
<recortado>

En el listado anterior, vemos que hay un par de heaps que han reservado (memoria en estado reservado) más de 400 megabytes, pero que sólo están utilizando (memoria en estado comprometido) un poco más de 100 kilobytes. Entre varios, el heap 04a30000, indicado más arriba en negrilla y con la palabra “<- éste”, es uno de los más grandes.


Veamos el detalle de este heap y sus segmentos, listados a continuación.





Index   Address  Name      Debugging options enabled
111: 04a30000
Segment at 04a30000 to 04a70000 (00010000 bytes committed)
Segment at 0f940000 to 0fa40000 (00003000 bytes committed)
Segment at 0fa40000 to 0fc40000 (00001000 bytes committed)
Segment at 100d0000 to 104d0000 (00001000 bytes committed)
Segment at 104d0000 to 10cd0000 (00001000 bytes committed)
Segment at 10cd0000 to 11cd0000 (00001000 bytes committed)
Segment at 11cd0000 to 13cd0000 (00001000 bytes committed)
Segment at 13cd0000 to 17cd0000 (00001000 bytes committed)
Segment at 17ed0000 to 1fed0000 (00001000 bytes committed)
Segment at 4dbd0000 to 55bd0000 (00001000 bytes committed)
Segment at 5bb60000 to 5eb60000 (00001000 bytes committed)

Mmm… mmm…mmm…mmm (esto me recuerda una canción de hace unos años), la mayoría de ellos no tiene más de 4 kilobytes usados para bloques de varios megabytes reservados. Si las matemáticas no te ayudan ahora, 1000 en hexadecimal es equivalente a 4096 en decimal.


Análisis de la situación


Recordemos que el manejo de la memoria lo realiza generalmente el sistema operativo aunque algunas aplicaciones pueden utilizar sus propios manejadores de memoria. Desde código ASP (VBScript) o Visual Basic 6.0, como también desde código manejado NO es posible trabajar a este nivel con la memoria. Lo anterior es un problema en un manejador de memoria.


Si no es ASP, VB. 6.0, ¿qué puede ser? (considerando que no hay componentes desarrollados por el cliente en C o C++)


La respuesta la da [DebugDiag]. Quien creo el heap es “Microsoft Data Access Runtime”, es decir, MDAC. Revisando la versión instalada, comprobamos que es la última con Windows Server 2003 SP2. El camino se pone difícil.


Investigación y resolución


Involucrando a las personas adecuadas, aprendimos que este comportamiento es considerado “esperado” cuando se cumplen las siguientes condiciones:



  • Se utilizan recordset del lado del cliente (client-side cursor)

  • Se obtienen muchos datos, muchos datos de una tabla

Ok ¿client-side cursor?¿que significa “muchos datos”?


“Cliente” es quien consulta la base de datos, que para este caso es IIS/ASP. En ese caso, los datos se llevan al cliente para ser luego procesados.


Después de investigar en el código, se encontró que una consulta estaba retornando más de 2 millones de registros. Eso es mucho [:)]


Reproducción


Decidido a demostrarlo, procedí a hacer unas pruebas con el siguiente código en mi “servidor.”



Y le agregué a mi tabla algo así como 4 millones de registros.


Después de varias ejecuciones, tanto en paralelo como en serie, los contadores de memoria reservada, comprometida y utilización de procesador mostraron esto:



Se puede ver que la memoria comprometida (verde) llegó como mucho hasta 300 megabytes, pero la memoria reservada (roja) aumentó sin mostrar intención de disminuir, llegando casi hasta 900 megabytes.


¿Cuál es la explicación a que no reutilice la memoria reservada y siga reservando más? Al menos yo no tengo la respuesta.


¿Que sucede cuando llegue a 2 gigabytes? [OOM]


Conclusiones


1.- Nunca desplegar “muchos” registros en una página. Mejor aún, nunca pedir muchos registros a la base de datos.


2.- Utilicen server-side cursors. Hagan la prueba con el mismo código y comparen los resultados. [;)]


Saludos,
Patrick

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

Traza de asp.net y el consumo de memoria

El siguiente caso a presentar está relacionado con el alto consumo de memoria de una aplicación. Como el título lo dice, está relacionado con el uso de la traza de asp.net (trace en web.config.)


El escenario era similar a lo descrito ahora. La aplicación analizada empezaba a consumir memoria y aunque tenía momentos donde la liberaba, la impresión general era que en el largo plazo, siempre subía. Este es un típico comportamiento de un memory leak o pérdida de memoria; la tendencia al alza, aunque con momentos donde baja un poco.


Como ya es tradición, un dump del proceso y mi amigo [windbg] nos darían las pistas necesarias. También nos apoyamos en performance monitor, pero hay veces que ya sabes que es una pérdida de memoria y éste no te dirá mucho más de lo que ya sabes.


Con el dump en mis manos, hacemos una revisión del proceso afectado y el estado de la memoria virtual del éste.


Recolección de información general


Tamaño del dump: ~300 MB. No es muy grande, pero tampoco es descartable. Tradicionalmente se espera a que la memoria privada del proceso llegue al menos hasta 500 MB para declararlo como sospechoso.


Información del proceso:





System Uptime: 180 days 15:52:41.140
Process Uptime: 0 days 2:08:23.000
Kernel time: 0 days 0:00:13.000
User time: 0 days 0:08:48.000

El sistema operativo lleva corriendo 180 días sin reiniciarse. El proceso en cuestión lleva del orden de 2 horas y 8 minutos corriendo y que ha consumido 13 segundos en modo privilegiado (kernel) y 8 minutos y 48 segundos en modo usuario.

Con 8 minutos de procesamiento ya llegó a 300 MB. Interesante.







El estado de la memoria virtual concuerda con el tamaño del dump, reflejado gráficamente en la imagen de la derecha, la cual pueden pinchar para agrandar.

Efectivamente hay aproximadamente 300 MB de memoria virtual, de los cuales casi 190 son de memoria manejada.


Memoria manejada


Haciendo una revisión de los heaps del GC, obtenemos la información de la siguiente lista. El servidor tiene 4 procesadores por lo que se crean cuatro heaps del GC, cada uno con sus propias generaciones, heaps efímeros y heaps de objetos grandes.





Number of GC Heaps: 4
——————————
Heap 0 (0x000d01c8)
generation 0 starts at 0x121135c8
generation 1 starts at 0x12109a44
generation 2 starts at 0x102d0030
ephemeral segment allocation context: none
segment begin allocated size reserved
0x102d0000 0x102d0030 0x121135d4 0x01e435a4(31,733,156) 0x00d79000
Large object heap starts at 0x202d0030
segment begin allocated size reserved
0x202d0000 0x202d0030 0x205d2168 0x00302138(3,154,232) 0x00cdd000
Heap Size 0x2245770(35,936,112)
——————————
Heap 1 (0x000d08d8)
generation 0 starts at 0x16009a28
generation 1 starts at 0x15eaacac
generation 2 starts at 0x142d0030
ephemeral segment allocation context: none
segment begin allocated size reserved
0x142d0000 0x142d0030 0x16009a34 0x01d39a04(30,644,740) 0x014c7000
Large object heap starts at 0x212d0030
segment begin allocated size reserved
0x212d0000 0x212d0030 0x21449a38 0x00179a08(1,546,760) 0x00e66000
Heap Size 0x1f2b4a0(32,683,168)
——————————
Heap 2 (0x000d13d8)
generation 0 starts at 0x24461404
generation 1 starts at 0x243e6e2c
generation 2 starts at 0x182d0030
ephemeral segment allocation context: none
segment begin allocated size reserved
0x182d0000 0x182d0030 0x1998c7dc 0x016bc7ac(23,840,684) 0x028ef000
0x242d0000 0x242d0030 0x24461410 0x001913e0(1,643,488) 0x033c4000
Large object heap starts at 0x2a2d0030
segment begin allocated size reserved
0x2a2d0000 0x2a2d0030 0x2a2d0030 0x00000000(0) 0x047df000
Heap Size 0x198fb8c(26,803,084)
——————————

Heap 3 (0x000d1ca0)
generation 0 starts at 0x087954cc
generation 1 starts at 0x083dd820
generation 2 starts at 0x1c2d0030
ephemeral segment allocation context: none
segment begin allocated size reserved
0x1c2d0000 0x1c2d0030 0x1df48b8c 0x01c78b5c(29,854,556) 0x02310000
0x08330000 0x08330030 0x087954d8 0x004654a8(4,609,192) 0x01fff000
Large object heap starts at 0x232d0030
segment begin allocated size reserved
0x232d0000 0x232d0030 0x2344ed50 0x0017ed20(1,568,032) 0x00e61000
0x0edc0000 0x0edc0030 0x0f195f40 0x003d5f10(4,022,032) 0x00c2a000
Heap Size 0x277ac50(41,397,328)
——————————
Reserved segments:
——————————
GC Heap Size 0x827b3ec(136,819,692)

De esta información se puede ver que hay muchos objetos en generación 2, lo que significa que hay objetos que no se han liberado y han ido envejeciendo más de lo necesario.


¿Qué hay en la memoria?


Haciendo un vaciado estadístico de los objetos, utilizando [windbg] y sos, obtenemos un listado como el de a continuación, donde se ha eliminado parte del comienzo y sólo se ha dejado el final, que contiene la información relevante para el caso.





MT        Count TotalSize Class Name
…..<recortado por el bien de esta página>…
0x028665f0 22,807 273,684 System.Xml.Xsl.EndEvent
0x02784adc 14,800 296,000 System.Data.DataRowCollection
0x027844dc 14,800 296,000 System.Data.DataRowBuilder
0x027862d4 14,911 298,220 System.Data.ColumnQueue
0x02782a74 11,824 331,072 System.ComponentModel.CollectionChangeEventHandler
0x0230159c 14,866 356,784 System.Xml.NameTable/Entry
0x02925aec 7,847 408,044 System.Xml.Xsl.XsltCompileContext
0x02926bfc 11,589 417,204 System.Xml.XPath.XPathChildIterator
0x02863d04 8,692 417,216 System.Xml.XPath.ChildrenQuery
0x027846d4 14,800 473,600 System.Data.RecordManager
0x0278001c 14,800 473,600 System.Data.ConstraintCollection
0x027842e4 14,913 477,216 System.ComponentModel.PropertyDescriptorCollection
0x0280cddc 16,754 670,160 System.Xml.XPath.XPathWhitespace
0x0280c924 10,044 682,992 System.Xml.XPath.XPathElement
0x02866564 22,807 729,824 System.Xml.Xsl.BeginEvent
0x0252ebe4 14,800 769,600 System.Data.DataColumnCollection
0x79bda488 14,813 888,780 System.Threading.ReaderWriterLock
0x79bab93c 17,498 909,896 System.Collections.Hashtable
0x02923770 28,877 924,064 System.Xml.DocumentXPathNavigator
0x027882e4 40,203 964,872 System.Data.Common.StringStorage
0x0280cba4 21,157 1,015,536 System.Xml.XPath.XPathAttribute
0x0278489c 29,600 1,184,000 System.Data.DataRelationCollection/DataTableRelationCollection
0x01ba2c28 17,561 2,839,896 System.Collections.Hashtable/bucket[]
0x0252e4b0 14,800 3,433,600 System.Data.DataTable
0x79ba2ee4 145,618 3,494,832 System.Collections.ArrayList
0x0278670c 54,976 3,518,464 System.Data.DataColumnPropertyDescriptor
0x01ba2964 24,879 5,024,760 System.Int32[]
0x0278513c 136,364 5,454,560 System.Data.DataRow
0x0252f5d0 54,760 7,009,280 System.Data.DataColumn
0x01ba26b0 1,262 8,513,840 System.Byte[]
0x000cff48 2,829 14,897,824 Free
0x79b94638 238,884 23,296,388 System.String
0x01ba209c 235,235 40,966,392 System.Object[]
Total 1,509,853 objects, Total size: 136,798,976

Existe un poco más de 1,5 millones de objetos en memoria, que consumen cerca de 136 MB, similar al resultado entregado en la lista anterior.


De esos 1,5 millones de objetos, existe una gran cantidad de strings y arreglos de objeto, como también de filas de datos y columnas de datos. Este comportamiento se presenta cuando se han creado Datasets y no se han liberado.


Un DataSet contiene filas y columnas, y en cada celda encontramos objetos de los tipos básicos como strings, enteros, decimales, objetos, etc. Por lo tanto, estos objetos que se ven al final no viven solos sino que están referenciados desde otro objeto, como podría ser un dataset. No significa que todos estén referenciados, pero con 136 mil filas (DataRow) y 54 mil columnas (DataColumn), varios de esos miles de objetos si lo están.


¿Cuantos DataSets hay?





MT         Count TotalSize Class Name
0x0252ce84 1,597 127,760 System.Data.DataSet
Total 1,597 objects, Total size: 127,760

Bueno, tomemos uno al azar y veamos donde nos lleva. Elegimos el objeto en la posición de memoria 0x0834d148.





Name: System.Data.DataSet
MethodTable 0x0252ce84
EEClass 0x0275b43c
Size 80(0x50) bytes
GC Generation: 2
mdToken: 0x0200003b (c:\windows\assembly\gac\system.data\1.0.5000.0__b77a5c561934e089\system.data.dll)
FieldDesc*: 0x0252c4b4
MT Field Offset Type Attr Value Name
0x0252c23c 0x4000583 0x4 CLASS instance 0x00000000 site
0x0252c23c 0x4000584 0x8 CLASS instance 0x00000000 events
0x0252c23c 0x4000582 0 CLASS shared static EventDisposed
>> Domain:Value 0x000c4ac8:NotInit 0x00138380:0x1c331c58 <<
0x0252ce84 0x40003d3 0xc CLASS instance 0x15cee704 defaultViewManager
0x0252ce84 0x40003d4 0x10 CLASS instance 0x0834d198 tableCollection
0x0252ce84 0x40003d5 0x14 CLASS instance 0x0834d220 relationCollection
0x0252ce84 0x40003d6 0x18 CLASS instance 0x00000000 extendedProperties
0x0252ce84 0x40003d7 0x1c CLASS instance 0x1c331c30 dataSetName
0x0252ce84 0x40003d8 0x20 CLASS instance 0x102d0224 _datasetPrefix
0x0252ce84 0x40003d9 0x24 CLASS instance 0x102d0224 namespaceURI
0x0252ce84 0x40003da 0x40 System.Boolean instance 0 caseSensitive
0x0252ce84 0x40003db 0x28 CLASS instance 0x1c2e69c8 culture
0x0252ce84 0x40003dc 0x41 System.Boolean instance 1 enforceConstraints
0x0252ce84 0x40003dd 0x42 System.Boolean instance 0 fInReadXml
0x0252ce84 0x40003de 0x43 System.Boolean instance 0 fInLoadDiffgram
0x0252ce84 0x40003df 0x44 System.Boolean instance 0 fTopLevelTable
0x0252ce84 0x40003e0 0x45 System.Boolean instance 0 fInitInProgress
0x0252ce84 0x40003e1 0x46 System.Boolean instance 1 fEnableCascading
0x0252ce84 0x40003e2 0x47 System.Boolean instance 0 fIsSchemaLoading
0x0252ce84 0x40003e3 0x2c CLASS instance 0x00000000 rowDiffId
0x0252ce84 0x40003e4 0x48 System.Boolean instance 0 fBoundToDocument
0x0252ce84 0x40003e5 0x30 CLASS instance 0x00000000 onPropertyChangingDelegate
0x0252ce84 0x40003e6 0x34 CLASS instance 0x00000000 onMergeFailed
0x0252ce84 0x40003e7 0x38 CLASS instance 0x00000000 onDataRowCreated
0x0252ce84 0x40003e8 0x3c CLASS instance 0x00000000 onClearFunctionCalled
0x0252ce84 0x40003e9 0 CLASS shared static zeroTables
>> Domain:Value 0x000c4ac8:NotInit 0x00138380:0x1c331c20 <<

Mmm, nada más que un dataset. No se si podría haber encontrado otra cosa [:)]. Veamos el nombre de éste, en la posición 0x1c331c30 (línea blanca arriba).





String: NewDataSet

[:s]. El nombre genérico no da pistas para encontrar alguna parte del código que lo esté creando. Vemos entonces quién lo está apuntando.





Scan Thread 10 (0x1cac)
Scan Thread 16 (0xa00)
Scan Thread 17 (0x1908)
Scan Thread 5 (0xa0c)
Scan Thread 4 (0x1dcc)
Scan Thread 19 (0x1a6c)
Scan Thread 3 (0x1584)
Scan Thread 2 (0x444)
Scan Thread 20 (0x15f4)
ESP:36ff548:Root:0x1c6b59a8(System.Threading.Thread)->0x15cecad4(System.Runtime.Remoting.Messaging.IllogicalCallContext)->0x15cecae0(System.Collections.Hashtable)->0x15cecb14(System.Collections.Hashtable/bucket[])->0x15cec81c(System.Web.HttpContext)->0x15cec608(System.Web.Hosting.ISAPIWorkerRequestInProcForIIS6)->0x182d81c4(System.Web.HttpWorkerRequest/EndOfSendNotification)->0x14339e70(System.Web.HttpRuntime)->0x182d7fac(System.Web.Util.Profiler)->0x14358454(System.Collections.ArrayList)->0x1d89d7b0(System.Object[])->0x834d148(System.Data.DataSet)
Scan Thread 22 (0x1098)
Scan Thread 24 (0xcd8)
…..<recortado por el bien de esta página>…
Scan Thread 67 (0x1938)
Scan Thread 54 (0x618)
Scan HandleTable 0xc9ec0
Scan HandleTable 0xcd008
Scan HandleTable 0x147008

El thread 20, que está procesando un requerimiento en la extensión ISAPI de asp.net en IIS6 (System.Web.Hosting.ISAPIWorkerRequestInProcForIIS6) tiene una referencia fuerte al objeto. Vemos también un HashTable, el Contexto y Runtime de http, los cuales se pueden considerar normales en el ciclo de vida de un requerimiento web.


Sin embargo, hay un invitado especial en esta lista de referencias. Éste es System.Web.Util.Profiler, del cual no hay mucha información disponible, pero después de examinarlo, ya podemos inferir de quién se trata. Veamos su contenido.





Name: System.Web.Util.Profiler
MethodTable 0x021c49d0
EEClass 0x0215912c
Size 28(0x1c) bytes
GC Generation: 2
mdToken: 0x0200029d (c:\windows\assembly\gac\system.web\1.0.5000.0__b03f5f7f11d50a3a\system.web.dll)
FieldDesc*: 0x021c4704
MT Field Offset Type Attr Value Name
0x021c49d0 0x4001076 0x8 System.Int32 instance 1478 _requestNum
0x021c49d0 0x4001077 0xc System.Int32 instance 7500 _requestsToProfile
0x021c49d0 0x4001078 0x4 CLASS instance 0x14358454 _requests
0x021c49d0 0x4001079 0x14 System.Boolean instance 0 _pageOutput
0x021c49d0 0x400107a 0x15 System.Boolean instance 1 _isEnabled
0x021c49d0 0x400107b 0x16 System.Boolean instance 1 _oldEnabled
0x021c49d0 0x400107c 0x17 System.Boolean instance 0 _localOnly
0x021c49d0 0x400107d 0x10 System.Int32 instance 0 _outputMode

Recordando las propiedades de la traza de asp.net, podemos ver asombrosas similitudes con las propiedades. Veamos la definición de la traza en el archivo web.config. La información oficial dice:





<trace
enabled=”true|false”
localOnly=”true|false”
pageOutput=”true|false”
requestLimit=”integer”
mostRecent=”true|false”
writeToDiagnosticsTrace=”true|false”
traceMode=”SortByTime|SortByCategory”
/>

El dump dice que la traza estaba habilitada (_isEnabled), no estaba local (_localOnly), que tenía marcado para almacenar hasta 7.500 requerimientos (segunda línea blanca) y que habían 1478 almacenados (primera línea blanca). El resto de las propiedades las pueden chequear ustedes. Recordemos que habían 1597 DataSets en memoria.


El objeto _requests es un System.Collections.ArrayList y los 1478 objetos dentro suman casi la totalidad de memoria manejada, que si bien recordarán, sumaba cerca de 136 MB.





sizeof(0x14358454) = 91,258,512 (0x5707e90) bytes (System.Collections.ArrayList)

Entonces, la condición de memoria elevada, se da en parte porque hay ~90 MB de objetos referenciados por la traza de asp.net. También hay una cantidad de importante de memoria (~70 MB) consumida por dlls y ensamblados (ver la primera imagen.)


Conclusiones


Las conclusiones que se pueden obtener en este caso son:




  1. No todos las pérdidas de memoria son producto de errores en la codificación.



  2. Si vas a habilitar la traza en producción, recuerda deshabilitarla una vez que termines.



  3. También, si no vas a poder leer la información de 7500 trazas, configúralo para que almacene menos.


Saludos,
Patrick

Microsoft.VisualBasic.dll, ¿Eres tan malo como dicen?

Algunos años atrás, todo lo relacionado con Visual Basic (VB) 6.0 tendía a ser menospreciado o subvalorado. Los desarrolladores que utilizábamos VB 6.0 no éramos los primeros en levantar la mano para decir orgullosos que lo utilizábamos, como sí lo hacían los que usaban C o C++.


Una pequeña fracción de esa baja estima se mantuvo aún cuando apareció .net. Era cierto que teníamos un nuevo lenguaje (o un lenguaje muy remozado) que permitía lograr cosas impensadas en VB 6.0, tales como programar realmente orientado a objetos, crear threads, o deshacernos por fin de los problemas de los componentes marcados como Apartment, pero seguía existiendo “algo.”


A mi entender, algunos de los problemas que NO ayudaron a la transición real de un lenguaje limitado a un lenguaje completo, se pueden desglosar en la siguiente lista:




  • La existencia Option Explicit en vb.net. No existe programación seria sin declaración e inicialización de variables.



  • La existencia de Option Strict en vb.net.



  • Microsoft.VisualBasic.dll, librería para ayudar a la migración de proyectos, que implementa esas terribles funciones como Len, Left, Right, Trim, Mid, Replace y otras.


Respecto a este último punto, siempre que tenía la dicha de ver algún proyecto usándola, terminaba recomendado que no se use y que use las propiedades de los tipos de .net. (Ej: en vez de usar Len(variable) usar variable.length).


Ante la obvia pregunta de ¿por qué no debo usarla?, venía una respuesta que obtuve de variados lugares, pero nunca comprobé empíricamente, y que sostenía que tenía menor rendimiento que las nativas de los tipos.


A veces incluso utilizaba [reflector] para justificar mi teoría, como muestro en la siguiente imagen. ¿Para qué usar Trim(variable) si al final lo que se ejecuta es variable.trim? Mejor hacerlo directamente.



En esta oportunidad he decidido hacer pruebas sobre las funciones más utilizadas de VB 6.0, pero que fueron reescritas en este ensamblado (Microsoft.VisualBasic.dll) y determinar bajo pruebas empíricas si son “tan” malas como aparentan.


Quiero hacer hincapié en algo muy importante. Las funciones antes mencionadas, implementadas en VB 6.0, y que califiqué como “terribles”, justifican el calificativo asignado. Muchas de ellas, si es que no todas, reciben como parámetro de entrada un tipo de datos variant y retornan un tipo variant.


Esta conversión a variant penaliza el rendimiento de la aplicación, y peor aún, si se realiza en en ambos sentidos (entrada y salida). Siempre hablando en el contexto de VB 6.0, algunas funciones tenían variantes que terminaban en $, como Left$, y que tenían la gracia de retornar un tipo string, pero seguían recibiendo un variant. No entiendo que costaba hacer una que recibiese string y retornase string, pero ya está. Ya fue.


Por suerte, ahora en .net, las implementaciones en Microsoft.VisualBasic.dll incluyen parámetros correctamente tipificados, con la consecuente mejora en rendimiento.


Vamos a la prueba y a los sorprendentes resultados.


Código a ejecutar


Todas las funciones a medir fueron llamadas desde una única función general para cada lenguaje, llamadas ProcesarComoVB6 y ProcesarComoVBNET. No es mi intención medir y comparar el rendimiento de cada función específica sino que medir en general que sucede si se utilizan funciones de Microsoft.VisualBasic.dll o las nativas de los tipos en forma directa.


Cada función general recibe una cadena de 41.000 bytes y la procesa siguiendo la misma regla, detallada en el código de más abajo.


El siguiente es el código a ejecutar, utilizando Microsoft.VisualBasic.dll



El mismo código, utilizando las llamadas nativas de los tipo



La prueba comprende la ejecución una cantidad de 200 veces cada una de las funciones, midiendo los tiempos en terminar de procesar todas las instrucciones. Antes de iniciar las 200 iteraciones de cada una de las funciones, estas son llamadas un par de veces antes para JITtearlas (bonita palabra, no?)


Resultados de las pruebas


Ejecutando la prueba en un proyecto desarrollado en Visual Studio 2003 con el Framework 1.1, compilado en modo release, se obtienen los resultados de la siguiente tabla:



















Ejecución N° Microsoft.VisualBasic.dll Métodos nativos
1 28,51 segundos 16,20 segundos
2 27,76 segundos 16,15 segundos
3 30,45 segundos 17,40 segundos

 


Wow…(no estoy haciendo propaganda a Vista [;)]), impresionante. No nos engañemos todavía. Aún hay mucho que descubrir.


Analicemos antes de seguir las funciones que estamos midiendo y qué podría justificar la diferencia.


Tanto Left, Right como Mid debieran tener costos similares a la representación en VB.NET utilizando Substring. Técnicamente lo que hacen es obtener un grupo de caracteres de una cadena. No hay mucha ciencia.


Conversiones de caracteres a números y viceversa no son costosos, o no debieran serlo. Entonces, Convert.ToChar y Convert.ToInt32 debieran tener similar rendimiento a Asc y Chr respectivamente. Esto último no es necesariamente cierto para el resultado de la transformación. Los resultados de Asc y Chr pueden diferir de los de Convert.* de acuerdo a la cultura que se utilice.


¿Que nos queda?…Replace…el dolor de cabeza de un procesador….


Nuevas pruebas, sin Replace


El siguiente es el resultado de las pruebas removiendo el Replace del final, de ambas funciones. Los resultados son nuevamente sorprendentes.



















Ejecución N° Microsoft.VisualBasic.dll Métodos nativos
1 7,59 segundos 7,46 segundos
2 9,20 segundos 8,73 segundos
3 8,98 segundos 8,07 segundos

 


Interesante, no? ¿Qué se puede concluir ahora?


Conclusiones aventuradas


Descartando la función Replace, como supusimos, no hay mucha diferencia en el tiempo entre utilizar el ensamblado Microsoft.VisualBasic.dll y las funciones nativas. Replace hace la diferencia. Veamos por qué.


Si se utiliza [Reflector] para ver el código de String.Replace se obtiene esto.



Si se utiliza Reflector para ver el código de Replace desde Microsoft.VisualBasic.dll, se obtiene esto, y pongan atención a la zona enmarcada en rojo. Ouch!! Eso afecta cualquier procesador.



Más aún, Strings.Split y String.Join son funciones implementadas en Microsoft.VisualBasic.dll y no las nativas del tipo string.


Consumo de recursos


Veamos ahora como anda el consumo de recursos y uso del procesador para cada ejecución. Para eso utilizaremos performance monitor y revisaremos contadores de CPU, proceso, excepciones en .net y memoria en .net.


Los contadores a medir son:




  • Uso del procesador para el proceso, tanto para tiempo de proceso de usuario como de kernel



  • Excepciones lanzadas por segundo



  • Colecciones en cada generación



  • Colecciones inducidas



  • Total de bytes utilizados



  • Bytes pedidos por segundo



  • Tiempo utilizado por el GC



  • Bytes privados del proceso


Grande fue mi sorpresa cuando los contadores de rendimiento de la memoria en .net, todos marcaban cero durante la ejecución. ¿El motivo? No se si es el motivo “oficial,” pero al menos a mi me bastó como auto-explicación. El Framework 1.1 no corre de forma nativa en 64 bits ya que este sólo puede generar código ensamblado de 32 bits. Como mi sistema operativo es 64 bits, es posible que la instrumentación de 1.1 no funcione. Por lo tanto, a mover todo al Framework 2.0 y Visual Studio 2005.


Nota: Si te preguntas por que no hice todo el post utilizando 2.0, la respuesta es porque quería mostrar cual es el impacto de correr aplicaciones 32 bits sobre 64 bits emulando 32, tanto para el Framework 1.1 como 2.0. También haré la prueba con 2.0 compilado en 32 bits, que es lo que viene justo ahora.


Compilando para 32 bits (x86) una aplicación .net 2.0


En esta oportunidad no haremos mucho análisis. Me interesa dejar los tiempos como referencia y poder comparar en los diferentes ambientes.


Versión con Replace




















Ejecución N° Microsoft.VisualBasic.dll Métodos nativos
1 23,32 segundos 25,15 segundos
2 23,29 segundos 25,16 segundos
3 23,28 segundos 25,46 segundos


Versión sin Replace




















Ejecución N° Microsoft.VisualBasic.dll Métodos nativos
1 7,40 segundos 7,37 segundos
2 7,17 segundos 7,09 segundos
3 7,18 segundos 7,78 segundos


¿Conclusiones?…mmm, no gracias.. No tengo nada inteligente que aportar, como tampoco quiero hacer suposiciones. Full 64 bits por favor!!


Compilando para 64 bits (x64) una aplicación .net 2.0


Veamos los resultados de la misma prueba compilado para 64, o mejor dicho, compilado para cualquier CPU. Total, una vez que se JITtee (bonita palabra nuevamente, no?), lo hará para el procesador en que se está ejecutando.


Versión con Replace




















Ejecución N° Microsoft.VisualBasic.dll Métodos nativos
1 14,07 segundos 19,35 segundos
2 13,98 segundos 18,79 segundos
3 14,25 segundos 19,12 segundos


Versión sin Replace




















Ejecución N° Microsoft.VisualBasic.dll Métodos nativos
1 5,86 segundos 5,96 segundos
2 5,93 segundos 5,68 segundos
3 5,79 segundos 5,75 segundos


¿¿¿¿Qué????


Parece que el equipo de desarrollo de VB.NET se tomó en serio las críticas y decidieron mejorar el producto.


Veamos con reflector el código de Replace de Microsoft.VisualBasic.dll, para la versión 2.0 del Framework.



Interesante. Cambiaron esa idea de hacer splits y joins e implementaron una función con ese fin específico. ReplaceInternal utiliza un Stringbuilder para cumplir su labor. Bien.


Volvamos ahora que tenemos contadores al análisis del consumo de recursos.


Consumo de recursos, V 2.0


Analicemos la utilización de recursos para ambas versiones, con y sin Replace. En todos los contadores colocaré el valor por defecto, que en algunos casos es el promedio y otros el máximo.


Versión con Replace



















































Contador Microsoft.VisualBasic.dll Métodos nativos
# Exceptions Thrown/sec 0 0
# Gen 0 Collections 23.236 15.134
# Gen 1 Collections 2 61
# Gen 2 Collections 0 12
# Induced GC 0 0
# Total Commited Bytes 1,3 MB 3 MB
% Time en GC 7,1 % 2,8 %
Allocated bytes/sec 1,1 GB (así es) 512 MB
% User Time 89 % 85 %
% Privileged Time 3 % 12 %
Private Bytes 23 MB 24,8 MB

 


Mini conclusiones versión con Replace


La utilización de métodos nativos consume menos recursos en general. Hay una reducción importante en las recolecciones de primera generación (gen 0), pero las recolecciones en esa generación son muy económicas, al igual que las de la generación 1. Las de generación 2 son caras y hay que evitarlas, aunque 12 es un número pequeño.


Lo anterior se traduce en que la versión con métodos nativos consume menos procesador recolectando “basura,” y genera mucho menos “basura” (Allocated bytes/sec).


En la versión con métodos nativos, podría existir una relación entre la cantidad de bytes commited y la cantidad de recolecciones de segunda y tercera generación (gen 1 y gen 2) ya que hay memoria que se mantiene ocupada más tiempo y no es liberada en recolecciones de primera generación. Esto es solo una suposición.


Versión sin Replace



















































Contador Microsoft.VisualBasic.dll Métodos nativos
# Exceptions Thrown/sec 0 0
# Gen 0 Collections 14.305 12.654
# Gen 1 Collections 0 52
# Gen 2 Collections 0 10
# Induced GC 0 0
# Total Commited Bytes 1,3 MB 3 MB
% Time en GC 9,3 % 8,2 %
Allocated bytes/sec 2,0 GB 1,5 GB
% User Time 93 % 94 %
% Privileged Time 4 % 4 %
Private Bytes 23,5 MB 25,9 MB

 


Mini conclusiones versión sin Replace


El consumo de recursos es equivalente. Llama la atención el aumento en ambas versiones de la cantidad de bytes pedidos por segundo (allocated bytes/sec).


El resto de los contadores no presenta diferencias importantes entre ambas funciones para la versión sin Replace.


Conclusiones


Las siguientes conclusiones puedo obtener del análisis.


1.- No correr aplicaciones 1.1 en 64 bits


2.- No correr aplicaciones compiladas para x86 en 64 bits


Tristemente, mi intención inicial de encontrar algún motivo para que no se utilice Microsoft.VisualBasic.dll en los proyectos no ha podido ser cumplida. [:(]


En el único escenario donde encarecidamente recomendaría no usarla es en aplicaciones 1.1, pero en aplicaciones 2.0, la diferencia es irrelevante.


Saludos,
Patrick.
 

Entre las excepciones y la flojera de los desarrolladores

Una de las recomendaciones importantes en el desarrollo de código es la “no utilización de excepciones para evitar realizar validaciones.”


¿A qué me refiero?


A usar try/catch para no tener que escribir código que valide algo. Total, si se cae, en el catch retorno que es falso, si no se cayó, entonces retorno verdadero. Así no es necesario codificar rutinas especiales.


Vamos al caso


Como ya es costumbre en mi trabajo, y de las buenas costumbres, las pruebas de carga muestran la peor parte de las aplicaciones, y esta no fue la excepción, aunque el culpable era código de un componente de terceros.


Pruebas de carga


Treinta minutos de ejecución de un script grabado con [ACT], 50 usuarios concurrentes, 30 minutos. No vamos a dar todos los detalles, pero el uso de la CPU estaba “fluctuante”, y tenía unas subidas a 100% por varios segundos.


El siguiente es el grafico de performance monitor. Como hay más de 30 minutos, los segundos que la aplicación pasaba al 100% solo se ven como picos, pero en algunos casos llegaba a casi 40 segundos.



Te podrá haber llamado la atención que el uso de la CPU está muy extraño, como que no es fluido, considerando que una prueba de carga debiera mantenerla ocupada constantemente. No tengo la explicación ahora, pero al final veremos algo diferente.


Mientras revisaba contadores varios, me llamó la atención la cantidad de excepciones que se producían a veces, por lo tanto, agregué el contador de excepciones y voila!!. Problema encontrado.



Asombrosa similitud, ¿no?


A tomar dumps en las excepciones para ver que está ocurriendo. Mmm, mejor que no. Con 184 excepciones por segundo, reventamos el servidor. Mejor aún, utilizo un archivo de configuración para AdPlus, que viene en [windbg], el cual configuro para obtener información de threads, threadpool, stacks manejados y no manejados y excepciones cuando yo le solicite, que será cuando la CPU esté en 100%.


¿Resultado?


Esta es parte del stack no manejado, de un thread manejado. Como este, habían 10 más, es decir, 11 threads lanzando excepciones, a una asombrosa tasa de 184 por segundo.






 22 Id: 3924.46b8 Suspend: 1 Teb: 7ffa5000 Unfrozen
ChildEBP RetAddr Args to Child
06ece448 7c827ad6 7c8063cb ffffffff 7921ace1 ntdll!KiFastSystemCallRet
06ece44c 7c8063cb ffffffff 7921ace1 00000000 ntdll!NtQueryVirtualMemory+0xc
06ece4ac 7c8123b4 7921ace1 00000000 793e8730 ntdll!RtlIsValidHandler+0x82
06ece520 7c834d44 06ecc000 06ece530 00010007 ntdll!RtlDispatchException+0x78
06ece800 77e52db4 06ece810 050d5008 e0434f4d ntdll!RtlRaiseException+0x3d
06ece860 7921af79 e0434f4d 00000001 00000000 kernel32!RaiseException+0x53
06ece8b8 7921aefc 1194c7f0 00000000 06eceb14 mscorwks!RaiseTheException+0xa0
06ece8e0 7921aeb0 1194c7f0 00000000 06eceb24 mscorwks!RealCOMPlusThrow+0x48
06ece8f0 79218cc2 1194c7f0 00000000 0219d0b4 mscorwks!RealCOMPlusThrow+0xd
06eceb24 792b1893 00000018 00000001 00000000 mscorwks!CreateMethodExceptionObject+0x67b
06eceb58 79274773 00000018 79274778 06ecec08 mscorwks!RealCOMPlusThrow+0x35
06eceb68 79338b01 0216137a 000000e7 06eceb90 mscorwks!StringToNumber+0x7e
06ecec08 04266804 06ecec14 0f1604f0 000000e7 mscorwks!COMNumber::ParseDouble+0x32


Esta es parte del stack manejado, del mismo thread.





0x06ece908 0x7c834cf4 [FRAME: GCFrame]
0x06ecec38 0x7c834cf4 [FRAME: ECallMethodFrame] [DEFAULT] R8
System.Number.ParseDouble(String,ValueClass System.Globalization.NumberStyles,Class System.Globalization.NumberFormatInfo)
0x06ecec48 0x79a14e0f [DEFAULT] R8
System.Double.Parse(String,ValueClass System.Globalization.NumberStyles,Class System.IFormatProvider)
0x06ecec84 0x79a0e3cc [DEFAULT] R8
System.Convert.ToDouble(String)
0x06ecec88 0x06a30741 [DEFAULT] [hasThis] ValueClass System.Drawing.StringAlignment
C1.Util.Styles.StyleContext.1M(String)
0x06ececc4 0x06a306cd [DEFAULT] [hasThis] ValueClass System.Drawing.StringAlignment C1.Util.Styles.StyleContext.GetGeneralAlignment(Class C1.Util.Styles.Style,String)
0x06ececd8 0x06a30246 [DEFAULT] [hasThis] Void C1.Util.Styles.StyleContext.UpdateStringFormat(Class C1.Util.Styles.Style,String)
0x06ececf8 0x0580f464 [DEFAULT] [hasThis] ValueClass System.Drawing.SizeF C1.Util.Styles.StyleContext.GetContentSize(Class C1.Util.Styles.Style,Class System.Drawing.Graphics,ValueClass System.Drawing.SizeF,String,Class System.Drawing.Image)
0x06eced40 0x06a31182 [DEFAULT] [hasThis] I4 C1.Util.Styles.StyleContext.GetContentWidth(Class C1.Util.Styles.Style,Class System.Drawing.Graphics,I4,String,Class System.Drawing.Image)

La información de la excepción se muestra en la siguiente caja, y es equivalente a la presentada en el stack manejado.






Exception 0f69dff0 in MT 79bacb74: System.FormatException
_message: Input string was not in a correct format.
_stackTrace:
00000000
00000000
79bbb998
79a14eb0 [DEFAULT] R8
System.Double.Parse(String,ValueClass System.Globalization.NumberStyles,Class System.IFormatProvider)
06e8eca0
79bac7b0
79a0e3cb [DEFAULT] R8
System.Convert.ToDouble(String)
06e8ed20
79bbf6b0
06a30740 [DEFAULT] [hasThis] ValueClass System.Drawing.StringAlignment
C1.Util.Styles.StyleContext.1M(String)
06e8ed24
0573bf28


¿Qué nos dice [reflector] del código en el método 1M?







No voy a entrar a analizar que hace o no el código.


Lo único que puedo vez rápidamente es que el desarrollador que codificó estas líneas tenia ganas de irse rápido a la casa, como muchas veces me pasó a mí [:)].


¿Por qué poner un try/catch en vez de hacer la validación que correspondería hacer?


¿Es tan difícil usar un expresión regular para validar decimales o doubles, algo así como “[-+]?[0-9]*\.?[0-9]+“?


Muchas de los try/catch que son codificados podrían ser reemplazados por validaciones con ifs y elses, pero consume mucho más tiempo aprender cosas nuevas, y seguramente las pruebas en el computador del desarrollador no detectaron este problema [:)].


Como no fue posible corregir el código defectuoso, ya que estaba en un componente de terceros, procedimos a hacer unos ajustes y remover parte de la funcionalidad que invocaba ese método.


Nueva prueba de carga


El resultado obtenido habla por si solo. Consecuentemente, el grafico del uso de CPU ahora muestra un comportamiento más esperado para una prueba de carga. Y la gran cantidad de excepciones se fueron.



Conclusión


Tarde o temprano, los problemas aparecen. Es mejor invertir un par de horas en aprender algo que te podrá servir muchas veces a futuro, y dejar la chapucería para otro tipo de actividades.


Estas conclusiones están medias pobres, pero se debe a que no hay mucho más que decir. Los gráficos hablan por sí solos.


Adicionales


Si te interesa aprender de expresiones regulares, existe un muy buen libro y muchos sitios en internet. Personalmente uso el libro Mastering Regular Expressions.


Otros sitios web interesantes:



Saludos,
Patrick.

¿Por qué no debo compilar en modo debug?, Parte III

Como lo mencioné al terminar el segundo post sobre por qué no debo habilitar debug=true en web.config, la tercera entrega vendría relacionada con optimizaciones a nivel de código IL.


Si no leíste los posts anteriores, te recomiendo hacerlos, aunque este no es la continuación de ninguno de los dos. Las direcciones son:



Bueno, veamos ahora las optimizaciones que se realizan, aunque siendo más ajustado a la realidad, el código generado en modo debug está des-optimizado y con potenciales “bugs”.


Lo anterior significa que en modo debug, se agregan operaciones a nivel de código de máquina, como también instrucciones de código a nivel de IL con el objetivo de apoyar el debugging y la edición en caliente (edit and continue). Utilicé la palabra bugs entre comillas ya que no son bugs reales, pero en un escenario no adecuado, se comportan como tal.


Cuando se compila en modo release, el código generado es de menor tamaño y mas rápido, es decir, optimizado, como esperaríamos que siempre fuese.


Para mi ejemplo, tomaré un problema causado por un ensamblado (assembly) compilado en modo debug, que es exactamente lo mismo que hace debug=true en un sitio web, salvo que tienen ambientes de impacto diferentes.


Dejaremos para la cuarta y última entrega, el análisis de código de máquina.


Excepción lanzada


La aplicación web, en momentos de mucha carga, empezaba a lanzar excepciones del tipo System.IndexOutOfRangeException, con el texto acorde “Index was outside the bounds of the array,” estado del cual no lograba salir hasta un reinicio del proceso.


El siguiente era el stack de ejecución al momento de lanzarse la excepción. Las direcciones de memoria son de un sistema de 64 bits.






# Child-SP RetAddr : Args to Child : Call Site
00 00000000`04c9dc50 00000000`7816c664 : ffffffff`fffffffe 00000000`04c9dd90 00000642`7fc2f008 00000001`7fffa790 : kernel32!PulseEvent+0x60
01 00000000`04c9dd20 00000642`7f4477db : 00000642`7f330000 00000002`00000585 00000000`c089c2d8 00000642`7f4508eb : MSVCR80!CxxThrowException+0xc4
02 00000000`04c9dd90 00000642`7fa0e4b2 : 00000000`04b833e0 00000000`06717520 00000642`7f521a48 00000000`00000003 : mscorwks+0x1177db
03 00000000`04c9ddf0 00000642`782caee2 : 00000001`7fffa790 00000642`781043b8 00000642`802a24c0 00000000`00000000 : mscorwks!PreBindAssembly+0x428b2
04 00000000`04c9df60 00000642`80261e22 : 00000642`7882fe08 00000000`c08982c0 00000001`7fffa790 00000000`c00f0a40 :
mscorlib_ni!System.Collections.ArrayList.Add(System.Object)+0x32
05 00000000`04c9dfa0 00000642`80282dc9 : 00000000`c089be48 00000000`c08982c0 00000001`7fffa790 00000000`c00f0a40 :
ASSEMBLY.NAMESPACE.CLASE..ctor()+0x82


Por cierto, el nombre del ensamblado y la clase han sido modificados. No se llamaban ASSEMBLY.NAMESPACE.CLASE.


Analicemos el stack de ejecución y la excepción


El constructor de CLASE, en la instrucción de offset 0x82 desde el inicio del método, estaba llamando al método Add de un ArrayList.


A su vez, el método Add, en la instrucción de offset 0x32 desde el inicio del método, se estaba lanzando la excepción.


La excepción es de tipo IndexOutOfRangeException, es decir, se está tratando de referenciar un ítem dentro de un arreglo, el cual no existe.


Código del cliente


Revisando el código en el constructor (.ctor) de la clase CLASE, sorpresivamente no se encontró nada relacionado con ArrayList. La clase CLASE es la clase proxy que se agrega a un proyecto, cuando se agrega la referencia de un servicio web . Con mayor razón, nadie ha tendría por qué agregar código ahí. ¿Entonces?


Reflector al rescate


Volcando los ensamblados desde dentro del dump y revisándolos con reflector, apareció este código:






public CLASE() //Equivalente a .ctor
{
    
__ENCList.Add(new WeakReference(this));
    this.Url = MySettings.Default.ASSEMBLY_NAMESPACE_CLASE;
    if (this.IsLocalFileSystemWebService(this.Url))
    {
        this.UseDefaultCredentials = true;
        this.useDefaultCredentialsSetExplicitly = false;
    }
    else
    {
        this.useDefaultCredentialsSetExplicitly = true;
    }
}


¿Y esa línea?… Interesante.


Necesitamos más pistas


Desensamblando Add de ArrayList, se obtiene el código de la siguiente sección, siendo la línea blanca la “responsable” del problema.






public virtual int Add(object value)
{
    if (this._size == this._items.Length)
    {
        this.EnsureCapacity(this._size + 1);
    }
    
this._items[this._size] = value;
    this._version++;
    return this._size++;
}


Ok, tenemos la línea responsable del error, que está en el código Add de ArrayList. Al evaluar el escenario posible, el error podía estar o generarse en cualquiera de todos estos puntos:



  1. Error en el código de Add

  2. Error en alguna otra parte del código, como CLASE..CTOR

  3. Algo más

El punto número uno se descarta rápidamente, y el motivo es el siguiente. No es que el código Microsoft este libre de bugs, sino que un error en Add de Arraylist habría sido reportado hace 346.432.194.385.037 años.[:)].


Nota aparte: Leí en el libro de Debugging de [Robbins], que si el debugging corresponde a la eliminación de bugs, el escribir código corresponde a la creación de bugs. Esto lo podemos interpretar como no hay código libre de errores.


El método .ctor de CLASE presentaba esa línea de diferencia, la causante de todo el problema.


¿Quién es __ENCList?.. más pistas por favor


Está definido como un ArrayList estático, es miembro de CLASE, e instanciado en el siguiente método:






[DebuggerNonUserCode]
static CLASE() //Equivalente a .cctor (sí, cctor con 2c)
{
    __ENCList = new ArrayList();
}


Interesante..un método estático, privado y decorado con un atributo de sospechoso nombre (DebuggerNonUserCode), el cual reconozco que no conocía hasta ahora. Recomiendo su investigación.
http://msdn2.microsoft.com/en-us/library/system.diagnostics.debuggernonusercodeattribute.aspx
 


Además, y algo muy importante cuando utilizas miembros estáticos, es la protección del acceso sobre éste. Que sean estáticos significa que es compartido por todos los threads del proceso. Entonces, se debe cuidar que cuando se haga escritura sobre una variable estática, se haga garantizando que nadie más (otros threads) pueda accederla mientras se realiza la operación. Esto es similar al uso de transacciones en algún motor de datos.


En este caso, el miembro estático no está protegido, lo que en inglés se conoce como thread-safe. El no cumplir con esto, puede llevarnos a situaciones de race conditions. Más información en http://support.microsoft.com/kb/317723/en-us


Recopilando pistas


Tenemos las siguientes pistas:



  1. Error en código que no es del cliente

  2. Código con error es agregado automáticamente por el compilador

  3. Clase estática con miembro estático que no está protegido

  4. Atributo de nombre sospechoso (debug)

Las pistas anteriores no permiten concluir nada en específico, pero dan indicios y suposiciones de donde estaba el problema y qué se debía revisar.


Efectivamente el proyecto web asociado a esta aplicación estaba compilado en modo debug (debug=true), y tanto la variable __ENCList como la línea en el constructor fueron agregadas por el compilador.


Habiendo realizado el cambio para compilar en modo release, y habiendo recompilado el proyecto, el problema no volvió a presentarse, y por supuesto, ni la variable ni la línea tampoco aparecieron en los ensamblados cargados en memoria.


Código de máquina


La revisión del código de máquina quedará para la cuarta y última entrega referente a esto.


desde Santiago, Chile
Patrick.

/3GB, memoria de kernel y un sábado de locos

Si no considero las 3 horas que dormí del viernes al sábado, podría decir que llevo casi 48 horas despierto, o que llevaba hasta hoy en la mañana ya que pude dormir 5 horas más de 6 a 11 am (hoy es domingo en la tarde). ¿Cómo tanto?. La primera trasnochada fue por una fiesta de la oficina. La segunda, por un visita fugaz a un cliente en apuros. Mi día sábado fue extenuante y estresante para mi familia, cumpleaños, visitas, compra de pasajes, arreglo de taxis, reservas hoteleras, información adicional, ajustar otros viajes, una locura.


Menos detalles aburridos y vamos al caso


El escenario era similar al descrito a continuación:




  1. Aplicaciones COM+ configuradas por defecto, salvo que algunas de ellas estaban configuradas con diferentes identidades (usuario que será utilizado para ejecutar la aplicación Com+). Las opciones disponibles para identidad son Interactive, Local Service, Network Service o uno específico.



  2. Después de un par de días funcionando, cualquier aplicación COM+ que no estuviese funcionando y era requerida, fallaría al levantarse



  3. Si la aplicación no había sido detenida durante todo el período de tiempo, seguiría funcionando sin problemas, aún cuando otras aplicaciones no pudiesen levantarse.



  4. Si esta aplicación dejaba de ser requerida por más de 3 minutos (valor por defecto) y era bajada, un nuevo requerimiento trataría de levantarla y fallaría.


Claramente no estábamos en presencia de algún problema de código ya que  en ese caso, habría fallado siempre. Y más aún, nadie había hecho ningún cambio en los componentes en bastante tiempo.


Investigación del problema


Como en cualquier actividad de resolución de problemas, lo PRIMERO que hay que mirar es el event viewer o visor de sucesos (en español).


Dos tipos de eventos llamaban la atención sutilmente. No habían muchos registros de ellos, pero estaban en el momento adecuado, en el lugar adecuado.


Uno de los eventos estaba en el mismo momento cuando empezaban los problemas. El mensaje era el siguiente.




  • Failed to create a desktop due to desktop heap exhaustion


Adicionalmente, otros tres eventos habían ocurrido uno de estos días, los que terminaron de aclarar la situación. Este evento el 2019:




  • Event ID 2019: “The server was unable to allocate from the system nonpaged pool because the pool was empty.”


Serie de preguntas y respuestas


Ingeniero, es decir, yo [:)]: ¿Configuraron /3GB en boot.ini?
Contraparte: Si
Ingeniero: ¿y configuraron userva?
Contraparte: No
Ingeniero: mmm…interesante

Ingeniero: ¿Cómo andan las PTEs?
Ingeniero: perfmon -> Memory -> Free System Page Table Entries (PTEs) –> cercano a 2.000 … ouch


Conclusión


El Kernel se quedó sin memoria.


¿Ahh?…bajémoslo a la tierra.


En una arquitectura de 32 bits, la memoria virtual es un recurso medianamente escaso. No vamos a hablar de la cantidad memoria física del servidor. Si bien, mientras más memoria mejor, el problema a describir ahora no depende totalmente de la cantidad de memoria del servidor, ya que o bien tengas 2 o 20 GB, se presentará igual.


Con 32 bits, la memoria virtual, que tampoco tiene que ver con la memoria paginada en disco, está restringida a 4GB por aplicación. El valor 4GB se obtiene al elevar 2 a 32, o 2^32.


De esos 4 GB virtuales, 2 GB son usados por un proceso y los otros 2 por el kernel. Cada aplicación tendrá sus 2 GB virtuales y compartirán los 2 GB de kernel. Debido a esto último, algunos de ustedes recordarán haber visto en Task manager que un proceso nunca pasa de 1,7 o 1,8 GB. Bueno, la explicación es esa. Una aplicación no puede usar más de 2 GB de memoria virtual.


Existe un switch para que sí lo haga, pero con su consecuencia. Este switch se configura en el archivo boot.ini, y corresponde a la opción /3GB.


El impacto de la aplicación de éste es que del espacio virtual de 4 GB, 1 GB pasa de memoria de kernel a memoria de proceso de usuario. Entonces ahora un proceso de usuario puede llegar a usar 3 GB y el kernel queda drásticamente reducido a 1 GB.


SQL Server, Exchange, COM+ y los Application pool de IIS son algunos de los procesos que tomarán ventaja de este cambio y podrán llegar a 2,7 u 2,8 GB de memoria usada, lo que representa un incremento del 50%, y que tiende a ayudar bastante en algunos casos, pero en otros, produce problemas si no se usa adecuadamente (como éste).


¿El problema?


El kernel necesita memoria para poder funcionar, y 1 GB virtual no es suficiente en algunos casos. En el kernel se cargan drivers, el manejador de memoria, de procesos, controladores gráficos, el HAL, manejo de plug & play y otras tareas.


Además, el kernel maneja dos pool de memoria, uno llamado paginable y el otros no paginable. En ingles, paged pool y nonpaged pool respectivamente. ¿Recuerdan el evento 2019? Vuelvan a leer la descripción.


Al aplicar el switch /3GB, el tamaño de estos pools se reduce a la mitad, pudiendo entonces en determinados casos agotarse y poner en riesgo el servidor. Si el kernel no es capaz de obtener memoria de estos pools, varios problemas pueden ocurrir, a saber:




  • Problemas de interfaz grafica, en donde ésta no responde adecuadamente



  • Problemas de funcionamiento de algunos procesos, para nuestro caso, las aplicaciones COM+ no levantan.



  • Falla en procesar requerimientos vía red


Al aplicar /3GB se reduce también la cantidad de PTEs disponibles, lo que generará problemas con los requerimientos de IO, entre otros.


Identidades de aplicaciones


Complementando lo anterior, si recuerdan, en un inicio hablamos de las identidades de las aplicaciones COM+.


Este tópico no lo comprendo a cabalidad, pero puedo decir (con temor a equivocarme) que cada aplicación que es iniciada con un usuario diferente, requerirá que el sistema operativo cargue ciertos componentes para el usuario (desktop). Estos componentes incluyen:




  • Menús del sistema



  • Ventanas



  • Otra información.


Entonces, si tengo aplicaciones COM+ configuradas con X usuarios, podría llegar a cargar X desktops. ¿De donde se obtiene la memoria para cargar estos desktops? De la memoria del kernel.


Como sé que la información que acabo de entregar del tópico de Desktops es bastante limitada, prefiero incluir un link donde esta MUCHO mejor descrita. Aunque está en inglés, no está difícil. El link es http://blogs.msdn.com/ntdebugging/archive/2007/01/04/desktop-heap-overview.aspx.


Solución


Si tu aplicación no hará uso de 3GB, no incluyas la opción. No será necesaria.


Si tienes alguno de los servicios que mencioné antes y necesitas usarlo, deberás entonces usar además la opción userva en el archivo boot.ini.


Userva se utiliza para “mover” un poco de memoria de proceso de usuario a kernel. Realmente no mueve nada, pero el efecto final es que en vez de tener 3GB de usuario y 1GB de kernel, puedes configurar 2,7 GB y 1,3GB respectivamente, lo que ayudará a mitigar el problema, y en la gran mayoría de los casos, desaparecerá totalmente.


El KB referenciado al final muestra como configurarlo. Si bien dice que se deberá probar entre 2900 y 3030, si es necesario para tu sistema, podrás llegar a un valor menor. Mayores valores no tienen sentido.


Si estas usando SQL Server, utiliza mejor AWE por sobre 3GB. No expondrás el kernel a estos problemas.


Adicionalmente, estos links te podrán proveer mas información:


http://technet.microsoft.com/en-us/library/7a44b064-8872-4edf-aac7-36b2a17f662a.aspx
http://support.microsoft.com/kb/316739


Este otro está curioso: http://xentelworker.blogspot.com/2005/10/i-open-100-explorer-windows-and-my.html


Saludos,
Patrick.

Configurando threads en machine.config

La configuración de threads y conexiones de asp.net es un tópico oscuro. De algunos libros o KBs se puede obtener información, pero a mi entender, ninguna de ellas explica claramente cómo deben configurarse las opciones disponibles.


Las opciones que hago mención son las que se encuentran en el archivo machine.config, dentro de las siguientes secciones:




  • system.net/connectionManagement, atributo maxconnection



  • system.web/httpRuntime, atributo minFreeThreads



  • system.web/httpRuntime, atributo minLocalRequestFreeThreads



  • system.web/httpRuntime, atributo aspRequestQueueLimit



  • system.web/processModel, atributo maxWorkerThreads



  • system.web/processModel, atributo maxIoThreads



  • system.web/processModel, atributo minWorkerThreads



  • system.web/processModel, atributo minIoThreads



  • system.web/processModel, atributo requestQueueLimit


Estas opciones mencionadas son esencialmente para 1.1 ya que para 2.0 se pueden auto-configurar algunas (processModel). Mi experiencia en un caso específico no fue satisfactoria con la auto-configuración, así que optamos por la configuración manual.


La documentación existente hoy no es aclaratoria. Un libro que me gusta usar bastante es Improving .net Application Performance and Scalability, y a pesar de que tiene algunas secciones dedicadas a esta configuración, personalmente no me gusta la propuesta realizada porque no explica algunos detalles importantes ni tampoco te guía de forma correcta a encontrar tu propia configuración.


Detalles del caso


Los requerimientos eran bien simples. “Quiero que mi servidor procese la mayor cantidad de requerimientos que pueda, y tenga un tiempo de respuesta aceptable”. Seguramente este es el requerimientos tradicional de cualquier persona, y hay varios puntos que son totalmente subjetivos, pero hicimos el mejor esfuerzo por hacer pedazos el servidor con requerimientos.


Configuramos los valores sugeridos en el libro antes mencionado, y que son los mismos mencionados en este KB. Estos los despliego en la siguiente imagen, capturada desde el archivo scale.pdf (libro) disponible para bajar en éste link. Además vienen los valores por defecto.



Imagen obtenida de la página 280 del libro mencionado


Como el servidor web que estábamos probando tenía 4 CPUS, los valores aplicados fueron 48, 100, 100, 352 y 304 respectivamente.


Con la excitación de haber realizado la configuración correcta, procedimos a hacer las pruebas de carga, con 100 usuarios simultáneos, desde 2 servidores al mismo tiempo (200 usuarios en total).


Resultados


Los requerimientos se empezaron a encolar y después de algunos segundos empezaron a ser rechazados por el servidor, el cual consumía no más allá de un 3% de la CPU.


El escenario anterior está documentado en varias partes. Un uso de CPU muy bajo y encolamiento de requerimientos, entonces debes modificar tu servidor para que procese más requerimientos.


Ya se lo que hay que hacer. Ahora, ¿cómo lo hago?


Las páginas 445, 446 y otras del libro sugieren modificar modificar algunos valores y monitorear, si tendrás olas de cargas, etc. Es en este punto donde la documentación no es suficiente.


Con esto no quiero decir que mi explicación va a ser mejor que la del libro o que haya que copiar los valores que nosotros definimos para este servidor. Bajo ningún criterio se deberán copiar ciegamente los valores que nosotros aplicamos. Primero, se deberá lograr total entendimiento de los parámetros, la aplicación que se está sirviendo y las implicancias de los cambios que se hacen, para luego, de acuerdo a un estudio y pruebas de carga, se determinen cuales son los adecuados para tu ambiente. Me interesa mostrar una forma de llegar a los valores para lograr un proceso repetible.


En nuestra prueba de carga, el contador de rendimiento Requests Executing del objeto ASP.NET Apps v1.1.4322 mostraba 48 constantemente, mientras los encolados (Requests Queued de ASP.NET v1.1.4322) crecía impetuosamente. Luego empezó a crecer Requests Rejected del contador ASP.NET v1.1.4322.


Nota 1: Recordemos que los requerimientos empiezan a ser rechazados cuando la cantidad de requerimientos ejecutándose (Requests Current) sobrepasa el valor de system.web/processModel/requestQueueLimit. Los requerimientos ejecutándose (Requests Current) corresponden a la suma de los ejecutando, encolados y en espera de ser enviados al cliente. Esto significa que los requerimientos serán rechazados antes de que se llene la cola.


Nota 2: Existe otra cola más específica para cada aplicación o directorio web. El largo de ésta se define con system.web/httpRuntime/aspRequestQueueLimit, y su valor debiera ser menor comparado con system.web/processModel/requestQueueLimit ya que esta otra es una cola de uso general del Worker Process.


Bueno, teníamos 48 requerimientos ejecutándose y varias decenas encolándose. Se esperaba recibir 100 requerimientos por segundo. A ese ritmo, nuestro destino se veía muy lejos y con nubes negras encima [li]. ¿Dónde estaba el problema?


Análisis


Los valores sugeridos en el libro y el KB definen, utilizando un criterio basado en condiciones generales, que la cantidad de requerimientos a procesar por CPU será 12. Esto se refleja en varios atributos. Vamos por parte. Se hará referencia a las páginas del libro donde se definen.




  • maxconnection: valor sugerido, 12*#CPU. Este atributo limita la cantidad de conexiones a recibir (página 445). Es decir, si he definido 48, no puedo esperar a recibir más de 48, por ende, termino encolando y luego rechazando requerimientos.



  • maxIoThreads: valor sugerido, 100. Corresponde a la cantidad de threads disponibles para operaciones de I/O (disco, red, etc.), definido en la página 280. Este contador se multiplica automáticamente por la cantidad de CPUs del servidor. Entonces, potencialmente tenemos 400 threads disponibles para procesar requerimientos de I/O, pero ya sabemos que más de 48 no pasarán, y no todos son de I/O, así que serán menos.



  • maxWorkerThreads: valor sugerido, 100. Lo mismo de el atributo maxIoThreads, pero para threads que procesaran requerimientos y trabajarán dentro del proceso. Seguimos limitados por 48.



  • minFreeThreads: valor sugerido, 88*#CPUs. Este atributo representa la cantidad de threads que quiero que estén libres. ¿De dónde sale el 88?. Es la resta del máximo disponible menos la cantidad de requerimientos que quiero procesar por CPU, que es 12. Si la matemática no falla, 100-12 es 88. [:)]. Como dice la página 282, esta opción efectivamente limita la cantidad de requerimientos a procesar a 12, si maxWorkerThreads es 100.



  • minLocalRequestFreeThreads: valor sugerido, 76*#CPUs. Como el nombre lo dice, limita la cantidad de threads disponibles para requerimientos locales, dejando sólo 12 disponibles, ya que como las matemáticas se me dan hoy, 88-12=76 [:)].


Otros atributos interesantes.




  • minWorkerThreads: valor sugerido, maxWorkerThreads/2. Este atributo define la cantidad de threads que estarán disponibles en caso de una ola de requerimientos, lo que en el libro se llama Burst Load, explicado en la página 282. Al igual que su contraparte max, es implícitamente multiplicado por la cantidad de CPUs.



  • minIoThreads: no hay un valor sugerido, pero se puede suponer un valor similar a maxIoThreads/2. Se utiliza para soportar olas de requerimientos. Al igual que su contraparte max, es implícitamente multiplicado por la cantidad de CPUs.



  • requestQueueLimit: valor por defecto, 5000. Definir a criterio. Por lo general, el valor por defecto será suficiente.



  • aspRequestQueueLimit: valor por defecto, 100.


Durante las pruebas, rara vez lo contadores de threads del pool de aplicación (w3wp.exe) sobrepasaron los 80. Consideremos los 48 trabajando, mas los del garbage collector (1*#CPUs), el finalizador, el thread de compresión http, RPC local, etc., y otros más de control.


Nuestros requerimientos fueron rechazados cuando sobrepasamos los 100 de aspRequestQueueLimit. El uso del procesador no superaba el 3%.


Ajustes


Como podrán suponer, severos ajustes se debieron realizar para permitir procesar más requerimientos.


El cliente decidió soportar 1.000 requerimientos procesando al mismo tiempo. Un gran número. Eso no significa que el servidor recibirá 1.000 requerimientos por segundo, sino que podrá procesar del orden de 1.000 requerimientos al mismo tiempo. La duración de cada requerimiento impactará en la cantidad que se ejecuten concurrentemente. Como mencioné antes, el cliente esperaba recibir 100 requerimientos por segundo.


Siguiendo esta definición, los contadores se redefinieron con los siguiente valores. Explicaremos el por qué de algunos de ellos, y algunos puntos en contra que se deben considerar.


Si no has leído el resto del post, te solicito que lo hagas. Copiar estos valores sin entender qué hacen, podrá hacer que tu servidor colapse.




  • maxconnection = 1000. Si no se permite tamaña cantidad de conexiones, no tendremos los requerimientos.



  • maxWorkerThreads = 250. La formula dice que el contador se multiplica por #CPU, entonces, para poder procesar tantos requerimientos, se necesitan muchos threads..



  • maxIoThreads = 250. Seguimos la misma formula.



  • minFreeThreads = 100. No existe formula que aplicar acá. ¿Cuántos threads se quieren libres siempre? ¿10%, 5%? definir a criterio.



  • minLocalRequestFreeThreads = 50. Si no voy a procesar requerimientos locales, ¿para qué quiero reservar threads?. Este valor debió ser más pequeño.



  • appRequestQueueLimit = 1000. Si se van a procesar 1.000 requerimientos concurrentes, y se espera una tasa de 100 requerimientos por segundo, de nada sirve una cola de 100 registros. Se quedará corta en algunos minutos o segundos.



  • minWorkerThreads = 80. Si se hubiese aplicado la regla, se debió haber definido 125, para tener 500 threads disponibles. No se justifica. (ver consideraciones más abajo)



  • minIoThreads = 100. Igual que minWorkerThreads, si se hubiese aplicado la regla, se debió haber definido 125, para tener 500 threads de I/O disponibles. No se justifica. ¿por que no definimos el mismo valor que minWorkerThreads?. Nadie sabe. [;)].


Resultados obtenidos


Los resultados obtenidos fueron los esperados. Aunque no se pudo hacer que el servidor consumiera más del 15% del procesador, se logró procesar una tasa promedio de 84 requerimientos por segundo, con un máximo de 252 requerimientos en un segundo. Los requerimientos concurrentes promediaron 700 con un máximo de 970.


Se llegó a 970 ya que se aumentó la carga hasta 500 conexiones simultáneas por cada máquina de prueba (2 máquinas). Esos pobres servidores colapsaron ejecutando el script de [ACT].


El punto lamentable de la prueba fue darse cuenta de que el servidor de datos no fue capaz de responder a la demanda. El DBA tendrá que entretenerse un rato afinando consultas. Esto se tradujo en que algunos requerimientos demoraran más tiempo del esperado.


Consideraciones importantes


Aunque ya lo he dicho varias veces, te ruego no copiar los valores entregados aquí ya que son para un caso específico y condiciones especiales. Este es un servidor de servicios web, en donde cada uno de los servicios web se ejecutan en unas decenas de milisegundos (si el servidor de datos tiene poca carga). Si el servidor sirviese páginas ASPX con lógica más compleja que una simple consulta a la base de datos o si sirviese archivos de gran tamaño, la historia sería diferente y esta configuración seguramente haría sucumbir al servidor.


El tener en un momento 970 threads ejecutándose generará una alta tasa de context switch, lo que impactará el rendimiento de cualquier servidor. Nuevamente recalco que las condiciones especiales de este caso permitían definir tal cantidad de threads. Además, cada thread podría llegar a consumir 1 MB de memoria, aunque por lo general no debiera consumir más de 256K. Esto hará que se consuman cerca de 250 MB de memoria sólo por los threads. También es posible que se generen bloqueos entre los threads en dependencia de como esté desarrollada la aplicación. Es precisamente esto último lo que está detallado en el KB que mencioné mas arriba.


Todo esto debe tenerse en mente al configurar el archivo machine.config.


Saludos,
Patrick.

La contradicción de las aplicaciones ultra parametrizables y customizables

Estas  últimas semanas han estado un poco aburridas. No se han presentado problemas de aplicaciones pero seguramente se presentarán… tarde o temprano. Sin embargo, a falta de problemas que se presentan, nos encargamos de buscarlos, o más bien dicho, de forzarlos.


Una de las últimas actividades realizadas corresponde a la revisión de una aplicación que será liberada pronto. Esta revisión consistió en generar pruebas de carga para diferentes casos de uso y analizar los resultados.

Actividad realizada

Grabamos los scripts con [ACT], los modificamos con [fiddler] y los ejecutamos con [ACT].

Resultados

Los resultados fueron sorprendentes, y no lo que se esperaba. La aplicación no lograba procesar más de 0,5 requerimientos por segundo, consumiendo el 70% de la CPU con un sólo usuario conectado.

Análisis detallado

La aplicación analizada pertenece a la fauna de aplicaciones que han sido concebidas con la idea de ser totalmente customizables y parametrizables. Particularmente no estoy en contra de las aplicaciones parametrizables, y más aún, el no permitir que se adapten a ciertas variables es una limitación, y producirá en el cortísimo plazo problemas de mantención.

¿Cuál es la arquitectura utilizada?

La aplicación está montada sobre un framework desarrollado por un tercero.
Nota aparte: ¿Se han fijado que ahora todo el mundo hace frameworks?, ¿y a casi cualquier cosa desarrollada le llaman framework? Bueno, volvamos a la aplicación.


Esta es una aplicación web desarrollada en .net montada con este framework. No puedo decir que es una aplicación ASP.NET ya que apenas utiliza ASP.NET.

¿Por qué no usa ASP.NET?

Cada página no tiene controles asp.net; ninguno. Así de simple. Incluso las páginas generadas no tienen viewstate, prueba de lo anterior.

¿Cómo es esto posible?

Las páginas son generadas desde una definición existente en algún archivo XML (400 kilobytes), el cual, en algún lugar indica con cierto criterio, donde buscar los controles que deben pintarse en la página, los que están definidos en una tabla en una base de datos de SQL Server.


Debido a lo anterior, no es de extrañarse que para pintar una página, recurra muchas veces al servidor de datos. Para complicar aún más el escenario, cada ítem de la página es un ítem en la base de datos. Todo esto para poder definir paramétricamente las páginas. Notar al final las contradicciones de este modelo.


Más aún, la lectura desde el servidor SQL es procesada en largas funciones y ciclos, los cuales, para más males, concatenan string en algunos casos. El resultado de esta gran concatenación es, como alguno de ustedes podrá adivinar/suponer, XML.


Luego, este XML es transformado en conjunto con un XSL que define la salida de la página. Recordar que el requerimiento era que la aplicación fuese mantenible fácilmente, algo que ya no se cumple.


Ok, después de todo este trabajo, la página está pintada.

¿Qué pasa si hago clic sobre algún botón?

Cómo no existen los controles de servidor, no existe un evento asociado al botón, y la página se procesa como se hacía en ASP, es decir, con request.form[] y sus amigos.


Lo bueno al menos es que como todo esto lo maneja este framework, es él el encargado de procesar el evento y llamar a las funciones de negocio asociadas.


Las funciones de negocio se definen en un XML, de varios cientos de kilobytes. En este archivo, utilizando información súper rígida, se define la ruta física del assembly, además del tipo y la función que se llamará. No es necesario definir los parámetros de entrada, porque se usa un único parámetro de tipo string, que en el fondo, es un XML.


Si en las funciones de negocio se requiere llamar a un procedimiento almacenados (SP), hay que hacerlo a través del framework. Obviamente hay que construir un XML con la información del SP y los parámetros. Sin embargo, en el XML no se escribe el nombre del SP sino que un pseudo-nombre asociado a una pseudo-base de datos. Entonces, el framework internamente se encarga de ir a buscar a otro XML, y que tiene como nombre el mismo valor de la pseudo-base de datos, la definición real del SP.

Contradicciones vitales

El sistema fue concebido así para poder ser fácilmente adaptable sin necesidad de mayores cambios en el código. La contradicción está en que el único que es capaz de hacer algún cambio en la aplicación es alguien que domine todos los elementos mencionados hasta ahora.


Es interesante que no se esté utilizando el GAC. ¿Será porque los assemblies cambian mucho en el tiempo y existe un costo administrativo de firmarlos e incluirlos en el GAC? Si cambian mucho en el tiempo, ¿Cuál era el problema de hacer una aplicación más rígida, o dicho de otra forma, una aplicación normal utilizando controles ASP.NET y librerías de clases?

Otra información

¿Si se preguntan cuántas veces baja a la base de datos para pintar una página especifica?
Más de 400


Saludos,
Patrick

Dispose en SPWeb, SPSite y SPListItemCollection, desarrollando Web Parts para SharePoint

Después de una extenuante semana de viaje viendo un caso fuera de Chile, el cual me obligó a estar offline casi todos los días, me doy un tiempo para escribir y dar a conocer los usuales problemas con que uno se enfrenta cuando analiza web parts que corren sobre SharePoint*.


Hasta hoy, he visto web parts desarrolladas que normalmente tienen pérdidas de memoria (memory leaks), principalmente de memoria no manejada pero también de memoria manejada.


Como consecuencia de lo anterior, el continuo uso de éstas (Web Parts mal codificadas), llevará irremediablemente a encontrarnos con [OOM] en nuestra aplicación. Una forma de sobrevivir ante este problema de pérdidas de memoria es configurar el pool de aplicación de IIS 6.0 o 7.0 para que recicle cuando la memoria consumida (privada o virtual) llegue a una cantidad de megabytes determinada. Para la versión 5.0, existe una aplicación llamada IIS Recycle que hace algo similar, aunque asp.net en IIS 5 tienes capacidades de reciclamiento.


El principal problema con el desarrollo de Web Parts para SharePoint es que, al menos hasta la versión 2003, SharePoint Portal depende mucho de componentes COM que utilizan memoria no manejada, y el desarrollador eso no lo sabe, no se da cuenta o definitivamente olvida liberar los recursos no manejados (que incluye llamar a Dispose cuando corresponda).


Si te interesa y quieres confirmar esto, dale una mirada con reflector al ensamblado Microsoft.SharePoint.Library.dll.


Adicionalmente al problema de la no liberación de recursos no manejados, algunas bibliotecas de SharePoint están programadas de tal forma de que si necesita un recurso y este no se ha instanciado (o se ha destruido adecuadamente), ésta lo vuelve a generar. Esto complica más el panorama ya que si un desarrollador fue cuidadoso y lo liberó, el posterior uso de otra función puede revivir el objeto. Esto no es cierto para todas las funciones, pero algunas tienen comportamiento peculiar. Veámoslo en acción (toda la acción que se puede tener en un blog [;)]).


Supongamos que un desarrollador obtiene una SPListItemCollection en un objeto oList y para liberar los recursos no manejados, llama responsablemente a oList.List.ParentWeb.Dispose(), pero si después decide obtener la cantidad de objetos de esta colección llamando a Count, se podrá vivir la situación detallada anteriormente. El llamado a Count revivirá el objeto SPWeb.


El método Dispose  de SPWeb llama a Close, que llama a el método a sobre at, que es de tipo Microsoft SharePoint.Library.a. Antes de seguir, ten en cuenta que ahora se enreda bastante más.

 




public void Dispose()


{


    this.Close();


}

 

public void Close()


{


    if (this.at != null)


    {


        this.at.a();


        this.at = null;


    }


}

 

Y luego, el llamado a Count de SPListItemCollection:






public override int get_Count()


{


    this.a(true);


    return this.c;


}

 

El código del método a (que está ofuscado) es:






private void a(bool A_0)


{


    string text;


    SPWeb web;

    a a; //Esto se ve mal, pero es producto de la ofuscación

    string viewXml;


    if (this.f)


    {

        web = this.b.Lists.Web;
       
a = web.l();
        <Cortado para abreviar…>t;

}

 

La variable web referencia ahora al valor de this.b.Lists.Web y luego se llama al método l (ele) (ofuscado también). Recordemos entonces que web referencia a un objeto SPWeb (Web) que está referenciado por un objeto SPListCollection (Lists) que no debe ser confundido con el objeto del cual llamamos a Count del tipo SPListItemCollection. Este último (SPListCollection) a su vez está referenciado por un objeto de tipo SPList (b), el cual es parte de nuestro objeto inicial, SPListItemCollection (¿no te dije que se enredaba?).


El método l (ele) es internal y el código que nos muestra reflector es el siguiente:






internal a l(){


    this.i();


    return this.at;


}

 

Como ven, está retornando la variable at. Esta misma variable era la que se había asignado a null cuando se ejecutó SPListItemCollection.List.ParentWeb.Dispose(). Conviene mostrar el código de ParentWeb disponible en SPList para aclarar toda la relación.


ParentWeb retorna el objeto SPWeb asociado a la variable m_Lists (del tipo SPListCollection).






public SPWeb ParentWeb


{


    get


    {


        return this.m_Lists.Web;


    }


}

 

Solo para demostrar lo anterior, el código de i y h se despliegan ahora. Verán que el objeto at es nuevamente generado si este es null.






private void i()


{


    if (this.at == null)


    {


        this.h();


    }


}


 


private void h()


{


    int num = this.b.i();


    bool flag = -1 == num;


    bool flag2 = null != this.b.g();

    this.at = g.a(!flag2, this.al, this.b.d(), ref num);  

    <Cortado para abreviar…>


}

 

Si te has mareado con tanto objeto, es entendible. Lo importante aquí es encargarse de liberar toda la memoria referenciada por los objetos de SharePoint.


Si estás desarrollado Web Parts, no puedes no leer el siguiente documento. Considéralo como lectura obligatoria para desarrollar web parts que vivan sin problemas. La dirección del documento en MSDN  es http://msdn2.microsoft.com/en-us/library/ms778813.aspx y éste detalla de forma casi perfecta como liberar toda la memoria no manejada cuando programas Web Parts.


¿Por qué no digo que está perfecto? Porque le faltó agregar parte del caso que vimos hoy. En ninguna parte del documento indica la liberación del objeto SPWeb que esta referenciado por SPListCollection y a su vez por SPList y finalmente por SPListItemCollection. Es cierto que podría subentenderse, pero no está explícito.


Eso sí, tiene gran detalle para mostrar con ejemplos, código que está mal escrito y como debe escribirse correctamente. Si pudiésemos contar siempre con ejemplos así de MSDN, sería fantástico. Incluso, da a conocer sutilezas de la implementación que pueden hacer que tu aplicación colapse si no sigues las recomendaciones. Como ejemplo, vean esta aclaración que aunque está en inglés, no es difícil de entender.

SPSiteCollection [ ] Index OperatorThe SPSiteCollection [] index operator returns a new SPSite object for each access. A SPSite instance is created even if that object has already been accessed.

Si bien hoy no hablamos de SPSite, la limpieza de éste es tan importante como la de SPWeb.

 

*Realmente no sé si las web parts corren sobre otra aplicación que no sea SharePoint [;)], ya sea en la versión para Windows 2003 conocida como Windows SharePoint Services, como la versión full llamada SharePoint Portal server (http://www.microsoft.com/latam/office/sharepoint/prodinfo/relationship.mspx).


Saludos,
Patrick