Debug de requisição http com K6📑
Tags: performance, k6, testing
Published: 2023-02-25 16:31:07

Quando realizamos testes de performance, é importante contar com depuração para entender o que está acontecendo durante as requisições. 

Nesse conteúdo, veremos como utilizar o modo de depuração do K6.

![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/ggqhmp3uetw7pgpy9q9i.png)

## Mão na massa👩‍💻

### Script de exemplo📚

Vamos começar com um script de exemplo, que faz uma requisição a API do K6 para listagem de crocodilos cadastrados:

```
import http from "k6/http";

export default function() {
      http.get("https://test-api.k6.io/public/crocodiles");
}
```

### Execução sem depuração ❌

Executando o script acima utilizando o comando `k6 run debbug-request.js` , teremos a seguinte saída:

```

          /\      |‾‾| /‾‾/   /‾‾/
     /\  /  \     |  |/  /   /  /
    /  \/    \    |     (   /   ‾‾\
   /          \   |  |\  \ |  (‾)  |
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: .\debbug-request.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)


running (00m00.8s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  00m00.8s/10m0s  1/1 iters, 1 per VU

     data_received..................: 6.5 kB 8.3 kB/s
     data_sent......................: 638 B  809 B/s
     http_req_blocked...............: avg=235.45ms min=0s       med=235.45ms max=470.9ms  p(90)=423.81ms p(95)=447.35ms
     http_req_connecting............: avg=72.03ms  min=0s       med=72.03ms  max=144.07ms p(90)=129.67ms p(95)=136.87ms
     http_req_duration..............: avg=138.38ms min=124.39ms med=138.38ms max=152.37ms p(90)=149.57ms p(95)=150.97ms
       { expected_response:true }...: avg=138.38ms min=124.39ms med=138.38ms max=152.37ms p(90)=149.57ms p(95)=150.97ms
     http_req_failed................: 0.00%  ✓ 0        ✗ 2
     http_req_receiving.............: avg=7.01ms   min=5.33ms   med=7.01ms   max=8.69ms   p(90)=8.35ms   p(95)=8.52ms
     http_req_sending...............: avg=0s       min=0s       med=0s       max=0s       p(90)=0s       p(95)=0s
     http_req_tls_handshaking.......: avg=94.66ms  min=0s       med=94.66ms  max=189.32ms p(90)=170.39ms p(95)=179.85ms
     http_req_waiting...............: avg=131.36ms min=119.06ms med=131.36ms max=143.67ms p(90)=141.21ms p(95)=142.44ms
     http_reqs......................: 2      2.534658/s
     iteration_duration.............: avg=768.07ms min=768.07ms med=768.07ms max=768.07ms p(90)=768.07ms p(95)=768.07ms
     iterations.....................: 1      1.267329/s
```

### Execução com depuração🔬

Para habilitar a depuração, adicionamos à execução do script a propriedade `--http-debug`. Há dois modos possíveis de depuração:

- --http-debug: exibe as solicitações e respostas HTTP, ignorando o corpo.
- --http-debug="full": exibe as solicitações e respostas HTTP, incluindo o corpo inteiro.

Executando o script utilizando o comando `k6 run --http-debug debbug-request.js`, teremos a seguinte saída:

