Ir para o conteúdo

Pix HTTP performance

Este documento serve para o diagnóstico de problemas de performance utilizando as APIs de comunicação HTTP do módulo Pix do Dinamo.

Info

Este fluxograma é destinado a resolução de problemas de performance. Para direcionamentos arquiteturais, veja o tópico Pix.

O diagnóstico básico inicial pode ser feito utilizando o fluxograma abaixo.

---
title: Fluxo para diagnóstico
---

%%{ init: { 'flowchart': { 'curve': 'basis' } } }%%

flowchart TD
    inicio((Lentidão nas<br>requisições<br>Pix HTTP))

    high_qty_session_?{A<br>quantidade<br>de sessões<br>abertas com o HSM<br>é maior que o<br>esperado ?}
    check_app_is_closing[Verificar se a aplicação<br>está fazendo o fechamento<br>das sessões após o seu<br>uso, inclusive nos casos<br>de erro]
    check_bacen_comm[Verificar se as chamadas<br>ao bacen estão<br>recebendo falhas. Em<br>caso de falha o Bacen<br>pode fazer um delay antes<br>de retornar um erro. Casos<br> de erro comuns: exceder o<br>limite de conexões e fila vazia.]

    qty_session_still_high_?{O número<br>de sessões<br>com o HSM<br>continua<br>alto ?}

    sessions_still_slow_?{A conexão<br>continua<br>lenta ?}

    check_network[Verificar se há<br>lenditão ou<br>instabilidade<br>conhecida na rede]
    network_still_slow_?{A conexão<br>continua<br>lenta ?}

    check_bacen[Verificar se há<br>lentidão com<br>o Bacen. Entrar<br>em contato ou<br>verificar se há<br>comunicados.]
    bacen_still_slow_?{A conexão<br>continua<br>lenta ?}

    check_Logs[Analisar logs do<br>client do HSM em<br>depuração. Ver<br>troubleshoot<br>específico.]
    logs_still_slow_?{A conexão<br>continua<br>lenta ?}

    suporte((Acionar<br>o suporte<br>do HSM))
    resolvido((Resolvido))

    inicio --> high_qty_session_?
    high_qty_session_? -->|Sim| check_app_is_closing
    high_qty_session_? -->|Não| check_bacen_comm

    check_app_is_closing --> qty_session_still_high_?
    qty_session_still_high_? -->|Sim| suporte
    qty_session_still_high_? -->|Não| resolvido

    check_bacen_comm --> sessions_still_slow_?
    sessions_still_slow_? -->|Não| resolvido
    sessions_still_slow_? -->|Sim| check_network

    check_network --> network_still_slow_?
    network_still_slow_? -->|Não| resolvido
    network_still_slow_? -->|Sim| check_bacen

    check_bacen --> bacen_still_slow_?
    bacen_still_slow_? -->|Não| resolvido
    bacen_still_slow_? -->|Sim| check_Logs

    check_Logs --> logs_still_slow_?
    logs_still_slow_? -->|Não| resolvido
    logs_still_slow_? ---->|Sim| suporte

Análise de logs do cliente do HSM

1. Gerar os logs do client do HSM em depuração

Habilitar os logs da biblioteca cliente do HSM em depuração e com flush habilitado.

  1. Definir a seguinte variável de ambiente com a pasta de destino. Lembre-se de definir uma pasta de destino sem o nome do arquivo. Para mais detalhes sobre como habilitar os logs, consulte o tópico Log. 

    HSM_LOG_DIR=/pasta_de_destino/

  2. Reinicie a aplicação e refaça os testes.

  3. Na pasta de destino dos logs, abrir o arquivo de log gerado. Deverá ter o nome tacndlib_xxxx.log, onde xxxx será o PID (Process ID) da aplicação.

2. Identificar as operações problemáticas

  1. Identificar as operações consideradas lentas. É possível ver o tempo total da operação Pix HTTP no item total_time_ms da linha de log LogDebugRequestInfo.

    2021/02/03 19:06:21 144E0000 0000008C 408e0e2f debug LogDebugRequestInfo fpos="m" name_lookup_time_ms=0.000047 connect_time_ms=0.000227 appconnect_time_ms=5.000350 pretransfer_time_ms=5.000403 starttransfer_time_ms=5.000554 total_time_ms=6.000215 redirect_time_ms=0.000000

