Í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.

Resultados del comando list de profiling en go que muestra el impacto de cada linea de código.

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.

Resultado del comando web de profiling en go. La función fibonacci se muestra en grande y en rojo.

Como parámetro opcional podemos pasarle el nombre de una función y go filtrará los resultados.

(pprof) web <funcion>

El comando web permite aislar los resultados por función

El esquema generado por el comando web puede exportarse a un pdf con el comando pdf.

(pprof) pdf

Otros recursos sobre profiling

Otros posts recomendados

Eduardo Zepeda picture

Eduardo Zepeda

Desarrollador web y entusiasta de GNU/Linux. Me siento bastante cómodo usando Python, Javascript/Typescript y Go: el odiado lenguaje de la mascotita azul. También creo en las bondades de la criptografía fuera de la especulación monetaria. Mensaje secreto en Vigenere: Yy pgkvnvm yw tvdmg k bp oqntq yonaqniomm dxzdeu. Mgz emzr, rdcyvqkanyyymm znumszl kdepfcqbkjs a ocpgkda huwnbwi. Lkzepwqi mg bucxkz swbyc izztgzwthaj y hmfdh, xjr na kfx, ad pwpcdmm gegd ydmw vgtqalfm zn Vicemmm.