```
          /\      |‾‾| /‾‾/   /‾‾/
     /\  /  \     |  |/  /   /  /
    /  \/    \    |     (   /   ‾‾\
   /          \   |  |\  \ |  (‾)  |
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: .\debbug-request.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

INFO[0001] Request:
GET /public/crocodiles HTTP/1.1
Host: test-api.k6.io
User-Agent: k6/0.38.3 (https://k6.io/)
Accept-Encoding: gzip

  group= iter=0 request_id=f6816da2-a76a-4a6f-55ba-7d2af7183f50 scenario=default source=http-debug vu=1
INFO[0001] Response:
HTTP/1.1 301 Moved Permanently
Connection: keep-alive
Content-Type: text/html; charset=utf-8
Date: Sat, 25 Feb 2023 14:57:12 GMT
Location: /public/crocodiles/
X-Frame-Options: SAMEORIGIN
Content-Length: 0

  group= iter=0 request_id=f6816da2-a76a-4a6f-55ba-7d2af7183f50 scenario=default source=http-debug vu=1
INFO[0001] Request:
GET /public/crocodiles/ HTTP/1.1
Host: test-api.k6.io
User-Agent: k6/0.38.3 (https://k6.io/)
Referer: https://test-api.k6.io/public/crocodiles
Accept-Encoding: gzip

  group= iter=0 request_id=7bc1e20f-7fef-4e88-5b40-d2f718df9529 scenario=default source=http-debug vu=1
INFO[0001] Response:
HTTP/1.1 200 OK
Content-Length: 609
Allow: GET, HEAD, OPTIONS
Connection: keep-alive
Content-Type: application/json
Date: Sat, 25 Feb 2023 14:57:12 GMT
Vary: Accept
X-Frame-Options: SAMEORIGIN

  group= iter=0 request_id=7bc1e20f-7fef-4e88-5b40-d2f718df9529 scenario=default source=http-debug vu=1

running (00m00.7s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✗ [======================================] 1 VUs  00m00.7s/10m0s  1/1 iters, 1 per VU

     data_received..................: 6.5 kB 9.3 kB/s
     data_sent......................: 638 B  912 B/s
     http_req_blocked...............: avg=165.14ms min=514.4µs  med=165.14ms max=329.77ms p(90)=296.84ms p(95)=313.3ms
     http_req_connecting............: avg=53.29ms  min=0s       med=53.29ms  max=106.58ms p(90)=95.92ms  p(95)=101.25ms
     http_req_duration..............: avg=157.83ms min=133ms    med=157.83ms max=182.67ms p(90)=177.7ms  p(95)=180.18ms
       { expected_response:true }...: avg=157.83ms min=133ms    med=157.83ms max=182.67ms p(90)=177.7ms  p(95)=180.18ms
     http_req_failed................: 0.00%  ✓ 0        ✗ 2
     http_req_receiving.............: avg=45.06ms  min=17.38ms  med=45.06ms  max=72.74ms  p(90)=67.21ms  p(95)=69.98ms
     http_req_sending...............: avg=1.07ms   min=0s       med=1.07ms   max=2.15ms   p(90)=1.94ms   p(95)=2.05ms
     http_req_tls_handshaking.......: avg=92.1ms   min=0s       med=92.1ms   max=184.2ms  p(90)=165.78ms p(95)=174.99ms
     http_req_waiting...............: avg=111.69ms min=107.76ms med=111.69ms max=115.61ms p(90)=114.83ms p(95)=115.22ms
     http_reqs......................: 2      2.857884/s
     iteration_duration.............: avg=683.8ms  min=683.8ms  med=683.8ms  max=683.8ms  p(90)=683.8ms  p(95)=683.8ms
     iterations.....................: 1      1.428942/s

```

Já executando o script com o comando`k6 run --http-debug="full" debbug-request.js` obtemos o seguinte resultado:

