2009-06-16 12 views
8

Estoy tratando de comenzar con Google Perf Tools para perfilar algunas aplicaciones intensivas de CPU. Es un cálculo estadístico que descarga cada paso a un archivo usando `ofstream '. No soy un experto en C++, así que estoy teniendo problemas para encontrar el cuello de botella. Mi primera pasada da resultados:¿Qué mide exactamente el perfil de C++ (herramientas de rendimiento de la CPU de Google)?

 
Total: 857 samples 
    357 41.7% 41.7%  357 41.7% _write$UNIX2003 
    134 15.6% 57.3%  134 15.6% _exp$fenv_access_off 
    109 12.7% 70.0%  276 32.2% scythe::dnorm 
    103 12.0% 82.0%  103 12.0% _log$fenv_access_off 
     58 6.8% 88.8%  58 6.8% scythe::const_matrix_forward_iterator::operator* 
     37 4.3% 93.1%  37 4.3% scythe::matrix_forward_iterator::operator* 
     15 1.8% 94.9%  47 5.5% std::transform 
     13 1.5% 96.4%  486 56.7% SliceStep::DoStep 
     10 1.2% 97.5%  10 1.2% 0x0002726c 
     5 0.6% 98.1%  5 0.6% 0x000271c7 
     5 0.6% 98.7%  5 0.6% _write$NOCANCEL$UNIX2003 

Esto es sorprendente, ya que se produce todo el cálculo real en SliceStep :: DoStep. El "_write $ UNIX2003" (¿dónde puedo encontrar qué es esto?) Parece provenir de la escritura del archivo de salida. Ahora, lo que me confunde es que si hago un comentario de todas las declaraciones outfile << "text" y ejecuto pprof, el 95% está en SliceStep::DoStep y `_write $ UNIX2003 'desaparece. Sin embargo, mi aplicación no se acelera, medida por el tiempo total. Todo esto acelera menos del 1 por ciento.

¿Qué me estoy perdiendo?

Agregado: La salida pprof sin las declaraciones outfile << es:

 
Total: 790 samples 
    205 25.9% 25.9%  205 25.9% _exp$fenv_access_off 
    170 21.5% 47.5%  170 21.5% _log$fenv_access_off 
    162 20.5% 68.0%  437 55.3% scythe::dnorm 
     83 10.5% 78.5%  83 10.5% scythe::const_matrix_forward_iterator::operator* 
     70 8.9% 87.3%  70 8.9% scythe::matrix_forward_iterator::operator* 
     28 3.5% 90.9%  78 9.9% std::transform 
     26 3.3% 94.2%  26 3.3% 0x00027262 
     12 1.5% 95.7%  12 1.5% _write$NOCANCEL$UNIX2003 
     11 1.4% 97.1%  764 96.7% SliceStep::DoStep 
     9 1.1% 98.2%  9 1.1% 0x00027253 
     6 0.8% 99.0%  6 0.8% 0x000274a6 

Esto se parece a lo que cabe esperar, excepto que veo ningún aumento visible en el rendimiento (0,1 segundos en un segundo cálculo 10) . El código es esencialmente:

ofstream outfile("out.txt"); 
for loop: 
    SliceStep::DoStep() 
    outfile << 'result' 
outfile.close() 

Actualización: Me sincronización utilizando impulso :: temporizador, empezando por donde el generador de perfiles se inicia y termina donde termina. No uso hilos ni nada sofisticado.

+0

¿Cómo se mide el tiempo de ejecución? Haga un "tiempo ./suprograma" para ambas configuraciones. ¿Utiliza multihilo? – ebo

+0

Haz una carrera con el tiempo y mide el tiempo de sys/usr. Los números del perfilador indican que debe tener un 40% menos de tiempo de ejecución sin salida. La explicación más sencilla sería que la medición del perfilador está sesgada. – ebo

+0

Todo está en el usuario. Lo que estoy haciendo es bastante simple, creo ... ¿El hecho de que el archivo esté abierto todo el tiempo significa algo? – Tristan

Respuesta

3

De mis comentarios:

Los números que se obtienen de su perfilador decir, que el programa debe estar alrededor de 40% más rápido y sin las declaraciones de impresión.

El tiempo de ejecución, sin embargo, se mantiene casi igual.

Obviamente, una de las mediciones debe ser incorrecta. Eso significa que debe hacer más y mejores mediciones.

Primero sugiero comenzar con otra herramienta fácil: el comando de tiempo. Esto debería hacerte una idea aproximada de tu tiempo.

Si los resultados todavía no son concluyentes que necesita una mejor caso_prueba:

  • Use un problema mayor
  • hacer un calentamiento antes de medir. Haz algunos bucles y comienza cualquier medición después (en el mismo proceso).

Tiristan: Todo está en el usuario. Lo que estoy haciendo es bastante simple, creo ...¿El hecho de que el archivo esté abierto todo el tiempo significa algo?

Eso significa que el perfilador está equivocado.

Impresión 100000 líneas a la consola utilizando los resultados de pitón en algo así como:

for i in xrange(100000): 
    print i 

a la consola:

time python print.py 
[...] 
real 0m2.370s 
user 0m0.156s 
sys  0m0.232s 

Versus:

time python test.py > /dev/null 

real 0m0.133s 
user 0m0.116s 
sys  0m0.008s 

Mi punto es: Tu medida interna Los y muestran que no se gana nada al desactivar la salida. Google Perf Tools dice que deberías hacerlo. ¿Quién está equivocado?

+0

La operación definitivamente toma 10 segundos, todo básicamente cerca de la función Slice :: DoStep. No entiendo cómo el _write puede desaparecer, después de ser 40%, y no tener ningún impacto ... – Tristan

+0

Ese es el punto. Un número debe estar equivocado. Averigua cuál. Los números que genera el generador de perfiles pueden no ser estadísticamente significativos o simplemente incorrectos. – ebo

1

_write $ UNIX2003 probablemente se está refiriendo a la llamada al sistema POSIX write, que se envía a la terminal. La E/S es muy lenta en comparación con casi cualquier otra cosa, por lo que tiene sentido que su programa pase mucho tiempo allí si está produciendo bastante.

No estoy seguro de por qué su programa no se acelerará cuando elimine la salida, pero realmente no puedo adivinar solo la información que ha proporcionado. Sería bueno ver algunos de los códigos, o incluso los resultados de rendimiento cuando se elimina la instrucción cout.

1

Google perftools recoge muestras de la pila de llamadas, por lo que lo que necesita es obtener algo de visibilidad sobre ellas.

De acuerdo con el documento, puede visualizar el gráfico de llamadas en la granularidad de la instrucción o la dirección. Eso debería decirte lo que necesitas saber.

Cuestiones relacionadas