Golang: How Observability and Profiling Revealed Nearly Undetectable Throttling

In a personal project with Go, which obtains information on financial assets from Bovespa.
The system makes intense use of concurrency and parallelism with goroutines, updating asset information (along with business calculations) every 8 seconds.
Initially, no errors or warnings appeared, but I noticed that some goroutines were taking longer than others to execute.

To be more specific, while the p99 time was 0.03 ms, at some points, it increased to 0.9 ms. This led me to investigate the problem further.

I discovered that I was using a semaphore goroutine pool, which was created based on the GOMAXPROCS variable.
However, I realized there was a problem with this approach.

When we use the GOMAXPROCS variable, it does not correctly capture the number of cores available in the container. If the container has fewer available cores than the VM's total, it considers the VM's total. For example, my VM has 8 cores available, but the container only had 4. This resulted in creating 8 goroutines to run at the same time, causing throttling.

After a lot of research overnight, I found a library developed by Uber that automatically adjusts the GOMAXPROCS variable more efficiently, regardless of whether it is in a container or not. This solution proved to be extremely stable and efficient: automaxprocs

uber-go / automaxprocs

Automatically set GOMAXPROCS to match Linux container CPU quota.

automaxprocs

Automatically set GOMAXPROCS to match Linux container CPU quota.

Installation

go get -u go.uber.org/automaxprocs

Quick Start

import _ "go.uber.org/automaxprocs"

func main() {
  // Your application logic here.
}

Performance

Data measured from Uber's internal load balancer. We ran the load balancer with 200% CPU quota (i.e., 2 cores):

GOMAXPROCS	RPS	P50 (ms)	P99.9 (ms)
1	28,893.18	1.46	19.70
2 (equal to quota)	44,715.07	0.84	26.38
3	44,212.93	0.66	30.07
4	41,071.15	0.57	42.94
8	33,111.69	0.43	64.32
Default (24)	22,191.40	0.45	76.19

When GOMAXPROCS is increased above the CPU quota, we see P50 decrease slightly, but see significant increases to P99. We also see that the total RPS handled also decreases.

When GOMAXPROCS is higher than the CPU quota allocated, we also saw significant throttling:

$ cat /sys/fs/cgroup/cpu,cpuacct/system.slice/[...]/cpu.stat
nr_periods 42227334
nr_throttled 131923
throttled_time 88613212216618

Once GOMAXPROCS was reduced to match the CPU quota, we saw no CPU throttling.

…

View on GitHub

.

Após implementar o uso dessa biblioteca, o problema foi resolvido, e agora o tempo p99 se manteve em 0.02 ms constantemente. Essa experiência destacou a importância da observabilidade e do profiling em sistemas concorrentes.

A seguir um exemplo bem simples, mas que consegue demonstrar a diferença de desempenho.

Utilizando o pacote nativo de testes e benckmak do Go, criei dois arquivos:

benchmarking_with_enhancement_test.go:

package main

import (
    _ "go.uber.org/automaxprocs"
    "runtime"
    "sync"
    "testing"
)

// BenchmarkWithEnhancement Função com melhoria, para adicionar o indice do loop em um array de inteiro
func BenchmarkWithEnhancement(b *testing.B) {
    // Obtém o número de CPUs disponíveis
    numCPUs := runtime.NumCPU()
    // Define o máximo de CPUs para serem usadas pelo programa
    maxGoroutines := runtime.GOMAXPROCS(numCPUs)
    // Criação do semáforo
    semaphore := make(chan struct{}, maxGoroutines)

    var (
        // Espera para grupo de goroutines finalizar
        wg sync.WaitGroup
        // Propriade
        mu sync.Mutex
        // Lista para armazenar inteiros
        list []int
    )

    // Loop com mihão de indices
    for i := 0; i < 1000000; i++ {
        semaphore <- struct{}{}
        // Adiciona ao waitGroup que existe mais uma goroutine para ser executada
        wg.Add(1)

        // Atribui a função a uma nova goroutine
        go func(i int) {
            // Quando a função finalizar, informa o semáforo e finaliza um registro do waitGroup
            defer func() {
                <-semaphore
                wg.Done()
            }()
            // Faz o bloqueio do array para outra goroutine não sobreescrever
            mu.Lock()
            // Adiciona o indice, em mais uma posição no array
            list = append(list, i)
            // Desbloqueia o array
            mu.Unlock()
        }(i)
    }
}

benchmarking_without_enhancement_test.go:

package main

import (
    "runtime"
    "sync"
    "testing"
)

// BenchmarkWithoutEnhancement Função sem a melhoria, para adicionar o indice do loop em um array de inteiro
func BenchmarkWithoutEnhancement(b *testing.B) {
    // Obtém o número de CPUs disponíveis
    numCPUs := runtime.NumCPU()
    // Define o máximo de CPUs para serem usadas pelo programa
    maxGoroutines := runtime.GOMAXPROCS(numCPUs)
    // Criação do semáforo
    semaphore := make(chan struct{}, maxGoroutines)

    var (
        // Espera para grupo de goroutines finalizar
        wg sync.WaitGroup
        // Propriade
        mu sync.Mutex
        // Lista para armazenar inteiros
        list []int
    )

    // Loop com mihão de indices
    for i := 0; i < 1000000; i++ {
        semaphore <- struct{}{}
        // Adiciona ao waitGroup que existe mais uma goroutine para ser executada
        wg.Add(1)

        // Atribui a função a uma nova goroutine
        go func(i int) {
            // Quando a função finalizar, informa o semáforo e finaliza um registro do waitGroup
            defer func() {
                <-semaphore
                wg.Done()
            }()
            // Faz o bloqueio do array para outra goroutine não sobreescrever
            mu.Lock()
            // Adiciona o indice, em mais uma posição no array
            list = append(list, i)
            // Desbloqueia o array
            mu.Unlock()
        }(i)
    }
}

A diferença entra elas, é que uma esta com a importação de biblioteca da Uber.

Ao executar o benchmark passando que seriam usados 2 CPUs, o resultado foi:

ns/op: fornece uma média em nanosegundos de quanto tempo leva para executar uma operação específica.

Percebam, que o total disponível da minha CPU são 8 núcleos, e foi o que a propriedade runtime.NumCPU() retornou. Porém, como na execução do benchmark, defini que o uso seriam de apenas duas CPUs, a o arquivo que não utilizou a automaxprocs, definiu que o limite de execução por vez, seriam de 8 goroutines, enquanto o mais eficiente seriam 2, pois dessa maneira se usa menos alocação deixa mais eficiente a execução.

Então, fica nítido a importância de observabilidade e proffiling das nossas aplicações.