DEV Community

Marlo Henrique
Marlo Henrique

Posted on • Edited on

Debug de requisição http com K6📑

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

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");
}
Enter fullscreen mode Exit fullscreen mode

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
Enter fullscreen mode Exit fullscreen mode

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

Enter fullscreen mode Exit fullscreen mode

Já executando o script com o comandok6 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
Enter fullscreen mode Exit fullscreen mode

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:

Top comments (0)

Sentry image

See why 4M developers consider Sentry, “not bad.”

Fixing code doesn’t have to be the worst part of your day. Learn how Sentry can help.

Learn more