javascript - Comprender la salida del generador de perfiles de Firebug

profiling profiler

Question

He estado tratando de usar el generador de perfiles de Firebug para comprender mejor el origen de algunos problemas de rendimiento de JavaScript que estamos viendo, pero estoy un poco confundido por el resultado.

Cuando perfilo algún código, el perfilador informa Perfil (464.323 ms, 26.412 llamadas) . Sospecho que el 464.323 ms es la suma del tiempo de ejecución para esas 26.412 llamadas.

Sin embargo, cuando profundizo en los resultados detallados, veo resultados individuales con un tiempo de ejecución promedio mayor a 464.323 ms, por ejemplo, el resultado con mayor tiempo promedio 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 varios números? ¿En cuáles debo confiar?

Answer 1

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 783.506ms, la mayor parte se gastó en funciones llamadas desde esa función.

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

Answer 2

Cada columna tiene una descripción de lo que significa que coloque el mouse sobre él en Firebug. Asumiré que puede leer cómo funciona cada columna por su cuenta. Sin embargo, definitivamente te has encontrado con algún comportamiento extraño que necesita ser explicado.

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

Sin embargo, el tiempo de una sola función no debe ser mayor que el tiempo total que el generador de perfiles registró para llamadas de JavaScript. Este problema definitivamente es un error, y puedo ver por qué tienes problemas para confiar en Firebug cuando te da un resultado tan paradójico. Creo que he rastreado el motivo por el cual 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 de Profiler haciendo lo siguiente:

1. Vaya a cualquier sitio que use AJAX. (Utilicé http://juicystudio.com/experiments/ajax/index.php )
2. Habilite la depuración de consola / script.
3. Encienda el generador de perfiles.
4. Haga una llamada AJAX. (Múltiples pueden iluminar más el problema).
5. Detenga el generador de perfiles, examine la salida.

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

Lo peor: dado que el tiempo , el tiempo promedio , el mínimo y el máximo cuentan todas las llamadas a funciones anidadas, todas son incorrectas si está 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íe en ninguna de esas columnas por ahora hasta que Firebug corrija el problema. (Es posible que tuvieran la intención de que el comportamiento fuera así, aunque en el mejor de los casos es confuso dejarlo así).

Si no estás usando AJAX, entonces otro problema está en juego; avísanos si eres o no.

Answer 3

Del tutorial de Firebug - Registro, perfil 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 particulares se han invocado.
Porcentaje de columna : Muestra el tiempo que consume cada función en porcentaje.
Columna de tiempo : Muestra la duración de la ejecución desde el punto de inicio de una función hasta el punto final de una función.
Columna prom . : muestra el tiempo promedio de ejecución de una función en particular. Si llama a una función por única vez, no verá las diferencias. Si llama más de una vez, verá las diferencias.
La fórmula para esa columna es
Avg = Own Ttime / Call;
Columna mínima y columna Máx . : muestra el tiempo mínimo de ejecución de una función en particular.
Columna de archivo : el nombre de archivo del archivo donde se encuentra la función.

Answer 4

Por lo que entiendo, así es como funciona ... el tiempo total del perfilador es la suma de la columna "Tiempo propio". Sin embargo, puede observar que algunos valores de tiempo individuales pueden ser mayores que el tiempo total del perfilador. Esas horas extras se gastaron fuera de JavaScript, ej. en una llamada de complemento. Si su función JS hace una llamada a un plugin, por ejemplo, y espera a que la función de complemento regrese a JS, esos tiempos de espera NO serán informados por el tiempo total del perfilador, pero se incluirán en la columna de Tiempo.