Como ler (de verdade) o seu log de benchmark — tempo, memória, CPU e “notes” (Copy)

Exemplo #1

Abaixo está uma leitura guiada do log que você obteve. A ideia é mostrar o que cada métrica significa, como interpretar os números e que perguntas ela responde. Vou usar os valores que você postou como fio condutor.

1) Bloco de tempo

--- Results (Time) ---
Executions: 5000  Successes: 4662  Failures: 338
Min/Mean/Max/StdDev: 0.001 / 0.016 / 0.122 / 0.009 ms
Total time duration: 126 ms

Executions / Successes / Failures

• Executions = total de iterações (5.000).
• Successes / Failures: a soma bate 5.000.
• Você configurou 5% de falhas por exceção e 2% por “business rule” (total esperado ≈ 7%).
  • Falhas observadas: 338/5000 = 6,76%, muito perto do esperado. ✅

Min/Mean/Max/StdDev (ms)

• Min: menor tempo de uma iteração.
• Mean: média aritmética dos tempos.
• Max: maior tempo observado.
• StdDev: desvio padrão (amostral), mede a dispersão; quanto maior, mais “irregulares” são os tempos.

Aqui: média ~ 0,016 ms por iteração, com desvio padrão de 0,009 ms. Para uma carga sintética curta (SpinWait), isso indica latência baixa e relativamente estável.

Total time duration

• É o tempo de parede (wall-clock) do bloco inteiro (todas as iterações) — 126 ms.

2) Bloco de memória

--- Results (Memory) ---
Metric: Private Bytes
Memory Before: 40.37 MB
Memory After : 40.37 MB
Memory Delta : 0 B
Peak (during): 40.37 MB

Metric

• Você escolheu Private Bytes (memória privada do processo). Alternativamente, poderia ser Working Set.

Before / After / Delta / Peak

• Before: leitura antes das iterações.
• After: leitura após todas as iterações.
• Delta = After − Before.
• Peak (during): maior leitura observada durante o loop (amostrada pelo MemorySampleStride).

O Delta = 0 e o Peak = Before significam que este workload não pressiona o heap (não faz alocações líquidas relevantes no processo).
Mesmo que existam alocações transitórias por iteração, o alocador as recicla/solta antes da medição final, então o saldo líquido é zero. Isso é esperado para uma carga sintética centrada em CPU (SpinWait).

3) Bloco de CPU (processo)

--- Results (CPU) ---
User   : 63 ms
Kernel : 78 ms
Total  : 141 ms
Utilization (normalized): 22.4 %

User / Kernel / Total

• User: tempo de CPU gasto em modo usuário.
• Kernel: tempo de CPU gasto no kernel (sistema).
• Total = User + Kernel.

Utilization (normalized)

• Utilização média do processo, normalizada pelo número de núcleos:Utilizac¸a˜o %≈CPU Total (ms)Elapsed (ms)×#cores×100
• Ex.: se você tem 4 cores lógicos e rodou 126 ms, então 141 ms de CPU total ≈ 22,4% (bate com sua leitura).

É normal o CPU Total (~141 ms) ficar um pouco acima do elapsed (~126 ms):pequenas diferenças de janela de medição,trabalho de kernel (timers/esperas),multiprocessamento (em cargas reais multi-thread, poderia ser muito maior que o elapsed).
Aqui, como a carga é basicamente SpinWait single-thread, a utilização normalizada fica bem abaixo de 100%, como esperado.

4) Bloco de “Notes” (telemetria cooperativa do seu código)

--- Results (Notes) ---
SpinWait iters | n=5000 | Min/Mean/Max=0.00 / 2514.16 / 4998.00 | StdDev=1444.38
Path Code (0=ok,1=exc,2=biz) | n=5000 | Min/Mean/Max=0.00 / 0.09 / 2.00 | StdDev=0.34
Is Fail (0/1) | n=5000 | Min/Mean/Max=0.00 / 0.07 / 1.00 | StdDev=0.25

Essas linhas não vêm “do ar”: foi você quem reportou de dentro do DoWorkParam usando MetricsReportNote(…). O Runner agrega automaticamente esses valores numéricos (contagem n, média, min, max, desvio padrão amostral). Isso é fantástico porque traz contexto de negócio para dentro do benchmark.

