Log dos tempos de resposta

Disponível a partir da versão 17.3.0.17.

Para facilitar a análise da performance de execução dos web services, e auxiliar na resolução de eventuais problemas, é possível configurar o broker de web services para gravar no log o trace das mensagens trocadas entre os clients e os servers, incluindo o tempo de execução de cada request. O cálculo do tempo de execução leva em consideração que cada pedido de web service é executado em uma conexão exclusiva (modelo HTTP/1.0).

São utilizadas duas chaves no arquivo de configuração do broker de web services: LOG_MSG e LOG_MSG_SIZE.

A chave LOG_MSG configura o broker para gravar no log as informações sobre cada mensagem recebida de um client ou um server. Estas informações consistem de: status da operação (0, ou código de erro), tamanho da mensagem (ou 0 quando for fechamento da conexão), ip e porta da origem (um server ou um client, e ip e porta do destino (um server ou um client). Além disso, no fechamento da conexão pelo server também é gravado o tempo de execução do web service, considerando o tempo de recepção da primeira mensagem vinda do client.

A chave LOG_MSG_SIZE configura o tamanho da parte do conteúdo da mensagem a ser gravado no log. Isto é feito para evitar sobrecarregar o log. Por exemplo, se LOG_MSG_SIZE=64, então apenas os primeiros 64 caracteres de cada mensagem será gravado no log. Se esta chave não for utilizada então o conteúdo das mensagens não será gravado no log. (O broker sempre tenta ler 1024 bytes de cada vez, então mensagens grandes virão em pedaços de 1024 bytes. De cada pedaço de 1024 bytes, a parte inicial será gravada no log, considerando o valor configurado em LOG_MSG_SIZE).

Exemplo

Broker aceitando conexões na porta 13340, vai gravar informações sobre as conexões e os primeiros 64 bytes de cada mensagem recebida.

LOCAL_SERVER_PORT = 13340
REMOTE_SERVER_01 = 10.172.36.130 49181
REMOTE_SERVER_02 = 10.172.36.130 49182
REMOTE_SERVER_03 = 10.172.36.130 49183
REMOTE_SERVER_04 = 10.172.36.130 49184
SORT_METHOD = ROUND_ROBIN
LOG_MSG = 1
LOG_MSG_SIZE = 64

Comando wget com request para o server, através do broker.
Utilitário de linha comando, fazendo um GET / HTTP/1.1 no ip e porta 10.172.36.130:13340
São mostrados os headers do request e do response (200 OK).
O tamando do body da resposta é de 37 bytes, e é gravado no arquivo index.html.

$ wget -t1 -d http://10.172.36.130:13340

---request begin---
GET / HTTP/1.1
User-Agent: Wget/1.16.3 (mingw32)
Accept: */*
Accept-Encoding: identity
Host: 10.172.36.130:13340
Connection: Keep-Alive

---response begin---
HTTP/1.1 200 OK
Date: Wed, 27 Nov 2019 16:57:38 GMT
Server: Application Web Server
MIME-version: 1.0
Content-type: text/html
Last-modified: Thu, 17 Oct 2019 12:48:36 GMT
Content-length: 37
X-Frame-Options: SAMEORIGIN

index.html 100%[===================================================>] 37 --.-KB/s in 0s

2019-11-27 13:57:38 (568 KB/s) - 'index.html' saved [37/37]

Log do broker.
Mensagens recebidas do client aparecem com "C→S Message".
Mensagens recebidas do server aparecem com "S→C Message".
Informações sobre a mensagem aparecem como "(ret=...  size=...   from=...   to=...)".
Conteúdo da mensagem aparece como "(part=... ): [.....]", incluindo quebras de linha.
Tempo de execução do request aparece como "[serverReplyTime=...]".
Na operação normal do broker vai haver muitas conexões em paralelo, portanto as linhas referentes às conexões vão estar misturadas.
Para selecionar as linhas referentes a uma conexão específica utiliza-se o campo "ctx:...". Neste exemplo, as linhas da conexão criada pelo programa wget acima estão identificadas pelo campo "ctx:008".
Como a formatação é bem definida, é possível criar estatísticas dos tempos utilizando-se de alguma linguagem de script para selecionar os campos de interesse, especialmente o campo serverReplyTime.
Para uso eventual, usando-se um editor de texto como o notepad++ é possível selecionar todos os campos serverReplyTime, ou todas mensagens da conexão "ctx:nnn", etc.

191127_135738 3188 BPC0210 M x 04 ctx:008 o1r0R1s0S0 M C->S Message: (ret=0 size=144 from=10.172.36.130:56632 to=10.172.36.130:49181)
191127_135738 3188 BPC0220 M x 04 ctx:008 o1r0R1s0S0 M C->S Message(part=64): [
GET / HTTP/1.1
User-Agent: Wget/1.16.3 (mingw32)
Accept: */*
]
191127_135738 3A6C BPC0210 M x 04 ctx:008 o1r1R0s0S0 M S->C Message: (ret=0 size=227 from=10.172.36.130:49181 to=10.172.36.130:56632)
191127_135738 3A6C BPC0220 M x 04 ctx:008 o1r1R0s0S0 M S->C Message(part=64): [
HTTP/1.1 200 OK
Date: Wed, 27 Nov 2019 16:57:38 GMT
Server: Ap
]
191127_135738 3A6C BPC0210 M x 04 ctx:008 o1r1R0s0S0 M S->C Message: (ret=0 size=37 from=10.172.36.130:49181 to=10.172.36.130:56632)
191127_135738 3A6C BPC0220 M x 04 ctx:008 o1r1R0s0S0 M S->C Message: [
<html>hello from appserver-1</html>
]
191127_135738 3A6C BPC0210 M x 04 ctx:008 o1r1R0s0S0 M S->C Message: (ret=0 size=0 from=10.172.36.130:49181 to=10.172.36.130:56632 [serverReplyTime=0])
191127_135738 3A6C BPC0210 M x 05 ctx:008 o0r0R0s0S0 M C->S Message: (ret=64 size=0 from=10.172.36.130:56632 to=10.172.36.130:49181)