¿Por qué las estadísticas línea por línea para NYTProf no coinciden con los totales?

Question

Tengo un script Perl que tarda unos 30 minutos en ejecutarse, así que por supuesto ejecuto Devel :: NYTProf. Gran perfilador. Para muchos de mis subs, obtengo algunos datos que no tienen sentido para mí.

Me estoy ejecutando con Perl 5.10.0 en Linux usando la configuración predeterminada de NYTProf.

En el resultado HTML, cada uno de los subs tiene una sección de resumen que indica cuánto tiempo se pasa en el sub y sus hijos y luego pasa a darme información de línea.

Las estadísticas de línea no suman el total gastado en la función. ¿Lo que da?

Por ejemplo, tengo una función que se informa que usa 233s (57 + 166). El informe de número de línea por línea tiene una línea que usa 20, otra que usa 4 y una que usa 2. Las otras líneas son < 1s y la función no es tan larga.

¿Qué puedo hacer para resolver esta discrepancia?

Podría pasar a Perl 5.12, pero eso requeriría cierto trabajo para instalar las dependencias. Me complace ejecutarlo en un modo más lento. ¿Hay alguna manera de aumentar la frecuencia de muestreo? Ejecutar en una máquina más lenta?

Haga clic aquí para ver una muestra: my NYTProf output. En este caso, se informa que el submarino usa 225 segundos, pero agregar todos los números produce 56 segundos. Esta carrera se había desactivado optimización:

setenv NYTPROF optimize=0:file=nytprof.optout 

actualización He volver a ejecutar con Perl 5.12 utilizando el findcaller bandera = 1 opción como se sugiere con más o menos los mismos resultados. (Corrí en un conjunto de datos diferente)

Actualización Tim B tiene razón. He cambiado algunos de mis subs claves para hacer el almacenamiento en caché ellos mismos en vez de usar memoize y los resultados de NYTProf son útiles de nuevo. Gracias Tim

Answer 1

que acaba de añadir esto a la documentación NYTProf:

= head2 Si la declaración de subrutinas y sincronizaciones no coinciden

NYTProf tiene dos perfiladores: una declaración de perfiles que se invoca cuando perl se mueve desde una instrucción perl a otra, y un perfilador de subrutina que se invoca cuando las llamadas perl o regresa de una subrutina.

Los horarios de los estados individuales para una subrutina por lo general se suman a poco menor que el tiempo exclusivo para el subrutina. Esto se debe a que el manejo de la llamada de subrutina y gastos generales de devolución se incluye en el tiempo exclusivo de para la subrutina. La diferencia solo puede ser un nuevo microsegundos, pero puede volverse perceptible para las subrutinas que son llamadas cientos de miles de veces.

La declaración de perfiles mantiene un seguimiento de cómo se gastó mucho tiempo en los gastos generales, al igual que los datos del perfil comunicado escritura para disco. El perfilador de subrutina resta los gastos generales que tienen acumulados entre la entrada y dejando la subrutina para dar un perfil más preciso. El perfilador de instrucciones es generalmente muy rápido porque la mayoría de las escrituras se almacenan en el buffer para la compresión de zip, por lo que el perfilador overhead por extracto tiende a ser muy pequeño, a menudo un solo 'tic'. El resultado es que la sobrecarga acumulada es bastante ruidosa. Esto se convierte en más significativo para subrutinas que se llaman con frecuencia y también son rápido. Esta puede ser otra contribución más pequeña, a la discrepancia entre el tiempo de extracto y las veces exclusivas .

Eso probablemente explica la diferencia entre la suma de la columna de tiempo comunicado (31.7s) y el tiempo de exclusiva reportado para la subrutina (57.2s). La diferencia asciende a aproximadamente 100 microsegundos por llamada (lo que parece un poco alto, pero no sin razón).

El generador de informes de seguimiento realiza un seguimiento de cuánto tiempo se gastó en gastos generales, como escribir datos de perfil de estado en el disco. El perfilador de subrutina resta la diferencia en los gastos generales entre entrar y salir de la subrutina para dar un perfil más preciso.