4.1) SpinWait iters

• O que é: o número de iterações de SpinWait executadas em cada loop (carga sintética de CPU).
• Como interpretar:
  • Min ~ 0, Max ~ 4998 (e não 5000) porque o seu Random(Max(1, MaxSpinWaitIters)) sorteia de 0 até Max-1.
  • Média ≈ metade do máximo (para distribuição uniforme): esperado ≈ 2500; observado 2514,16 ✅.
  • StdDev alto (1444) é esperado em uniforme [0, 5000).

Perguntas que isso responde:

• A carga foi distribuída como eu planejei?
• Houve viés para limites (0 ou Max)?
• A variabilidade de latência está casada com a variabilidade da carga? (spoiler: sim)

4.2) Path Code (0=ok,1=exc,2=biz)

• O que é: Você codificou o “caminho lógico” de cada iteração:
  • 0 = OK, 1 = exceção, 2 = falha de negócio.
• Como interpretar:
  • Com 5% de exceção e 2% de business rule, o valor esperado da média é
    0.05×1+0.02×2=0.09.
    Observado 0.09 ✅.
  • Max = 2 confirma que os três caminhos ocorreram.

Perguntas que isso responde:

• Minhas taxas de erro batem com a configuração?
• Houve execuções realmente tomando o caminho “business” (2)?
• Posso correlacionar “tempo alto” com “caminho de exceção”?

4.3) Is Fail (0/1)

• O que é: Um rótulo binário de falha (0=sucesso, 1=falha).
• Como interpretar:
  • A média ≈ probabilidade de falha.
    Você esperava ~0,07; observou 0,07 ✅.
  • Max = 1 e Min = 0, como esperado.

Perguntas que isso responde:

• Qual foi a taxa de falha real no lote?
• Mudanças de código alteraram a taxa? (alvo clássico para regressão)

5) Cruzando as métricas

• Tempo médio pequeno + CPU normalizada baixa + Memória estável:
  Confirma que seu teste é CPU-bound e curto, com pouca ou nenhuma pressão real de heap.
• Notes comprovam intenção do teste:
  A distribuição do SpinWait está correta; as taxas de falha (exceção/business) batem; e o rótulo binário consolida.
• Quando algo “sai do esperado”:
  • Se o Is Fail sobe, você sabe que houve um efeito funcional, não apenas ruído de latência.
  • Se o tempo degrada mas SpinWait iters não mudou, então há overhead externo (ex.: logging excessivo, sincronização, contenção).
  • Se Memória (Delta/Peak) cresce num teste que não deveria alocar, você tem um sinal de vazamento ou cache não reciclado.
  • Se a CPU normalizada sobe, você está de fato gastando mais ciclos — útil para diferenciar “lento por I/O” de “lento por CPU”.

6) Dicas rápidas de uso

• Quer forçar memória a aparecer? Faça alocações reais por iteração (e libere no fim).
• Quer pressionar CPU? Aumente MaxSpinWaitIters ou faça cálculos reais (hash, sort) no loop.
• Quer ver percentis? Já estão sendo coletados quando KeepSamples=True; é só imprimir P50/P90/P95/P99 do TRunSnapshot.
• Quer “notes” mais ricas?
  • Registre tamanho de input, tipo de caso, flags de recursos (ex.: “usou cache?”, “abriu transação?”).
  • Use nomes numéricos (como você fez) para ganhar estatística automática (média, stddev).
  • Para strings (ex.: “status=ok/fail”), dá para contar frequência em outro passo (ou manter contadores com MetricsReportInc).

7) Conclusão

Você não está só “cronometrando”. Com tempo + memória + CPU + notes, o relatório passa a contar histórias completas:

• “Quanto demorou?” (tempo e percentis)
• “Quanto custo de CPU?” (tempo de CPU e utilização normalizada)
• “Pressionou o heap?” (Private Bytes/Working Set Before/After/Peak)
• “O que estava acontecendo dentro do código?” (Notes numéricos, fiéis ao domínio)

Esse modelo de medição cooperativa é um diferencial: ele eleva o nível do diagnóstico, casa números com contexto e evita leituras superficiais. É exatamente a proposta do TheCodeNaked: métricas que explicam o porquê — não só o quanto.