c++ - Confuso salida de gprof
optimization profiling (6)
16.637s gprof en un programa de C ++ que tomó 16.637s , según time() , y obtuve esto para la primera línea de salida:
% cumulative self self total
time seconds seconds calls s/call s/call name
31.07 0.32 0.32 5498021 0.00 0.00 [whatever]
¿Por qué lista el 31.07% del tiempo si solo tomó .32 segundos? ¿Es esto un tiempo por llamada? (¿No sería eso auto / llamada?)
Esta es la primera vez que uso gprof , así que sea amable :)
Editar: al desplazarse hacia abajo, parece que gprof solo piensa que mi programa tarda 1.03 segundos. ¿Por qué podría ser tan malo?
Self segundos es el tiempo pasado en [lo que sea].
Los segundos acumulados son el tiempo que se pasa en [lo que sea] y las llamadas que se encuentran arriba (como [lo que sea] + principal)
Ninguno de los dos incluye el tiempo empleado en funciones llamadas desde [lo que sea]. Es por eso que no estás viendo más tiempo en la lista.
Si su función [cualquiera] llama a muchos printf, por ejemplo, su salida de gprof le indica que printf está consumiendo la mayor parte de ese tiempo.
Esta parece ser una muy buena visión general de cómo leer la salida de gprof . El 31.07% que está viendo es una parte del tiempo total de ejecución que gprof piensa que se está gastando en esa función (sin incluir las funciones que llama). Las probabilidades son la razón por la que el porcentaje es tan grande, mientras que el tiempo es pequeño, es que gprof piensa que el programa no dura tanto como tú. Esto se comprueba fácilmente desplazándose hacia abajo en esta primera sección de la salida de gprof: los segundos acumulados se seguirán haciendo más y más grandes hasta que se limite en el tiempo total de ejecución del programa (desde la perspectiva de gprof). Creo que encontrará que esto es aproximadamente un segundo en lugar de los 16 que está esperando.
En cuanto a por qué hay una gran discrepancia allí, no puedo decir. Quizás gprof no está viendo todo el código. ¿O usó tiempo en el código instrumentado mientras estaba perfilando? No esperaría que eso funcione correctamente ...
Sí, esos valores de "segundos" no son por llamada. El porcentaje de tiempo es para la ejecución completa del programa. En efecto, su programa gastó el 31% del tiempo en esa función (debido al número de llamadas + tiempo empleado por llamada).
Es posible que desee leer sobre cómo analizar los perfiles planos de gprof.
Corrección: Lo siento, esos primeros dos segundos son acumulativos, como lo señala el OP.
Creo que es extraño que estés viendo 0 para "self" y "s / call total".
Citando la sección de precisión gprof : "La cantidad real de error suele ser más de un período de muestreo. De hecho, si un valor es n veces el período de muestreo, el error esperado es la raíz cuadrada de n períodos de muestreo. el período de muestreo es de 0.01 segundos y el tiempo de ejecución de foo es de 1 segundo, el error esperado en el tiempo de ejecución de foo es de 0.1 segundos. Es probable que varíe mucho en promedio de una ejecución de generación de perfiles a la siguiente. Más.)"
Además, posiblemente relacionado, podría valer la pena señalar que gprof no perfila programas multiproceso. Es mejor utilizar algo como Sysprof o OProfile en tales casos.
¿Has probado algunas de las otras herramientas mencionadas en esta pregunta ? Sería interesante cómo se comparan.
El cuello de botella resultó estar en E / S de archivos (consulte ¿Es std :: ifstream significativamente más lento que FILE? ). Cambié a la lectura del archivo completo en un búfer y se aceleró enormemente.
El problema aquí es que gprof no parece generar perfiles precisos cuando se espera la E / S de archivos (ver http://www.regatta.cs.msu.su/doc/usr/share/man/info/ru_RU/a_doc_lib /cmds/aixcmds2/gprof.htm ). De hecho, seekg y tellg ni siquiera estaban en la lista de perfiles, ¡y eran el cuello de botella!
Usted está experimentando un problema común a gprof y otros perfiladores basados en los mismos conceptos: 1) muestree el contador del programa para obtener algún tipo de histograma, 2) instrumente las funciones para medir tiempos, conteos y obtener un gráfico de llamadas.
Para localizar realmente problemas de rendimiento, les falta el punto.
No se trata de medir rutinas, sino de encontrar un código culpable.
Supongamos que tiene una muestra que realiza radiografías estroboscópicas del programa al azar en el reloj de pared. En cada muestra, el programa puede estar en el medio de I / O, puede estar en el código que compiló, puede estar en alguna rutina de biblioteca como malloc .
Pero no importa dónde esté, la responsabilidad de pasar ese tramo de tiempo es compartida por cada línea de código en la pila de llamadas , porque si ninguna de esas llamadas se hubiera realizado, no estaría en el proceso de llevarlas a cabo. el trabajo solicitado por esa llamada.
Así que mira cada línea de código que aparece en varias muestras de la pila de llamadas (mientras más muestras tenga, mejor). Ahí es donde está el dinero. No mire dónde está el contador del programa. Hay "bolsillos profundos" en la parte superior de la pila.