5. Meça
Cinco experimentos, uma tabela de resultados. Rode cada experimento pelo menos duas vezes e relate a segunda execução (a primeira aquece as JVMs e os pools de conexão). Os números das caixas "forma esperada" são ilustrativos — o que importa é você conseguir explicar os seus números.
| # | Experimento | Botão | O que registrar |
|---|---|---|---|
| A | síncrono vs outbox | NOTIFY_MODE | p50 / p95 / p99 do POST /orders |
| B | queda do notification | parar o contêiner no meio do teste | taxa de erro, pico de lag, tempo de drenagem |
| C | rajada e drenagem | NOTIFY_CONCURRENCY 1 vs 6 | lag ao longo do tempo, tempo de drenagem, atraso p95 do e-mail |
| D | reprocessamento | NOTIFY_IDEMPOTENT | e-mails por pedido depois de um reset de offsets |
| E | pico da venda relâmpago | sala de espera aberta, ADMIT_PER_SECOND=10 | admitidos/s, espera p95, erro do ETA, p95 dos pedidos |
Os scripts do k6
import http from 'k6/http';
import { check } from 'k6';
import exec from 'k6/execution';
const BASE_URL = __ENV.BASE_URL || 'http://localhost:8084';
const RUN = __ENV.RUN || `${Date.now()}`;
export const options = {
scenarios: {
orders: {
executor: 'constant-arrival-rate', // open model: arrivals do not wait for responses
rate: Number(__ENV.RATE || 50),
timeUnit: '1s',
duration: __ENV.DURATION || '60s',
preAllocatedVUs: 50,
maxVUs: 500,
},
},
thresholds: {
http_req_failed: ['rate<0.01'],
http_req_duration: ['p(95)<200'],
},
};
export default function () {
const n = exec.scenario.iterationInTest;
const body = JSON.stringify({
showId: 'show-7', // no waiting room open for this show
holdId: `hold-${RUN}-${n}`, // unique per request: every request is a new order
customerEmail: `fan${n}@example.com`,
amount: 350.0,
});
const res = http.post(`${BASE_URL}/orders`, body, {
headers: { 'Content-Type': 'application/json' },
});
check(res, { 'order created': (r) => r.status === 201 });
}
import http from 'k6/http';
import { check, sleep } from 'k6';
import exec from 'k6/execution';
import { Counter, Trend } from 'k6/metrics';
const BASE_URL = __ENV.BASE_URL || 'http://localhost:8084';
const SHOW = __ENV.SHOW || 'show-42';
const RUN = __ENV.RUN || `${Date.now()}`;
const JSON_HEADERS = { 'Content-Type': 'application/json' };
const waitTime = new Trend('wr_wait_seconds');
const etaError = new Trend('wr_eta_error_seconds');
const admitted = new Counter('wr_admitted');
const gaveUp = new Counter('wr_gave_up');
export const options = {
scenarios: {
fans: {
executor: 'ramping-arrival-rate',
exec: 'fan',
startRate: 0,
timeUnit: '1s',
preAllocatedVUs: 300,
maxVUs: 1500,
stages: [
{ target: 20, duration: '5s' }, // the on-sale opens
{ target: 20, duration: '30s' }, // 20 new fans per second
{ target: 0, duration: '5s' },
],
gracefulStop: '120s', // let the last fans in the queue finish
},
bots: {
executor: 'constant-arrival-rate',
exec: 'bot',
rate: 5,
timeUnit: '1s',
duration: '40s',
preAllocatedVUs: 5,
},
},
thresholds: {
'http_req_duration{name:order}': ['p(95)<300'],
'checks{name:order}': ['rate>0.99'],
'checks{name:bot}': ['rate==1'],
},
};
export function setup() {
http.post(`${BASE_URL}/orders/waiting-room/${SHOW}/open`);
}
export function fan() {
const t0 = Date.now();
let ticket = http.post(`${BASE_URL}/orders/waiting-room/${SHOW}/join`, null, { tags: { name: 'join' } }).json();
const promisedEta = ticket.etaSeconds ?? 0; // admitted right away: no wait was promised
for (let i = 0; i < 300 && ticket.status === 'WAITING'; i++) {
sleep(1);
ticket = http
.get(`${BASE_URL}/orders/waiting-room/${SHOW}/tickets/${ticket.ticketId}`, { tags: { name: 'poll' } })
.json();
}
if (ticket.status !== 'ADMITTED') {
gaveUp.add(1);
return;
}
const waited = (Date.now() - t0) / 1000;
waitTime.add(waited);
etaError.add(waited - promisedEta);
admitted.add(1);
const n = exec.scenario.iterationInTest;
const res = http.post(
`${BASE_URL}/orders`,
JSON.stringify({ showId: SHOW, holdId: `wr-${RUN}-${n}`, customerEmail: `fan${n}@example.com`, amount: 350.0 }),
{ headers: { ...JSON_HEADERS, 'X-Admission-Ticket': ticket.ticketId }, tags: { name: 'order' } },
);
check(res, { 'admitted fan orders': (r) => r.status === 201 }, { name: 'order' });
}
export function bot() {
const n = exec.scenario.iterationInTest;
const res = http.post(
`${BASE_URL}/orders`,
JSON.stringify({ showId: SHOW, holdId: `bot-${RUN}-${n}`, customerEmail: `bot${n}@example.com`, amount: 350.0 }),
{ headers: JSON_HEADERS, tags: { name: 'bot' }, responseCallback: http.expectedStatuses(403) },
);
check(res, { 'queue jumper refused': (r) => r.status === 403 }, { name: 'bot' });
}
export function teardown() {
http.post(`${BASE_URL}/orders/waiting-room/${SHOW}/close`);
}
#!/bin/sh
# Prints the total lag of a consumer group every 2 s. Usage: sh scripts/kafka-lag.sh [group]
GROUP=${1:-notification}
while true; do
LAG=$(docker compose exec -T kafka /opt/kafka/bin/kafka-consumer-groups.sh \
--bootstrap-server kafka:9092 --describe --group "$GROUP" 2>/dev/null \
| awk '$6 ~ /^[0-9]+$/ { s += $6 } END { print s + 0 }')
echo "$(date +%T) lag=$LAG"
sleep 2
done
Rode todo teste do k6 com os percentis no resumo:
A. Síncrono vs outbox
NOTIFY_MODE=sync docker compose up -d --wait order # "before"
k6 run --summary-trend-stats="avg,p(50),p(95),p(99),max" load/orders-load.js
NOTIFY_MODE=outbox docker compose up -d --wait order # "after"
k6 run --summary-trend-stats="avg,p(50),p(95),p(99),max" load/orders-load.js
As variáveis chegam aos contêineres porque o docker-compose.yaml as interpola (NOTIFY_MODE: ${NOTIFY_MODE:-outbox}), como escrito nos passos 2 e 3.
Forma esperada (ilustrativa)
Com EMAIL_LATENCY=50ms, o p50 síncrono fica um pouco acima de 50 ms — o fã paga pelo e-mail em todo pedido — enquanto a versão com outbox responde em poucos milissegundos (dois INSERTs e um commit). A 50 pedidos/s as duas mantêm a taxa, e numa máquina ocupada as caudas medem sobretudo a máquina: compare o p50. Aumente a taxa (RATE=200 DURATION=30s) e a diferença vira um precipício. Uma execução de teste deste lab (outros programas rodando, load average perto de 10 em 8 núcleos) deu:
| Carga | Modo | p50 | p95 | p99 | vazão |
|---|---|---|---|---|---|
| 50/s por 60 s | sync | 58 ms | 132 ms | 352 ms | 50/s |
| 50/s por 60 s | outbox | 3,3 ms | 426 ms | 1,7 s | 49/s |
| 200/s por 30 s | sync | 2,7 s | 7,5 s | 9,3 s | 113/s (o k6 descartou um terço das chegadas) |
| 200/s por 30 s | outbox | 1,8 ms | 32 ms | 95 ms | 200/s |
Os números absolutos dependem da sua máquina; a razão é a lição: com o e-mail no caminho da requisição, todo pedido espera por ele e o serviço satura muito antes. Aqui a chamada HTTP roda dentro da transação do pedido, então cada pedido segura uma das 10 conexões do pool do banco durante todo o e-mail: no máximo 10 / 0,055 s ≈ 180 pedidos/s, mesmo na teoria. Se até a versão com outbox estiver lenta para você, feche outros contêineres (docker ps) e rode de novo.
B. Queda do notification
Rode a carga por 60 s e, em outro terminal, derrube o notification por 20 s no meio:
Faça isso uma vez em cada modo, com sh scripts/kafka-lag.sh rodando em um terceiro terminal. No modo sync, pelo menos um terço dos pedidos falha — uma queda do e-mail virou uma queda de pedidos. Muitas vezes bem mais: numa execução de teste deste lab 54 % das requisições falharam e o k6 descartou mais da metade das chegadas, porque cada pedido esperando pelo notification caído segura uma conexão do banco, o pool de 10 se esgota e os pedidos seguintes esperam 30 s por uma conexão (Connection is not available, request timed out after 30000ms em docker compose logs order). No modo outbox, nenhum pedido falha; o lag sobe enquanto notification está fora e drena depois que ele volta.
C. Rajada e drenagem
NOTIFY_CONCURRENCY=1 docker compose up -d --wait notification
START=$(date -u +%FT%TZ) # when this run starts (UTC)
RATE=100 k6 run load/orders-load.js # kafka-lag.sh in another terminal
Quando o kafka-lag.sh voltar a 0 (com concorrência 1 isso leva vários minutos), meça quão atrasados chegaram os e-mails desta execução:
docker compose exec db psql -U boxoffice -d boxoffice -c "
SELECT count(*) AS emails,
percentile_cont(0.50) WITHIN GROUP (ORDER BY extract(epoch FROM sent_at - occurred_at)) AS p50_s,
percentile_cont(0.95) WITHIN GROUP (ORDER BY extract(epoch FROM sent_at - occurred_at)) AS p95_s
FROM notification.notifications
WHERE occurred_at >= '$START';"
Depois repita os dois blocos com NOTIFY_CONCURRENCY=6. O START limita cada consulta à sua própria execução: os e-mails da outra execução, e do experimento B, distorceriam os percentis.
Preveja antes de rodar: que lag a concorrência 1 vai atingir?
Cada thread consumidora atende no máximo 1 / 50 ms = 20 e-mails/s. Com uma thread e 100 pedidos/s, o backlog cresce a 100 − 20 = 80 mensagens/s: depois de 60 s, ≈ 4 800 mensagens de lag, e ele drena a 20/s → ≈ 240 s para esvaziar. Com seis threads (capacidade 120/s > 100/s) o lag fica perto de zero. Mais de seis threads não ajudariam: o tópico tem seis partições. Uma execução de teste deste lab chegou a cerca de 4 900 mensagens e levou cerca de 320 s para drenar: cada e-mail custa um pouco mais que os 50 ms de latência simulada (SMTP, a transação no banco). Com seis threads o lag ficou abaixo de cerca de 200.
D. Reprocessamento
docker compose stop notification
docker compose exec kafka /opt/kafka/bin/kafka-consumer-groups.sh --bootstrap-server kafka:9092 \
--group notification --topic order-events --reset-offsets --to-earliest --execute
docker compose start notification
Espere o kafka-lag.sh mostrar 0 e compare e-mails com pedidos distintos:
Faça com NOTIFY_IDEMPOTENT=true e com NOTIFY_IDEMPOTENT=false (reinicie o notification com a variável definida, como em C). Sem deduplicação, o reprocessamento reenvia todos os e-mails do tópico: dezenas de milhares no ritmo do consumidor levam vários minutos. Pedidos feitos no modo sync (A, B) nunca passaram pelo Kafka, então o reprocessamento não os repete.
E. Pico da venda relâmpago pela sala de espera
ADMIT_PER_SECOND=10 docker compose up -d --wait order
k6 run --summary-trend-stats="avg,p(50),p(95),p(99),max" load/waiting-room-spike.js
Cerca de 700 fãs chegam em 40 s, a 20 por segundo; a sala deixa entrar 10 por segundo. Confira no resumo: wr_admitted cresce a 10/s, http_req_duration{name:order} fica estável, toda requisição de robô recebe 403, e wr_eta_error_seconds — a espera real menos o ETA prometido na entrada — fica dentro de um ou dois segundos: a Lei de Little, espera = posição / taxa, é uma promessa honesta quando a taxa é constante.
Resultados
Copie esta tabela para o seu repositório (results/lab7.md) e preencha.
| Métrica | Antes | Depois |
|---|---|---|
| A · Vazão (req/s) | ||
A · p50 do POST /orders (ms) | ||
A · p95 do POST /orders (ms) | ||
A · p99 do POST /orders (ms) | ||
| A · Taxa de erro (%) | ||
B · Taxa de erro com notification fora por 20 s (%) | ||
| B · Pico de lag (mensagens) / tempo de drenagem (s) | — | |
| C · Pico de lag, concorrência 1 vs 6 (mensagens) | ||
| C · Tempo de drenagem, concorrência 1 vs 6 (s) | ||
| C · Atraso p95 do e-mail, concorrência 1 vs 6 (s) | ||
| D · E-mails / pedidos distintos após reprocessar (idempotência desligada vs ligada) | ||
| E · Pedidos por segundo durante o pico | — | |
| E · Espera p95 (s) / erro p95 do ETA (s) | — | |
| E · p95 dos pedidos (ms) / robôs recusados (%) | — |
"Antes" é sync (A, B), concorrência 1 (C), idempotência desligada (D). Abaixo da tabela, escreva um parágrafo por experimento: o que mudou, por quê (com a fórmula ou o mecanismo) e o que você faria em seguida em produção.