Go: Analisando performance com pprof

Introdução

O pprof (Performance Profiler) é uma ferramenta que vem com o Go e que serve para extrair dados de performance, como uso de CPU, alocação de memória, goroutines, entre outros.

A grande utilidade do pprof é que ele nos diz exatamente onde no nosso código os recursos estão sendo utilizados, ou seja, conseguimos achar com facilidade as funções que estão usando mais CPU ou mais memória, e até conseguimos ver a linha exata do código que está causando o problema de performance.

Aplicação de exemplo

Vou usar como exemplo esse código:

package main

import (
    "os"
)

func main() {
    if len(os.Args) != 3 {
        panic("argumentos invalidos")
    }

    b, err := os.ReadFile(os.Args[1])
    if err != nil {
        panic(err)
    }

    err = os.WriteFile(os.Args[2], b, 0666)
    if err != nil {
        panic(err)
    }
}

O que ele faz é simples: copia o conteúdo de um arquivo para outro arquivo, similar ao que o comando cp faz.
Claro que é só um exemplo bobo comparado a aplicações reais, mas é suficiente para praticarmos.

Esse programa tem um problema... Se eu tento copiar um arquivo muito grande, o uso de memória aumenta em mais de 3GB:

Por que isso acontece? Vamos investigar.

Fazendo o profiling

A forma mais prática de fazer o profiling de CPU e memória é criando um teste comum ou de benchmark.
Para isso vou criar um arquivo main_test.go e vou adicionar:

package main

import "testing"

func Test_main_CopyManjaro(t *testing.T) {
    // injetando os argumentos para o programa funcionar
    os.Args = []string{"gp", "manjaro.iso", "manjaro2.iso"}
    main()
}

E daí, se executarmos:

go test .

Ele vai só rodar os testes nesse pacote.

Já para extraírmos os profiles, fazemos:

go test -cpuprofile cpu.prof -memprofile mem.prof .

Analisando os dados de memória

Agora que extraímos os dados que queríamos, vamos analisar na ferramenta web do pprof.
Para isso, basta executar:

go tool pprof -http :8080 mem.prof

E ele vai abrir o profile de memória no seu navegador padrão.

Esse gráfico pode parecer meio intimidador a primeira vista, mas basicamente ele está nos dizendo quais funções chamam quais, e quais usam mais memória:

Se seguirmos o gráfico, a função tRunner (do pacote de testes) chama Test_main, que chama a main, e a main chama os.ReadFile, sendo esse último quem aloca nesse caso 3.82GB.

Indo em View e trocando a visualização para Top chegamos na mesma conclusão.

Otimizando com base no profiling de memória

Descobrimos que a função os.ReadFile é a causadora do problema de uso de memória, porque estamos lendo todo o arquivo em memória e só então escrevendo o conteúdo num novo arquivo.

A solução é ler pedaço por pedaço do arquivo e ir escrevendo em outro arquivo, e para isso podemos usar a função io.Copy.

O código vai ficar assim:

package main

import (
    "os"
    "io"
)

func main() {
    if len(os.Args) != 3 {
        panic("argumentos invalidos")
    }

    src, err := os.Open(os.Args[1])
    if err != nil {
        panic(err)
    }
    defer src.Close()

    dst, err := os.Create(os.Args[2])
    if err != nil {
        panic(err)
    }
    defer dst.Close()

    _, err = io.Copy(dst, src)
    if err != nil {
        panic(err)
    }
}

E o resultado do uso de memória, olhando pelo gerenciador de tarefas é:

Analisando um profiling de CPU

O profiling de CPU desse caso não vai nos dar muita informação interessante, por ser um código extremamente simples, então vou usar um exemplo de outro projeto que fiz para um desafio.

O projeto em questão envolve ler um arquivo e inserir os dados de cada linha num banco Postgres.

O meu programa estava levando 37 segundos para processar 50 mil linhas, então resolvi fazer o profiling de CPU para investigar.
Eu fiz o profiling de CPU e abri o pprof na aba de Flame Graph (new).
Essa aba nos mostra quais funções estão levando mais tempo para executar:

Pode parecer intimidador, mas em resumo o que o gráfico diz para nós é que a função main.main chama diversas funções, como:

• pgx.(*Conn).Exec
• main.CustomerFrom
• Fields

E as funções mais "largas" são as que estão tomando mais tempo para serem executadas, e nesse caso é a pgx.(*Conn).Exec.
Essa função é a que executa a inserção no banco Postgres.

Pesquisando sobre Postgres e estudando a lib pgx eu descobri que uma possível solução era enviar várias inserções de uma vez (chamado de batch), e resolvi experimentar e fazer um novo profiling.
O resultado foi: queda de 37s para 2s no tempo de execução.

Veja que a função pgx.(*Conn).SendBatch e Exec estão tomando uma fatia muito menor do tempo, e o que estava lento agora era a serialização e desserialização de dados.

E em aplicações que "não param"?

Até agora as técnicas de profiling que vimos só vão servir para aplicações que encerram rápido, como scripts, ferramentas de terminal, etc.

Para aplicações que rodam por tempo indeterminado, como servidores e interfaces gráficas, vamos precisar de outra abordagem para fazer esse profiling.

Para manter esse artigo simples e leve, vamos abordar essas técnicas na parte 2.
A parte 1 é mais para te dar uma noção de como funciona profiling em Go e como identificar problemas de performance.

Conclusão

Espero que essa primeira parte tenha te dado uma boa noção de como fazer profiling em Go e também tenha te esclarecido a importância de mensurar antes de otimizar, pois sem métricas você não tem como priorizar o que precisa ser otimizado e vai acabar gastando bastante energia otimizando coisas que não precisam tanto assim.

Aguarde a segunda parte para falarmos como analisar performance de aplicações web e similares, onde como já falamos, são aplicações que rodam por tempo indeterminado e precisam de estratégias diferentes para mensurar performance.