El generador de informes de estado general es muy rápido porque la mayoría de las escrituras se almacenan en búfer para la compresión de zip, por lo que la sobrecarga del generador de perfiles tiende a ser muy pequeña, a menudo un solo 'tic'. El resultado es que la carga general acumulada es bastante ruidosa. Esto se vuelve más significativo para las subrutinas que se llaman con frecuencia y también son rápidas (en este caso, 250303 llama a 899 μs/llamada). Entonces, sospecho que esta es otra contribución más pequeña a la discrepancia entre el tiempo de declaración y los tiempos exclusivos.

Más importante aún, También he añadido esta sección:

= head2 Si Headline subrutinas con sincronizaciones no coinciden con los llamados Subs

general tiempos de subrutinas son reportados con un titular como "gastaron 10s (2 + 8) dentro ... ". En este ejemplo, 10 segundos se pasaron dentro de la subrutina (el "tiempo inclusivo") y, de eso, se pasaron 8 segundos en las subrutinas llamadas por este. Que deja 2 segundos como el tiempo pasado en el código de subrutina en sí (el "tiempo exclusivo", a veces también llamado "tiempo propio").

El informe muestra el código fuente de la subrutina. Las líneas que realizan llamadas a otras subrutinas se anotan con detalles del tiempo pasado en esas llamadas.

veces la suma de los tiempos de llamadas realizadas por las líneas de código en la subrutina es menor que el tiempo de incluido exclusiva reportado en el titular (10-2 = 8 segundos en el ejemplo anterior ) .

lo que está sucediendo aquí es que las llamadas se realizan a otras subrutinas pero NYTProf no es capaz de determinar la ubicación de llamar correctamente para las llamadas no aparecen en el informe en el lugar correcto.

El uso de una versión anterior de perl es una causa (see below). Otro está llamando a las subrutinas que salen por "goto & sub;" - se encuentra con más frecuencia en SUB y código AUTOLOAD utilizando el módulo Memoize .

En general, el tiempo global subrutina es precisa y debe ser de confianza más que la suma de los tiempos de declaración o sub llamadas anidadas.

El módulo Memoize es la causa principal de la discrepancia en su informe. Las llamadas al Memoize::__ANON__[...] ejecutan un sub generado por Memoize que se parece a sub { unshift @_, $cref; goto &_memoizer; }. Ese goto &_memoizer es implementado por perl como una especie de retorno a la persona que llama, seguido de una llamada al sub especificado, y esa es la forma en que NYTProf lo perfila.

La confusión es causada por el hecho de que, a pesar de add_bit_to_map se está grabando como la persona que llama de _memoizer lo que el tiempo de la llamada se agrega a add_bit_to_map, el archivo y la línea de ubicación del número de la llamada se registra como la ubicación de la goto.

Puede ser posible mejorar esto en versiones futuras.

Gracias por pedirme que investigue esto y mejore la documentación.

Tim Bunce.

p.s. Recomiendo hacer preguntas sobre NYTProf en el mailing list.

Answer 2

Intente deshabilitar el optimizador de perl. De CPAN's Devel::NYTProf docs:

Optimizar = 0

Desactivar el optimizador de Perl.

De forma predeterminada, NYTProf deja habilitado el optimizador de perl. Eso le da más tiempo de perfil exacto de en general, pero puede conducir a conteos de declaraciones impares para conjuntos individuales de líneas. Eso es porque el optimizador de mirilla de perl ha reescrito efectivamente las declaraciones , pero no se puede ver cómo se ve la versión reescrita .

Por ejemplo:

1  if (...) { 
2   return; 
3  } may be rewritten as 

1 return if (...) 

por lo que el perfil no va a mostrar un recuento de declaración para la línea 2 en el código fuente porque el retorno se fusionó con el declaración si en la línea precedente.

Utilizando el Optimizar = 0 desactiva la opción el optimizador de manera que obtendrá más baja rendimiento general, pero más recuento de los estados asignados con precisión.

Si encuentra algún otro ejemplo del efecto del optimizador en la salida NYTProf (que no sea el rendimiento, obviamente) por favor sepamos.