Analisis de Rendimiento

Analisis de Rendimiento

Introducción

Empiezas un proyecto y empiezas a aplicar todo lo que has aprendido en la universidad y en los libros, blogs, consejos que has ido leyendo e intentar aplicar toda la ingeniera del software al nuevo desarrollo. Te creas tus diagramas de clases, secuencia, estás un minutos o más pensando que nombre dar a una clase, y las relaciones entre ellas.

Un mes despues..

Han surgido nuevos requisitos que estaban ocultos, otros se han derivado en otros requisitos y los jefes quieren ver resultados.  ¿Solucion? tiras lineas de código a casco porro, y a usar el copy&paste más que nunca (esto ya debería ser una señal de aviso..que algo no va bien). Sacas una versión, y los testeadores y usuarios: "esto parece que va más lento.."

Efectivamente, se ha dedicado el tiempo a tirar lineas de código y a sacar funcionalidad, sin reparar en el rendimiento de la aplicación.

Creo que durante todas las fases del desarrollo hay que parar de tirar lineas de código y mirar como va el rendimiento de la aplicación. El Visual Studio ofrece mucha información, que la verdad, uno casi se pierde entre tanta información. Y con este post, intentaré que me sirva para tener una especie de protocolo para cuando quiere hacer dicho analisis seguir esos pasos y hacerlo de la manera más efectiva. También, entender un poco más el tema del rendimiento.

Para ver el tema de rendimiento, me he creado un pequeño programa que genera 1000 primitivas, y según está generando las primitivas de la lotería, va dibujando la frecuencia de cada numero en la ventana. Y final de la simulación, se ve una casi distribución uniforme.

Así uno puede ver si tienes mucho histórico sobre las primitivas, la probabilidad se parece y si una tiene poco histórico, casi no tienes patrones para hacer cálculos y jugar a la Primitiva. En fin, en su día incorpore a un programa a la posición del Sol y de la Luna por los efectos gravitacionales sobre las bolas del bombo, pero nada...las variables a tomar en cuenta sin inmensas..pero bueno, nos entretenemos pensando en como...pero bueno, vamos al grano...

Variables

Hay muchas páginas que hablan sobre las variables, a si que, no voy enumerarlas, solo voy a comentar lo que me parecen y así, entenderlas mejor.

El método  public List<Primitive> Generate(int numberOfPrimis, onPrimitiveGenerated handle) es el método donde empieza a ejecutar todo. Y este método tarda alrededor de 7.062 milisegundos.

Lanzamos el profiler en modo "intrumentalización".

Paso 1:
Ponemos Current view a "Funtions"

Paso 2:
Ordenamos los resultados por la la columna "Funtion Name". Aquí algunos dirán por alguna columna donde están los resultados de los tiempos, pero como me quiero centrar solo en los tiempos de las funciones que he creado, lo ordeno por los nombres (seguro que hay una manera de filtrar, pero aún la desconozco).

Paso 3:

Buscamos la función que tenga el tiempo "Elapsed Inclusive Time", y este tiempo es el de la función
primiLotto.Kernel.PrimitivesGenerator.Generate(int32,class primiLotto.Kernel.onPrimitiveGenerated)

y sus tiempos en el profiler es de:

6.991,38(Elapsed Time Inclusive)

que, casualmente es muy parecido a con el otro tiempo calculado por el Stopwatch de 7062mseg.

Entonces, ya tenemos una correlacion. El "Elapsed Time Inclusive" mide el tiempo dentro de una función y también el tiempo de las funciones a las que llama. Es decir, el tiempo total, desde que se inicia hasta que termina.

De aquí, vamos a ver si derivamos el significado de las demás variables.

"Elapsed Exclusive Time" en el ejemplo para el método Generate es de 0.59 mseg. ¿como es posible?? esta variable lo que mide es el tiempo que es ha ejecutado el método, sin incluir las funciones hijas. Es como si cuando se llama a una función hija (en este caso por ejemplo al método generatePrimi ) es como si se parase el cronometro y a la vuelta de la función, se pone de nuevo el cronometro.

Entonces, el método que tenga mayor "Elapsed Exclusive Time" es la que me va a decir, que función esta siendo un cuello de botella.

Si ahora nos fijamos en que función tiene mayor ""Elapsed Exclusive Time" , esta es:

Y la función es drawProbability con un tiempo de 23.77mseg. Pero ojo!, hay si tiempo "Elapsed Inclusive Time", es de 1042.92, con lo cual, hay hay 'algo' en la función, que la hace ir más lenta.

Pero vamos a ver que nos dice el Visual Studio, generando el el árbol con las llamadas más costosas.

Nos dice el VS que el cuello de botella está en efectivamente en drawProbability . Y las llamadas a la API del GDI+ es lo que le está haciendo ir más lento. Mirando el código se ve que en cada iteración del bucle, se crea Pen y Brush que se puede crear al principio, ahorrando la creación de estos objetos 49 veces.

Optimizando

Creando los objetos Pen y Brush fuera del bucle en el método drawProbability , en tiempo "Elapsed Time Inclusive" es de 6564 msg.

7062 - 6564 = 498 msg ahora más rápido para 1000 simulaciones.

Truquito

Una de las cosas que se podría hacer para detectar a tiempo que una función está tardando mucho es por poner lo siguiente

public void DoSameThink()

{

    Stopwatch stopwatch = new Stopwatch();

            stopwatch.Start();

  //codigo de la función

//...............................

//...............................

    stopwatch.Stop();

Debug.Assert(stopwatch.ElapsedMilliseconds < 1000, "El método DoSameThink ha superado 1 segundo");

}

ejemplo:

Conclusión No he contado nada que este escrito por otros blogs, libros, pero a mí me ha servido para asimiliar mejor el tema del rendimiento, de como analizar y ver los cuellos de botella. Si tu también estabas en ese caso y te ha ayudado, estupendo!!! Como se ve, hay muchas variables que da el visual studio que aquí no se han nombrado, pero ya con estas dos variables que hemos nombrado, podemos mejorar algo el rendimiento de nuestro código. El código fuente por está aquí por alguien quiere bajarlo y trastear con ello modificandolo. En próximas, a ver si me adentro más en este campo. Félix Romo felix.romo.sanchezseco@gmail.com