```

          /\      |‾‾| /‾‾/   /‾‾/
     /\  /  \     |  |/  /   /  /
    /  \/    \    |     (   /   ‾‾\
   /          \   |  |\  \ |  (‾)  |
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: .\debbug-request.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

INFO[0001] Request:
GET /public/crocodiles HTTP/1.1
Host: test-api.k6.io
User-Agent: k6/0.38.3 (https://k6.io/)
Accept-Encoding: gzip

  group= iter=0 request_id=af32a69d-fb1a-42dc-7434-d9de66c964b3 scenario=default source=http-debug vu=1
INFO[0002] Response:
HTTP/1.1 301 Moved Permanently
Connection: keep-alive
Content-Type: text/html; charset=utf-8
Date: Sat, 25 Feb 2023 15:08:14 GMT
Location: /public/crocodiles/
X-Frame-Options: SAMEORIGIN
Content-Length: 0

  group= iter=0 request_id=af32a69d-fb1a-42dc-7434-d9de66c964b3 scenario=default source=http-debug vu=1
INFO[0003] Request:
GET /public/crocodiles/ HTTP/1.1
Host: test-api.k6.io
User-Agent: k6/0.38.3 (https://k6.io/)
Referer: https://test-api.k6.io/public/crocodiles
Accept-Encoding: gzip

  group= iter=0 request_id=22cbfd7c-4d67-4ca7-5ab2-d12a07dd1ee8 scenario=default source=http-debug vu=1
INFO[0003] Response:
HTTP/1.1 200 OK
Content-Length: 609
Allow: GET, HEAD, OPTIONS
Connection: keep-alive
Content-Type: application/json
Date: Sat, 25 Feb 2023 15:08:14 GMT
Vary: Accept
X-Frame-Options: SAMEORIGIN

[{"id":1,"name":"Bert","sex":"M","date_of_birth":"2010-06-27","age":12},{"id":2,"name":"Ed","sex":"M","date_of_birth":"1995-02-27","age":27},{"id":3,"name":"Lyle the Crocodile","sex":"M","date_of_birth":"1985-03-03","age":37},{"id":4,"name":"Solomon","sex":"M","date_of_birth":"1993-12-25","age":29},{"id":5,"name":"The gharial","sex":"F","date_of_birth":"2004-06-28","age":18},{"id":6,"name":"Sang Buaya","sex":"F","date_of_birth":"2006-01-28","age":17},{"id":7,"name":"Sobek","sex":"F","date_of_birth":"1854-09-02","age":168},{"id":8,"name":"Curious George","sex":"M","date_of_birth":"1981-01-03","age":42}]  group= iter=0 request_id=22cbfd7c-4d67-4ca7-5ab2-d12a07dd1ee8 scenario=default source=http-debug vu=1

running (00m01.9s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✗ [======================================] 1 VUs  00m01.9s/10m0s  1/1 iters, 1 per VU

     data_received..................: 6.5 kB 3.4 kB/s
     data_sent......................: 638 B  330 B/s
     http_req_blocked...............: avg=729ms    min=0s       med=729ms    max=1.45s    p(90)=1.31s    p(95)=1.38s
     http_req_connecting............: avg=567.16ms min=0s       med=567.16ms max=1.13s    p(90)=1.02s    p(95)=1.07s
     http_req_duration..............: avg=206.83ms min=177.96ms med=206.83ms max=235.71ms p(90)=229.94ms p(95)=232.82ms
       { expected_response:true }...: avg=206.83ms min=177.96ms med=206.83ms max=235.71ms p(90)=229.94ms p(95)=232.82ms
     http_req_failed................: 0.00%  ✓ 0       ✗ 2
     http_req_receiving.............: avg=86.7ms   min=43.21ms  med=86.7ms   max=130.2ms  p(90)=121.5ms  p(95)=125.85ms
     http_req_sending...............: avg=0s       min=0s       med=0s       max=0s       p(90)=0s       p(95)=0s
     http_req_tls_handshaking.......: avg=102.33ms min=0s       med=102.33ms max=204.66ms p(90)=184.19ms p(95)=194.42ms
     http_req_waiting...............: avg=120.12ms min=105.51ms med=120.12ms max=134.74ms p(90)=131.82ms p(95)=133.28ms
     http_reqs......................: 2      1.03424/s
     iteration_duration.............: avg=1.9s     min=1.9s     med=1.9s     max=1.9s     p(90)=1.9s     p(95)=1.9s
     iterations.....................: 1      0.51712/s
     vus............................: 1      min=1     max=1
     vus_max........................: 1      min=1     max=1
```

## Conclusão💖

O modo de depuração do K6 nos permite verificar melhor os resultados das requisições e entender o que está acontecendo durante os testes de performance. Dessa forma, conseguimos aprimorar nossos resultados.

Gostou do conteúdo e quer saber mais sobre testes de performance com K6? Então não deixe de conferir meu curso na Udemy: 

- [Teste de performance com K6](https://www.udemy.com/course/teste-de-performance-com-k6/?referralCode=95CCD8BC9F22A2A96BDA)