Comprender la salida del perfilador de Firebug

Question

He estado tratando de usar el generador de perfiles de Firebug para comprender mejor la fuente de algunos problemas de rendimiento de JavaScript que estamos viendo, pero la salida me confunde un poco.

Cuando perfilo algún código, el generador de perfiles informa sobre Perfil (464,323 ms, 26,412 llamadas) . Sospecho que 464.323 ms es la suma del tiempo de ejecución de esas 26.412 llamadas.

Sin embargo, cuando profundizo en los resultados detallados, veo resultados individuales con un promedio tiempo de ejecución superior a 464.323 ms, p. el resultado con el tiempo promedio más alto informa los siguientes detalles:

Calls: **1**
Percent: **0%**
Own Time: **0.006 ms**
Time: **783.506 ms**
Avg: **783.506 ms**
Min: **783.506 ms**
Max: **783.506 ms**

Otro resultado informa:

Calls: **4**
Percent: **0.01%**
Own Time: **0.032 ms**
Time: **785.279 ms**
Avg: **196.32 ms**
Min: **0.012 ms**
Max: **783.741 ms**

Entre estos dos resultados, la suma de los resultados de Tiempo es mucho más que 464.323.

Entonces, ¿qué significan estos diversos números? ¿En cuáles debo confiar?

Answer 1

Cada columna tiene una descripción de lo que significa si configura el mouse para que se desplace sobre ella en Firebug. Asumiré que puedes leer cómo funciona cada columna por tu cuenta. Sin embargo, definitivamente ha encontrado algún comportamiento extraño que debe explicarse.

El tiempo propio es la cantidad de tiempo que la función pasó ejecutando código dentro de sí misma. Si la función no llama a otras funciones, entonces tiempo propio debería ser igual a hora . Sin embargo, si hay llamadas de función anidadas, entonces time también cuenta el tiempo dedicado a ejecutarlas. Por lo tanto, el tiempo casi siempre será mayor que el tiempo propio y, en la mayoría de los casos, sumarán más que el tiempo total informado por el generador de perfiles.

Sin embargo, ninguna > función time debería ser mayor que el tiempo total que el generador de perfiles registró para las llamadas de JavaScript. Este problema es definitivamente un error, y puedo ver por qué tienes problemas para confiar en Firebug cuando te da una salida tan paradójica. Creo que he rastreado la razón por la que ocurre este error: AJAX.

Parece que las llamadas AJAX están causando que las columnas que cuentan las llamadas a funciones anidadas informen información incorrecta. Terminan contando tanto el tiempo de ejecución de JavaScript como la solicitud al servidor.

Puede reproducir este error del generador de perfiles haciendo lo siguiente:

1. Vaya a cualquier sitio que use AJAX. (Solía http://juicystudio.com/experiments/ajax/index.php )
2. Habilitar la depuración de consola / script.
3. Encienda el perfilador.
4. Haz una llamada AJAX. (Varios pueden iluminar más el problema).
5. Detenga el generador de perfiles, examine la salida.

En este ejemplo, con respecto al tiempo vs. tiempo propio , el tiempo propio de cada función se suma al tiempo total del perfilador pero la columna time incorpora la cantidad de tiempo que la llamada AJAX tardó en comunicarse con el servidor. Esto significa que la columna hora es incorrecta si está buscando solo la velocidad de ejecución de JavaScript.

Se pone peor: ya que tiempo , tiempo promedio , min y max cuentan todas las llamadas a funciones anidadas, todos son incorrectos si estás usando AJAX. Además de eso, cualquier función que eventualmente use AJAX (en una llamada de función anidada) también informará su hora incorrectamente. ¡Esto significa que muchas funciones pueden estar informando información incorrecta! Así que no confíes en ninguna de esas columnas por ahora hasta que Firebug solucione el problema. (Es posible que pretendieran que el comportamiento fuera así, aunque en el mejor de los casos es confuso dejarlo así).

Si no está utilizando AJAX, hay otro problema en juego; háganos saber si es o no.

Answer 2

Si entiendo las cosas correctamente, es algo como esto:

En la primera línea verá que el tiempo propio es " solo 0.006ms " ;. Eso significa que, aunque el tiempo dedicado a esa función fue de 783.506 ms, la mayor parte se dedicó a funciones llamadas desde esa función.

Cuando uso Firebug para optimizar el código, trato de reducir el "tiempo propio" de funciones que se llaman más. (obviamente, verificando también si hay llamadas de función innecesarias para eliminar por completo)

Answer 3

De Tutorial de Firebug - Registro , Perfiles y línea de comandos (parte II) : (los ejemplos son buenos)

  

Columnas y descripción de Profiler

     

Columna de función : muestra el nombre de cada función.
   Columna de llamada : muestra el recuento de cuántas funciones en particular se han invocado.
   Columna de porcentaje : muestra el tiempo que consume cada función en porcentaje.
   Columna de tiempo : muestra la duración de la ejecución desde el punto inicial de una función hasta el punto final de una función.
   Columna Promedio : Muestra el tiempo promedio de ejecución de una función en particular. Si está llamando a una función solo una vez, no verá las diferencias. Si llama más de una vez, verá las diferencias.
        La fórmula para esa columna es
        Promedio = tiempo propio / llamada;
   Columna mínima y Columna máxima : muestra el tiempo mínimo de ejecución de una función en particular.
   Columna de archivo : el nombre del archivo donde se encuentra la función.

Answer 4

Por lo que entiendo, así es como funciona ... el tiempo total del generador de perfiles es la suma de la columna 'Tiempo propio'. Sin embargo, puede observar que algunos valores de tiempo único pueden ser mayores que el tiempo total del generador de perfiles. Esas horas extras se gastaron fuera de JavaScript, por ejemplo. en una llamada de complemento. Si su función JS realiza una llamada de complemento para, por ejemplo, y espera a que la función de complemento vuelva a JS, entonces esos tiempos de espera NO serán informados por el tiempo total del generador de perfiles, sino que se incluirán en la columna Tiempo.