Monitoramento do tempo de resposta da solicitação HTTP

Olá, Desenvolvedores!

Hoje quero falar sobre um assunto que já me deu trabalho. Tenho certeza de que isso deve ter acontecido com muitos de vocês (o chamado "gargalo"). Como esse é um tema amplo, este artigo focará apenas em identificar solicitações HTTP recebidas que podem estar causando problemas de lentidão. Também disponibilizarei uma pequena ferramenta que desenvolvi para ajudar a identificá-las.

Nosso software está cada vez mais complexo, processando um grande número de solicitações de diferentes origens, seja aplicativos de front-end ou back-end de terceiros. Para garantir um desempenho ideal, é fundamental ter um sistema de registro capaz de obter algumas medições importantes, como tempo de resposta, número de referências globais e número de linhas de código executadas para cada resposta HTTP. Como parte do meu trabalho, participo do desenvolvimento de software EMR e da análise de incidentes.  Como a carga do usuário vem principalmente de solicitações HTTP (API REST ou aplicativo CSP), a necessidade desse tipo de medição quando ocorrem problemas generalizados de lentidão se tornou óbvia.

Medição de tempo de resposta

Um dos elementos mais relevantes para avaliar o desempenho de um aplicativo é o tempo de resposta. Cada solicitação precisa ser respondida dentro de um prazo razoável para fornecer uma experiência satisfatória ao usuário. Por isso que, ao registrar o tempo de resposta de cada solicitação, um sistema de registro ajuda a identificar o desempenho ruim. Também podemos usar essas informações para identificar quais APIs ou CSPs são mais lentos a fim de otimizá-los e aumentar a execução geral do aplicativo​.

Número de referências globais

Embora o tempo de resposta seja uma característica essencial, também não devemos negligenciar o número de referências globais. Devemos lembrar que o acesso ao disco também costuma ser uma operação cara em termos de tempo de execução. No entanto, a eficiência do cache IRIS pode mascarar esse problema. Quero dizer com isso que, se muitas referências globais em cache forem acessadas simultaneamente, o tempo de resposta será excelente. Ainda assim, o desempenho cai consideravelmente assim que os dados acessados vêm de fora do cache. Em outras palavras, em um sistema onde são feitas várias solicitações ao mesmo tempo, o uso excessivo do acesso ao disco pode causar uma lentidão considerável. Um sistema de registro que mede referências de acesso global para cada solicitação também nos permite detectar solicitações HTTP que solicitam recursos em excesso. Ao identificar problemas desse tipo, os desenvolvedores podem fazer alterações para minimizar esse acesso (adicionando índices, otimizando consultas SQL, mudando a lógica etc.)

Número de linhas de código executadas

Contar o número de linhas de código executadas para cada solicitação nos oferece uma medida da complexidade e magnitude das operações realizadas. Essa medição nos ajuda a identificar consultas que executam muitas linhas de código, o que pode indicar partes do código que precisam de otimização. Na maioria dos casos, o problema está no número de referências globais. Porém, caso uma parte complexa do código seja apenas a manipulação de dados de memória com pouco acesso ao banco de dados, essa medição permitirá destacá-la (por exemplo, se houver um problema com loops).

Detecção de anomalias

Um registro do sistema também pode ser usado para detectar anomalias no desempenho da consulta de resposta. Ao registrar essas medições, é possível identificar solicitações fora do comum. Por exemplo, se uma consulta que costuma ser executada rapidamente de repente começa a demorar mais ou a acessar o disco em excesso, pode haver um problema que exige atenção imediata (como um maior tempo de resposta após a atualização de um aplicativo). Lembre-se de que a detecção precoce de anomalias nos ajuda a resolver problemas de desempenho rapidamente e garante uma boa experiência do usuário.

Pacote web-timing-logger

Recentemente, desenvolvi uma pequena ferramenta para a comunidade que nos permite registrar todas as solicitações HTTP recebidas. Se você tiver interesse, ela está disponível no Open Exchange. Essa ferramenta registra especialmente as principais métricas discutidas neste artigo: número de linhas de código executadas, número de referências globais e tempo de resposta. Ela também registra algumas informações sobre o autor da chamada que podem ser úteis para depuração:

