Month: July 2007

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:

• http://www.regular-expressions.info/floatingpoint.html


• http://regexlib.com/default.aspx

Saludos,
Patrick.

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:

• 
  

  http://msmvps.com/blogs/pmackay/archive/2007/05/08/post0c.aspx



• 
  

  http://msmvps.com/blogs/pmackay/archive/2007/05/23/post0e.aspx 

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.