Índice del contenido
Go: profiling o perfilado básico del uso del CPU
Go: profiling o perfilado básico del uso del CPU
Además del testing de pruebas unitarias y la medición del coverage en go , este lenguaje de programación es capaz de realizar un profiling (o perfilar) la eficiencia del código, analizándolo de manera muy detallada. Esto es bastante útil para encontrar cuellos de botella o partes del código muy costosas, que se llaman numerosas veces o cuyo rendimiento pueden mejorarse.
¿Cómo funciona internamente el profiling de Go en GNU/Linux?
GNU/Linux, más específicamente GNU, tiene una señal de alarma llamada SIGPROF , esta señal avisa cuando un contador de tiempo termina de medir el uso del CPU e interrumpe la ejecución del código.
En el profiling de Go, la señal SIGPROF se programa para ser llamada cada 10 ms. Cada vez que se invoca esta señal, se examina la instrucción actual del contador de programa (PC) y se rastrea hacia atrás a la secuencia de instrucciones que la llamaron. El resultado del proceso anterior es un informe de los elementos en la pila de ejecución , conocido como stack trace o seguimiento de pila.
El proceso de profiling va a ralentizar la ejecución del código, pues se interrumpe cada 10ms para ver que se está ejecutando. Como seguramente ya dedujiste, si una función se encuentra múltiples veces en los stack traces que se generan, tras cada señal SIGPROF, significa que ha durado mucho tiempo ejecutándose.
Al finalizar el profiler la herramienta pprof de go organiza los datos para que puedan representarse de una manera más amigable para el usuario.
Profiling o perfilado de CPU en go
Para esta etrada voy a usar el clásico fibonacci por recursión para demostrar las capacidades de profiling de go. Estoy usando go version go1.15.15 linux/amd64.
func Fibonacci(n int) int {
if n <= 1 {
return n
}
return (Fibonacci(n-1) + Fibonacci(n-2))
}
Para el testing en go, justo como te expliqué en la entrada anterior, usaremos un array de structs para manejar los diferentes casos.
func TestFibonacci(t *testing.T) {
tables := []struct {
n int
fibo int
}{
{0, 0},
{1, 1},
{2, 1},
{15, 610},
{17, 1597},
{40, 102334155},
}
for _, table := range tables {
result := Fibonacci(table.n)
if result != table.fibo {
t.Errorf("Fibonacci incorrecta, esperabamos %d, pero obtubimos %d", table.fibo, result)
}
}
}
Obteniendo la información del profiling
Igual que hicimos para ver el coverage en el testing de go , usamos un flag para crear un archivo con la información del profiling en binario, este archivo no lo podemos visualizar directamente.
go test -cpuprofile=cpu.out
PASS
ok _/home/eduardo/Programacion/goTesting/testing 0.813s
Pero podrá ser usado por otras herramientas para visualizarlo de manera más humana.
Visualizar resultados del profiling
Para ver el resumen del uso de cpu usamos tool pprof pasándole como argumento el archivo que contiene los datos del profiling.
go tool pprof cpu.out
File: testing.test
Type: cpu
Time: Feb 10, 2022 at 1:06pm (CST)
Duration: 802.18ms, Total samples = 690ms (86.02%)
Entering interactive mode (type "help" for commands, "o" for options)
Tras ejecutar el comando anterior estaremos dentro de una terminal. Si ejecutamos top veremos el comportamiento de nuestro código.
Mira como Fibonacci ocupa casi la totalidad del tiempo usado.
(pprof) top
File: testing.test
Type: cpu
Time: Feb 10, 2022 at 1:06pm (CST)
Duration: 802.18ms, Total samples = 690ms (86.02%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 690ms, 100% of 690ms total
flat flat% sum% cum cum%
680ms 98.55% 98.55% 680ms 98.55% _/home/eduardo/Programacion/goTesting/testing.Fibonacci
10ms 1.45% 100% 10ms 1.45% runtime.epollwait
0 0% 100% 680ms 98.55% _/home/eduardo/Programacion/goTesting/testing.TestFibonacci
0 0% 100% 10ms 1.45% runtime.findrunnable
0 0% 100% 10ms 1.45% runtime.mcall
0 0% 100% 10ms 1.45% runtime.netpoll
0 0% 100% 10ms 1.45% runtime.park_m
0 0% 100% 10ms 1.45% runtime.schedule
0 0% 100% 680ms 98.55% testing.tRunner
Dentro de la terminal pprof es posible inspeccionar el tiempo promedio de ejecución de cada línea de una función, usando:
list <nombre_funcion>
Tras ejecutar el comando se generará una lista donde podemos ver cada función desglosada linea por linea, junto con su impacto.
De seguro ya observaste que la mayor parte del tiempo la consume la parte recursiva de Fibonacci.
Exportación de resultados
Además de resultados en consola, también podemos visualizar los resultados, de manera más entendible usando el comando web, que crea un pequeño esquema accesible desde el navegador.
Cada caja representa una función individual y las lineas indican el orden en el que unas funciones llaman a las otras.
Como parámetro opcional podemos pasarle el nombre de una función y go filtrará los resultados.
(pprof) web <funcion>
El esquema generado por el comando web puede exportarse a un pdf con el comando pdf.
(pprof) pdf