3. Analisar os dados encontrados

Com os logs das operações problemáticas identificados é possível ver os pontos dentro da operação onde se gastou mais tempo.

Os logs de tempo da operação tem contadores em milissegundos que marcam o tempo entre o início da operação até o tempo do marcador. Por exemplo: connect_time_ms é o tempo do início da operação até o final da conexão com o servidor remoto. appconnect_time_ms é o tempo do início da operação até o final do handshake TLS. Para saber o tempo levado na operação de appconnect_time_ms, basta diminuir o tempo levado em connect_time_ms do tempo de appconnect_time_ms. Assim: tempo do handshake TLS = appconnect_time_ms - connect_time_ms.

Alguns dos pontos mais comuns que devem ser verificados.

  • Tempo alto em appconnect_time_ms
    • Na primeira abertura de sessão é possível que se tenha um tempo maior em appconnect_time_ms. Isto acontece porque neste momento acontece o handshake TLS e o uso da chave no HSM, o que causa um tempo maior. Nas operações seguintes com a mesma sessão esse tempo deve ser baixo, porque que o túnel já está estabelecido e será reutilizado daqui pra frente.
    • Caso este tempo esteja extremamente alto, verificar a qualidade da conexão com o HSM.
    • Este é o único ponto da operação onde há comunicação com o HSM.
    • Caso as operações seguintes continuem com um tempo maior, verifique se os parâmetros de sessão estão habilitado corretamente; para detalhes consulte o tópico Sessões.
    • Caso continue com tempo alto, verificar se a sessão não está sendo reutilizada. O reuso de sessão um fator importante para performance.
  • Tempo alto em starttransfer_time
    • Este contador marca o tempo do início da operação até o recebimento do primeiro byte. Pode indicar uma lentidão entre a comunicação com o servidor remoto.
    • Algumas possíveis causas são lentidão da rede, demora processamento do servidor remoto etc.
    • Em casos de erro o BACEN pode esperar um tempo de delay para enviar a resposta. Geralmente são tempos bem definidos. É possível ver casos de espera de 5 segundos neste ponto.

Outros pontos podem ser verificados para depurar as conexões. A tabela abaixo descreve as outras informações disponíveis nos logs.

Dado Descrição
name_lookup_time_ms Tempo decorrido entre o início da requisição até o final da resolução de nome. Tempo em milissegundos.
connect_time_ms Tempo decorrido entre o início da requisição até o final conexão com o host remoto (ou proxy). Se houver redirecionamento o tempo é adicionado. Tempo em milissegundos.
appconnect_time_ms Tempo decorrido entre o início da requisição até o final do handshake SSL/SSH com o host remoto. Tempo em milissegundos.
pretransfer_time_ms Tempo decorrido entre o início da requisição até o momento imediatamente antes do envio dos dados. Se houver redirecionamento o tempo é adicionado. Tempo em milissegundos.
starttransfer_time_ms Tempo decorrido entre o início da requisição até o momento do recebimento do primeiro byte. Se houver redirecionamento o tempo é adicionado. Tempo em milissegundos.
total_time_ms Tempo total da requisição. Se houver redirecionamento o tempo é adicionado. Tempo em milissegundos.
redirect_time_ms Tempo total levado nos redirecionamentos. Tempo em milissegundos.
content_length_upload Tamanho do content-length no upload dos dados. Recuperado do campo Content-Length. Recebe -1 caso o tamanho não seja conhecido. Tamanho em bytes.
content_length_download Tamanho do content-length no download dos dados. Recuperado do campo Content-Length. Recebe -1 caso o tamanho não seja conhecido. Tamanho em bytes.
upload_speed Velocidade média do upload completo. Velocidade em bytes/segundo.
download_speed Velocidade média do download completo. Velocidade em bytes/segundo.
download_size Tamanho total do payload (body) do download. Os metadados e headers não entram nesta contagem. Tamanho em bytes.
upload_size Tamanho total do payload (body) upload. Tamanho em bytes.
redirect_count Contagem de redirecionamentos feitos.
num_connects Contagem de conexões criadas para concluir a transferência anterior.
request_size Tamanho total da requisição enviada. Tamanho em bytes.
received_header_size Tamanho total de todos os headers recebidos. Tamanho em bytes.
http_response_code Código de resposta HTTP da requisição. Será zero se nenhum código de resposta for recebido.