Introducción
Go posee herramientas para hacer profiling de manera sencilla. Cuando hacemos profiling tratamos de identificar las partes del código que más se demora. Para ello debemos de recopilar datos como tiempos de ejecución, uso de memoria, llamadas de funciones, etc.
En Go, esta herramienta se llama pprof. El enlace anterior se muestran distintas formas de usar esta herramienta, pero en este artículo veremos las dos más comunes:
- Con tests
- En runtime
Con tests
Si tenemos tests y conocemos el caso de prueba que ejercita la parte de código que vamos a analizar, tan solo tenemos que agregar el flag -cpuprofile.
Pongamos este ejemplo sencillo:
package main
import (
"math"
"testing"
)
func compute(n int) {
quickComputation(n)
moderateComputation(n)
heavyComputation(n)
}
func TestComputation(t *testing.T) {
compute(100_000_000)
}
func heavyComputation(n int) float64 {
result := 0.0
for i := 0; i < n; i++ {
result += math.Sqrt(float64(i))
}
return result
}
func moderateComputation(n int) int {
sum := 0
for i := 0; i < n; i++ {
sum += i
}
return sum
}
func quickComputation(n int) int {
return n * (n + 1) / 2
}
Lo esperable es que la función que más tiempo de CPU consuma sea heavyComputation. Veamos que dice pprof:
# Corre el tests y guarda los datos del profile en cpu.prof
go test -cpuprofile=cpu.prof .
# Leemos cpu.prof
go tool pprof cpu.prof
Luego de lanzar el último comando se abre una terminal. Si escribimos top nos muestra el top de funciones que más CPU consumen ordenadas de mayor a menor:
File: profiling.test
Type: cpu
Time: Dec 9, 2024 at 3:01pm (WET)
Duration: 201.10ms, Total samples = 70ms (34.81%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 70ms, 100% of 70ms total
flat flat% sum% cum cum%
40ms 57.14% 57.14% 40ms 57.14% profiling.heavyComputation (inline)
30ms 42.86% 100% 30ms 42.86% profiling.moderateComputation (inline)
0 0% 100% 70ms 100% profiling.TestComputation
0 0% 100% 70ms 100% profiling.compute (inline)
0 0% 100% 70ms 100% testing.tRunner
(pprof)
Como vemos nos muestra heavyComputation en el primer puesto.
Ahora, si escribimos web en la terminal de pprof, nos genera una representación gráfica de las funciones:
En runtime
pprof expone una interfaz HTTP para hacer profiling y recopilar datos en runtime. Este escenario es para cuando no tenemos una primera idea de por donde puede estar el cuello de botella, así que toca correr el software entero y disparar la acción que hace que nuestro programa dispare la CPU.
Para exponer la interfaz HTTP hay que escribir código, pero es bastante sencillo. La documentación está aquí
Adaptemos el ejemplo anterior:
import (
"fmt"
_ "net/http/pprof"
)
func main() {
go func() {
for {
heavyComputation(1_000_000)
moderateComputation(1_000_000)
quickComputation(1_000_000)
time.Sleep(time.Second * 5)
}
}()
// Start http server
fmt.Println("pprof at http://localhost:6060/debug/pprof/")
http.ListenAndServe(":6060", nil)
}
Corremos el programa y comenzamos a registrar datos:
# Arrancar programa
go run .
# Comenzar a almacenar datos de cpuprofile durante 30 segundos
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=30
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=30
Saved profile in /home/andres/pprof/pprof.profiling.samples.cpu.004.pb.gz
File: profiling
Type: cpu
Time: Dec 9, 2024 at 3:42pm (WET)
Duration: 30s, Total samples = 50ms ( 0.17%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 50ms, 100% of 50ms total
flat flat% sum% cum cum%
30ms 60.00% 60.00% 30ms 60.00% main.heavyComputation (inline)
10ms 20.00% 80.00% 10ms 20.00% main.moderateComputation (inline)
10ms 20.00% 100% 10ms 20.00% runtime.findRunnable
0 0% 100% 40ms 80.00% main.main.func1
0 0% 100% 10ms 20.00% runtime.mcall
0 0% 100% 10ms 20.00% runtime.park_m
0 0% 100% 10ms 20.00% runtime.schedule
(pprof)