domingo, septiembre 21, 2014

VFP: Usando el Coverage Profiler para tunear el sistema

Por: Fernando D. Bozzo

Como todos saben, el comando SET COVERAGE genera un LOG de texto de las líneas de ejecución de los programas de un sistema, en este formato:

   0.000261,c_foxbin2prg,init,649,c:\desa\foxbin2prg\foxbin2prg.fxp,2
   0.000432,c_foxbin2prg,init,650,c:\desa\foxbin2prg\foxbin2prg.fxp,2
   0.000013,,foxbin2prg,434,c:\desa\foxbin2prg\foxbin2prg.fxp,1
   3.293160,,foxbin2prg,436,c:\desa\foxbin2prg\foxbin2prg.fxp,1
   0.001645,c_foxbin2prg,ejecutar,1527,c:\desa\foxbin2prg\foxbin2prg.fxp,2
   0.000460,c_foxbin2prg,ejecutar,1531,c:\desa\foxbin2prg\foxbin2prg.fxp,2
   0.000130,c_foxbin2prg,ejecutar,1533,c:\desa\foxbin2prg\foxbin2prg.fxp,2
   0.000403,c_foxbin2prg,ejecutar,1534,c:\desa\foxbin2prg\foxbin2prg.fxp,2




¿Cómo se usa el SET COVERAGE?


Su uso es muy sencillo, sólo hay que poner esta línea donde se quiera comenzar a generar el LOG:

SET COVERAGE TO <Archivo_de_LOG>

Y para detener la generación, se usa esta otra:

SET COVERAGE TO


Ejemplo de uso de SET COVERAGE:



Luego, al ejecutar el programa, todas las líneas que se ejecuten como consecuencia de su uso, quedarán apuntadas en el LOG.

Por ejemplo, si tuviéramos un menú con 3 opciones que son evaluadas en un DO CASE, y al ejecutar el programa solo entramos en una opción, se loguearán como ejecutadas sólo las líneas del CASE correspondiente a la opción que se utilizó. Para que se logueen todas las condiciones del DO CASE se deberá entrar en todas las opciones del menú, ya que cada selección loguerá las líneas que ejecute.


La mayoría cree que este archivo LOG es para abrir con MODIFY FILE o con un editor de texto y ver las líneas una a una, para saber qué se ejecutó, pero realmente esa es una pequeña parte de la historia...




Descubriendo el poder del Coverage Profiler


Hay una herramienta que viene con Visual FoxPro desde la versión 6 en adelante, que es el Coverage Profiler, y que se encuentra en el menú Tools (o Herramientas en Español):



El Coverage Profiler sirve para:

  • Obtener estadísticas de uso de los programas
  • Saber qué líneas se ejecutan y cuáles no en cada uno
  • Saber cuánto tarda la ejecución de un método o procedimiento
  • Encontrar cuellos de botella para posterior mejora

 Una vez generado el LOG, se abre el Coverage Profiler del menú Tools y se selecciona el LOG generado para que sea analizado:




Al terminar de procesar el LOG, se muestra la ventana por defecto en el modo Coverage (cobertura de código), donde se marca con un símbolo "|" a la izquierda las líneas de código que no se han ejecutado.

En la parte superior, bajo los iconos, se muestra una lista de los archivos cuyo código fuente ha sido escaneado, y de donde se puede seleccionar qué archivo ver. En este caso tenemos un solo archivo.

Pantalla de la vista Coverage (icono azul del cuaderno, arriba, en el medio):




 Si elegimos el icono de al lado, del rayo amarillo, seleccionaremos el modo Profiler, donde se mostrará información extra por cada línea, como cantidad de veces que se ejecutó (hits), tiempo de la primera ejecución (1st) y tiempo medio de ejecución (Avg).


Ejemplo de la vista Profiler (icono amarillo del rayo, arriba, en el medio):



CVP: El Coverage Profiler mejorado


Además de este Profiler, existe otro, bastante mejorado y con algunas funciones más, que permite ver la información más rápidamente, trae más estadísticas que pueden ajustarse, y resalta las líneas de ejecución más lentas para no tener que revisar todo el código y que salte a la vista:




Haciendo doble-click en la 2da línea de la pantalla anterior (c_foxbin2prg.ejecutar), se abre automáticamente ese método para su análisis:




¿Cómo se usa el Coverage Profiler (CVP) para tunear un sistema?


Ante todo, hay que tener presente que esta herramienta nos da información y estadísticas sobre nuestro sistema, no esperen ningún botón mágico que tunee nada, ya que esto está pensado para entregar a los desarrolladores la información necesaria para que puedan encontrar rápidamente las funciones más lentas y que puedan mejorarlas, por ejemplo mediante refactorización o incluso mediante su rediseño.

Para sacar el mayor provecho de esta herramienta, el análisis conviene hacerlo así:

1. En la primera pantalla (la de estadísticas de ejecución), seguir el orden de los programas de arriba hacia abajo, ya que el orden comienza por lo más lento

2. Una vez dentro del código del programa (ventana de Profile), buscar las llamadas que sean más lentas, que típicamente serán llamadas a métodos o procedimientos

3. Una vez dentro del procedimiento, ya podemos observar que partes son las más lentas, según el tiempo de ejecución de sus líneas y de la cantidad de veces que se ejecutan.

4. Cuando se termine de analizar el código, se puede volver hasta atrás, al punto 2, y continuar con el siguiente procedimiento, y finalmente al punto 1 para elegir el siguiente programa



Algunos tips para mejoras de performance en el código


- Cuando se encuentre un bloque de código cuyas líneas se ejecutan muchas veces, si se usan referencias a objetos del tipo "thisform.objeto1.objeto2.objeto3.propiedad", asignando el objeto completo a una variable fuera del bloque (ej: obj3 = thisform.objeto1.objeto2.objeto3) y usando la variable dentro del bloque (ej: obj3.propiedad) se puede ganar bastante velocidad, y más cuantas más veces se ejecute el bloque

- Si en el caso anterior hubieran muchas líneas de acceso al objeto, puede que sea más eficiente usarlas dentro de un WITH <objeto>

- Si hay funciones, consultas u operaciones que se repiten mucho, ver la posibilidad de cachear el resultado de la misma en una variable si fuera posible, y usar esa variable en su lugar



Descarga de CVP

Dejo a continuación los links de descarga del programa CVP, tanto de su página original como de GDrive por si la otra no estuviera disponible:

CVP: Link de descarga original a la página


CVP: Link de descarga secundario a GDrive (v1.18.02)



Como puede verse, esta herramienta es una gran desconocida, y tiene mucho para ofrecer.
Espero que a partir de ahora, puedan aprovecharla.


Hasta la próxima nota! :D

2 comentarios:

  1. Excelente forma de analizar el coverage. Siempre tan util.
    Te comento un detalle si el log generado es grande puede que el profiler de VFP de error, pero el CVP no lo da.
    Con esta nueva optica voy a implementar en mis sistemas con control centralizado de errores un metodo para generar un cover a pedido, ya que el CVP me puede dar una mano con los errores crónicos.

    ResponderEliminar
    Respuestas
    1. Hola Pancho:

      En algunos casos a mí también me dió error, sobre todo cuando el LOG superaba el gigabyte (que es una burrada). Una solución a este problema, y sólo cuando el LOG es muy grande, es activar el profiler selectivamente para ciertos métodos y generar un LOG distinto para cada uno, así no se recarga un único LOG, aunque a costa de perder el panorama completo, al menos permite buscar las partes lentas.

      Saludos!

      Eliminar