Como fazemos microbenchmarks em Kotlin

As vezes precisamos fazer alguns testes de performance ou de benchmark, a fim de ter um melhor embasamento na hora de tomar nossas decisões. Dado que não existe muito material sobre o assunto com essa stack específica, pensamos em descrever aqui como fizemos nossa aplicação simples para benchmarks.

Afinal, o que é um microbenchmark?

Um microbenchmark é um teste projetado para medir o desempenho de uma unidade muito pequena: o tempo para chamar um método sincronizado versus um método não sincronizado; a sobrecarga na criação de um encadeamento versus o uso de um conjunto de encadeamentos; o tempo para executar um algoritmo aritmético versus uma implementação alternativa; e assim por diante.

É uma forma bem interessante de verificar se algum fluxo que estamos fazemos está consumindo muito ou pouco tempo ou recursos (CPU, memória, rede, disco, etc). Porém deve ser feito com cautela.

Muitos fatores podem interferir na execução e aferição de um benchmark, como capacidade de processamento do computador, memória disponível, versão do framework, entre outros. Por conta disso, deve ser feito para testes isolados de unidades bem específicas.

Testando uso de reflections para nossos logs

Há alguns meses atrás estávamos estudando a necessidade do uso de Reflection para identificar a função e a classe exata de onde o log foi gerado.

Nossa hipótese era que a utilização de Reflection poderia aumentar o consumo de recursos da função, mas não sabíamos o quanto aumentaria e se isso impactaria de verdade nossas aplicações.

Importação de dependências

Usamos a biblioteca JMH (the Java Microbenchmark Harness) para fazer a comparação. Utilizamos tanto o JMH Core quanto JMH Annotation Processor.

plugins {
    kotlin("jvm") version "1.4.32"
    kotlin("kapt") version "1.4.32"
    id("me.champeau.gradle.jmh") version "0.5.2"
    id("io.morethan.jmhreport") version "0.9.0"
    application
}

No build.gradle.kts do projeto nós declaramos a task para rodar os testes de benchmark

task("benchmarks", type = JavaExec::class) {
  classpath = sourceSets.getByName("test").runtimeClasspath
  main = "br.com.alice.benchmarks.BenchmarksRunnerKt"
}

Além disso importamos a biblioteca orgs.slf4j.Logger para criar nossos logs. A lista de dependências ficou:

dependencies {
    kapt("org.openjdk.jmh:jmh-generator-annprocess:1.25")

    implementation("org.openjdk.jmh:jmh-core:1.25")
    implementation("org.openjdk.jmh:jmh-generator-annprocess:1.25")

    api("ch.qos.logback:logback-classic:1.2.3")
    implementation("net.logstash.logback:logstash-logback-encoder:6.4")

    annotationProcessor("org.openjdk.jmh:jmh-generator-annprocess:1.25")

    testImplementation(kotlin("test-junit"))
}

Criação da função de log

Para realizar o teste, criamos uma abstração para a biblioteca orgs.slf4j.Logger . Só possui uma simples função de logar info, simulando nossa biblioteca interna para logs.

Criando os casos de teste

JMH suporta diferentes tipos de benchmarks: Throughput, AverageTime, SampleTime, and SingleShotTime. São configurados via annotation @BenchmarkMode .

• Throughput: nesse modo, o teste é executado em um período pre determinado e é avaliado o número de vezes que o método em teste foi executado
• AverageTime: inverso ao Throughput, esse método é usado para se ter o tempo médio de cada chamada do método em teste.
• SampleTime: esse método também utiliza um tempo pré determinado, porém aqui algumas chamadas são selecionadas randomicamente e seu tempo avaliado.
• SingleShotTime: mede o tempo de uma única chamada.

Para o nosso caso, utilizamos AverageTime, dessa forma a gente simular os nossos micro-serviços utilizando os métodos de log diversas vezes e ver o quanto isso impactaria o tempo e os recursos dos mesmos.

Configuramos também a unidade de medida temporal para microsegundos, também via annotation @OutputTimeUnit .

Usamos a annotation @Benchmark para definir uma função como test case do benchmarking. Criamos 3 tipos de testes:

• Log sem nenhuma reflection
• Log utilizando reflection através do Throwable para receber os nomes de classe e método.
• Log utilizando reflection através da Thread para receber os nomes de classe e método.

Configuração final do benchmark

Para agrupar todos os testes, configurar saída do resultado e definir últimas configurações, nós criamos o arquivo BenchmarksRunner.kt, assim declarado no gradle.build.kts , mostrado no início do artigo.

As configurações utilizadas no OptionsBuilder:

• include adiciona o teste que vamos realizar. Nele indicamos qual a classe a ser executada, nesse caso o LogReflectionBenchmark .
• forks é o número de testes paralelos que vão ser executados em cada iteração. Utilizamos 2 forks.
• threads é o número de threads a ser utilizada para cada teste. Escolhemos duas threads. Dependendo do número de threads disponíveis na máquina, esse valor pode aumentar.
• warmupBatchSize é o tamanho o grupo de aquecimento. Utilizamos 2 batches.
• warmupIterations é o número de iterações a serem executadas antes de começar a contabilizar o tempo. Esse número é importante pois ajuda a contabilizar depois que a máquina já estiver rodando os testes. Um número muito alto pode impactar negativamente o teste, se o processo já tiver consumido bastante recurso da máquina.
• measurementIterations é o número de iterações, agora contabilizando o tempo de cada teste. O resultado final é montado a partir a média entre as diferentes iterações.

Além disso, definimos como arquivos output benchmark_output.log e benchmark_result.json . Eles vão conter as informações dos testes.

Hora de rodar os testes

Depois de toda a configuração, podemos rodar o BenchmarksRunner.main e aguardar os resultados. Após alguns minutos, o resultado foi mostrado no arquivo benchmark_output.log .

LogReflectionBenchmark.logWithReflectionThreadGetStackTrace     avgt    4  28.860 ± 7.172  us/op
LogReflectionBenchmark.logWithReflectionThrowableGetStackTrace  avgt    4  42.075 ± 11.087  us/op
LogReflectionBenchmark.logWithoutReflection                     avgt    4  0.36028 ±  0.00035  us/op

Como vocês podem ver, a utilização do log sem nenhum tipo de reflection foi cerca de 100x mais rápida do que com uso de qualquer reflection. Isso já foi necessário para que o nosso time decidisse não precisar logar o nome da função e nem da classe.

Teste você mesmo

Caso queira validar também em sua máquina, o código de exemplo está aberto. Você pode fazer o mesmo teste que nós fizemos, ou usar o exemplo para criar seus próprios microbenchmarks em Kotlin.

alice-health/kotlin-benchmark-example

No repositório tem a descrição de como executar os testes. E se você conseguiu testar outros use cases, compartilha aqui com a gente!

Que tal fazer parte desse time?

Estamos buscando pessoas que topem o desafio de transformar a saúde no Brasil através da tecnologia. Clica aqui para saber mais das vagas que temos em aberto!