• Data e hora.
• O usuário conectado.
• Endereço IP do autor da chamada.
• URL.
• Namespace de execução.
• Web app.
• Nome da página (se aplicável).
• URL sem parâmetros.

 

Além disso, também oferece a capacidade de integrar métricas personalizadas com SAM ("/api/monitor"), que permite incorporá-las no Prometheus e criar um painel de controle com o Grafana.

Há uma série de dados por web app, página ou rota (se for um aplicativo REST) ​​agregado por dia e quarto de hora:

• Total de acessos: número de solicitações recebidas.
• Tempo total: tempo de resposta cumulativa para todas as solicitações.
• Tempo máximo: tempo de resposta mais lento.
• Tempo média: tempo médio de resposta.

As mesmas métricas também estão disponíveis para referências globais e linhas de código executadas.

                                                                                                    

Abaixo você pode ver um exemplo com as métricas ativadas nos web apps "/api/monitor/" e "/csp/sys/exp/":

webmeasure_average_gloref{id="/api/monitor/"} 903.5227272727272727
webmeasure_average_gloref{id="/api/monitor/metrics"} 903.5227272727272727
webmeasure_average_gloref{id="/csp/sys/exp/"} 1853.6875
webmeasure_average_gloref{id="/csp/sys/exp/%CSP.Broker.cls"} 1242.933333333333333
webmeasure_average_gloref{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 11015
webmeasure_average_gloref_current_quarter{id="/api/monitor/"} 903.5227272727272727
webmeasure_average_gloref_current_quarter{id="/api/monitor/metrics"} 903.5227272727272727
webmeasure_average_gloref_current_quarter{id="/csp/sys/exp/"} 1853.6875
webmeasure_average_gloref_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 1242.933333333333333
webmeasure_average_gloref_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 11015
webmeasure_average_lines{id="/api/monitor/"} 29365.5
webmeasure_average_lines{id="/api/monitor/metrics"} 29365.5
webmeasure_average_lines{id="/csp/sys/exp/"} 19415.5
webmeasure_average_lines{id="/csp/sys/exp/%CSP.Broker.cls"} 11570.73333333333333
webmeasure_average_lines{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_average_lines_current_quarter{id="/api/monitor/"} 29365.5
webmeasure_average_lines_current_quarter{id="/api/monitor/metrics"} 29365.5
webmeasure_average_lines_current_quarter{id="/csp/sys/exp/"} 19415.5
webmeasure_average_lines_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 11570.73333333333333
webmeasure_average_lines_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_average_timing_in_ms{id="/api/monitor/"} 27.27256818181818182
webmeasure_average_timing_in_ms{id="/api/monitor/metrics"} 27.27256818181818182
webmeasure_average_timing_in_ms{id="/csp/sys/exp/"} 16.6
webmeasure_average_timing_in_ms{id="/csp/sys/exp/%CSP.Broker.cls"} 9.94633333333333333
webmeasure_average_timing_in_ms{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_average_timing_in_ms_current_quarter{id="/api/monitor/"} 27.27256818181818182
webmeasure_average_timing_in_ms_current_quarter{id="/api/monitor/metrics"} 27.27256818181818182
webmeasure_average_timing_in_ms_current_quarter{id="/csp/sys/exp/"} 16.6
webmeasure_average_timing_in_ms_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 9.94633333333333333
webmeasure_average_timing_in_ms_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_max_lines{id="/api/monitor/"} 29498
webmeasure_max_lines{id="/api/monitor/metrics"} 29498
webmeasure_max_lines{id="/csp/sys/exp/"} 137087
webmeasure_max_lines{id="/csp/sys/exp/%CSP.Broker.cls"} 45208
webmeasure_max_lines{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_max_lines_current_quarter{id="/api/monitor/"} 29498
webmeasure_max_lines_current_quarter{id="/api/monitor/metrics"} 29498
webmeasure_max_lines_current_quarter{id="/csp/sys/exp/"} 137087
webmeasure_max_lines_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 45208
webmeasure_max_lines_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_max_timing{id="/api/monitor/"} 40.783
webmeasure_max_timing{id="/api/monitor/metrics"} 40.783
webmeasure_max_timing{id="/csp/sys/exp/"} 116.405
webmeasure_max_timing{id="/csp/sys/exp/%CSP.Broker.cls"} 66.458
webmeasure_max_timing{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_max_timing_current_quarter{id="/api/monitor/"} 40.783
webmeasure_max_timing_current_quarter{id="/api/monitor/metrics"} 40.783
webmeasure_max_timing_current_quarter{id="/csp/sys/exp/"} 116.405
webmeasure_max_timing_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 66.458
webmeasure_max_timing_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_total_gloref{id="/api/monitor/"} 39755
webmeasure_total_gloref{id="/api/monitor/metrics"} 39755
webmeasure_total_gloref{id="/csp/sys/exp/"} 29659
webmeasure_total_gloref{id="/csp/sys/exp/%CSP.Broker.cls"} 18644
webmeasure_total_gloref{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 11015
webmeasure_total_gloref_current_quarter{id="/api/monitor/"} 39755
webmeasure_total_gloref_current_quarter{id="/api/monitor/metrics"} 39755
webmeasure_total_gloref_current_quarter{id="/csp/sys/exp/"} 29659
webmeasure_total_gloref_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 18644
webmeasure_total_gloref_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 11015
webmeasure_total_hit{id="/api/monitor/"} 44
webmeasure_total_hit{id="/api/monitor/metrics"} 44
webmeasure_total_hit{id="/csp/sys/exp/"} 16
webmeasure_total_hit{id="/csp/sys/exp/%CSP.Broker.cls"} 15
webmeasure_total_hit{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 1
webmeasure_total_hit_current_quarter{id="/api/monitor/"} 44
webmeasure_total_hit_current_quarter{id="/api/monitor/metrics"} 44
webmeasure_total_hit_current_quarter{id="/csp/sys/exp/"} 16
webmeasure_total_hit_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 15
webmeasure_total_hit_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 1
webmeasure_total_lines{id="/api/monitor/"} 1292082
webmeasure_total_lines{id="/api/monitor/metrics"} 1292082
webmeasure_total_lines{id="/csp/sys/exp/"} 310648
webmeasure_total_lines{id="/csp/sys/exp/%CSP.Broker.cls"} 173561
webmeasure_total_lines{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_total_lines_current_quarter{id="/api/monitor/"} 1292082
webmeasure_total_lines_current_quarter{id="/api/monitor/metrics"} 1292082
webmeasure_total_lines_current_quarter{id="/csp/sys/exp/"} 310648
webmeasure_total_lines_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 173561
webmeasure_total_lines_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_total_timing_in_ms{id="/api/monitor/"} 1199.993
webmeasure_total_timing_in_ms{id="/api/monitor/metrics"} 1199.993
webmeasure_total_timing_in_ms{id="/csp/sys/exp/"} 265.6
webmeasure_total_timing_in_ms{id="/csp/sys/exp/%CSP.Broker.cls"} 149.195
webmeasure_total_timing_in_ms{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_total_timing_in_ms_current_quarter{id="/api/monitor/"} 1199.993
webmeasure_total_timing_in_ms_current_quarter{id="/api/monitor/metrics"} 1199.993
webmeasure_total_timing_in_ms_current_quarter{id="/csp/sys/exp/"} 265.6
webmeasure_total_timing_in_ms_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 149.195
webmeasure_total_timing_in_ms_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405

Você deve ter notado que as métricas ilustradas acima são muito genéricas. Recomendo fortemente que você amplie e personalize suas métricas. É necessário para o monitoramento adequado dos aplicativos

 

Instalação usando ZPM

Se você deseja fazer uma instalação de teste e é usuário do Docker, recomendo que você revise esta seção para obter algumas informações práticas antes de passar para a próxima. O script de criação do contêiner configura o ambiente automaticamente.

A instalação é feita com o ZPM. Basta acessar o terminal IRIS e executar o seguinte:

zpm "install web-timing-logger”

Após a instalação, você precisa inicializar as configurações, então execute:

Do ##class(dc.webtiming.Config).Initialize()

Por padrão, o log e as métricas de solicitações HTTP não estão ativos. Para ativá-los, siga as seguintes etapas:

Do ##class(dc.webtiming.Config).SetLogEnabled(1)

Do ##class(dc.webtiming.Config).SetMetricsEnabled(1)

Para SAM ("/api/monitor") expor métricas personalizadas, além de adicionar uma função ao web app /API/monitor, você deve registrar uma classe em SYS.Monitor.SAM.Config. Então, execute o seguinte comando:

Do ##class(dc.webtiming.Config).ConfigureAPIMonitor()

Se você quiser usar esse utilitário em diversos web apps que são executados em diferentes namespaces, é fundamental mapear o pacote "dc.webtiming" e os globais "dc.webtiming*" em “%ALL”.  Para evitar fazer isso manualmente, use o método especificado abaixo:

Do ##class(dc.webtiming.Config).AddToPercentAllNS()

Todas as ações mencionadas acima podem ser executadas em uma única linha com o próximo comando:

Do ##class(dc.webtiming.Config).DefaultSetup()

Instalação usando Docker

O início com o Docker é clássico. Clone o repositório e inicie o contêiner:

git clone https://github.com/lscalese/iris-web-timing-logger.git
docker-compose up -d

Ativação em um web app

Agora que configuramos o sistema, ainda há um detalhe importante a ser configurado para que você possa registrar as medições. Para entender o que é preciso fazer, você deve saber como funciona o sistema.  Para acionar a medição e o registro, o web-timing-logger usa os eventos "OnStartRequest" e "OnEndRequest". Esses eventos são implementados na classe "dc.webtiming.CSPSessionEvents", que é uma subclasse de "%CSP.SessionEvents". Em seguida, cada web app precisa ser configurado com a classe de evento "dc.webtiming.CSPSessionEvents".

 

Se o seu web app já estiver usando outra classe de evento, não se preocupe! Basta adicionar as seguintes chamadas a essa classe:

No método OnStartRequest: 

Do ##class(dc.webtiming.Events).OnStart()

e no método OnEndRequest:

Do ##class(dc.webtiming.Events).OnEnd()

Isso adicionará a funcionalidade de medição e gravação às suas classes de evento existentes.

Faça essa configuração para todos os web apps que você deseja medir.

Se você tiver um sistema vazio e só quiser fazer alguns testes, use a configuração no web app /API/monitor. Como o acesso às métricas é estabelecido por uma chamada HTTP, elas também podem ser medidas para gerar logs.  Então, basta abrir seu navegador e acessar a página http://localhost:49165/api/monitor/metrics várias vezes (adapte com o número da sua porta). Você perceberá que as métricas "webmeasure" são alimentadas, e a tabela "dc_webtiming_log.Request" é preenchida com dados de solicitações HTTP:

SELECT *
FROM dc_webtiming_log.Request

Mesmo que Web-timing-logger facilite a identificação de pontos de entrada problemáticos em web apps, ele não oferece informações precisas sobre partes específicas do código que estão causando problemas.   Depois de identificar o ponto de entrada, você poderá usar outras ferramentas, como OEX ZProfile, desenvolvida por Dmitry Maslennikov. Ela pode realizar uma análise aprofundada do código que está sendo executado. Confira um artigo dedicado aqui.

Isso é tudo por hoje. É claro que poderíamos abordar outras coisas sobre o "web-timing-logger", como limpeza de logs, exemplo do painel de controle do Grafana ou até mesmo algumas consultas SQL interessantes. Espero que você tenha gostado do artigo e ele tenha dado ideias para o monitoramento dos seus aplicativos. Posso escrever uma continuação se você tiver interesse.

Até logo!