Já tem um tempo que utilizo a pilha da elastic pra coletar e armazenar logs de aplicações, serviços e dispositivos que preciso monitorar. Sendo o Logstash o responsável em receber, tratar e publicar os logs, garantir que ele tenha um bom desempenho é extremamente importante.
Boa parte dos problemas de desempenho que enfrentei estavam relacionados a erros de configuração, implantação ou uso incorreto de alguns filtros, principalmente o filtro grok
.
Embora o grok
seja extremamente útil, ele é um filtro baseado em expressões regulares e que precisa validar cada expressão configurada, dependendo do número de eventos por segundo essas validações podem acabar gerando uma grande carga na CPU da máquina do Logstash, o que pode impactar em todo o processo de monitoramento.
Grok ou Dissect?
Uma forma simples de otimizar o desempenho de um pipeline é verificar a possibilidade de utilizar outro filtro no lugar do grok
. Um filtro que eu venho utilizando bastante como substituto é o dissect
.
A principal diferença entre o grok
e o dissect
é que o dissect
não utiliza expressões regulares para analisar a mensagem, os campos são definidos a partir de sua posição, tudo que estiver entre um %{
e um }
é considerado um campo e todo o resto é considerado um delimitador, isso torna o dissect
mais rápido que o grok
e também exige menos processamento durante a análise.
Considere o exemplo de mensagem a seguir:
2020-08-20T21:45:50 127.0.0.1 [1] program.Logger INFO - sample message
Podemos extrair dessa mensagem os seguintes campos:
-
timestamp
,ipaddr
,thread
,logger
,loglevel
,msg
Para analisarmos essa mensagem com o grok
e dissect
usamos as seguintes configurações.
grok
grok {
match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} %{IP:ipaddr} \[%{INT:thread}\] %{DATA:logger} %{WORD:loglevel} - %{GREEDYDATA:msg}"}
}
dissect
dissect {
mapping => {
"message" => "%{timestamp} %{ipaddr} [%{thread}] %{logger} %{loglevel} - %{msg}"
}
}
Perceba que a estrutura é bem semelhante, mas no grok
precisamos especificar contra qual expressão regular iremos validar o campo, como por exemplo TIMESTAMP_ISO8601
para o campo timestamp
ou IP
para o campo ipaddr
, algo que não temos no dissect
, já que o filtro irá armazenar como valor do campo o que estiver naquela posição na mensagem e isso acaba sendo um dos fatores que influencia na escolha de um ou outro.
Se as mensagens coletadas em um pipeline possuem sempre a mesma estrutura, ou até mesmo poucas variações, o uso do dissect
no lugar do grok
se faz possível e se mostra vantajoso, já que a análise será mais rápida e precisará de menos processamento.
Mas será que é mesmo mais rápido e usa menos processamento?
Grok vs Dissect
Para comparar o desempenho dos dois filtros utilizei um pipeline simples usando como input
o filtro generator
e como output
o filtro stdout
, e alternei o uso dos filtros grok
e dissect
exemplificados anteriormente.
input {
generator {
lines => ["2020-08-20T21:45:50 127.0.0.1 [1] program.Logger INFO - sample message"]
count => 10000000
}
}
filter {
#
# filtro de grok ou dissect
#
if [sequence] != 0 and [sequence] != 9999999 {
drop { }
}
}
output {
stdout { }
}
Esse pipeline basicamente gera 10 milhões de mensagens, aplica o filtro especificado no momento, grok
ou dissect
, e faz um drop
na mensagem, exceto a primeira e a última, que são exibidas apenas para verificar o início e fim do processamento.
A saída desse pipeline é a seguinte.
{
"host" => "elk",
"ipaddr" => "127.0.0.1",
"message" => "2020-08-20T21:45:50 127.0.0.1 [1] program.Logger INFO - sample message",
"sequence" => 0,
"loglevel" => "INFO",
"logger" => "program.Logger",
"@version" => "1",
"timestamp" => "2020-08-20T21:45:50",
"msg" => "sample message",
"thread" => "1",
"@timestamp" => 2020-08-26T02:00:38.127Z
}
{
"host" => "elk",
"ipaddr" => "127.0.0.1",
"message" => "2020-08-20T21:45:50 127.0.0.1 [1] program.Logger INFO - sample message",
"sequence" => 9999999,
"loglevel" => "INFO",
"logger" => "program.Logger",
"@version" => "1",
"timestamp" => "2020-08-20T21:45:50",
"msg" => "sample message",
"thread" => "1",
"@timestamp" => 2020-08-26T02:02:34.018Z
}
Como estava interessado em comparar o processamento da máquina durante a execução dos filtros, utilizei o nmon
rodando em background e coletando métricas a cada 1 segundo, durante 5 minutos, o que resulta em 300 medidas, uma quantidade mais do que suficiente para esse caso.
Para a execução do pipeline utilizei uma máquina virtual com 4 vCPUs e 4 GB de RAM rodando o CentOS 7.8 e o Logstash na versão 7.9.
Cada medida gerada pelo nmon tem o seguinte formato.
ZZZZ,T0010,00:16:49,21-AUG-2020
CPU001,T0010,50.5,2.0,0.0,46.5,1.0
CPU002,T0010,99.0,0.0,0.0,1.0,0.0
CPU003,T0010,97.0,1.0,0.0,1.0,1.0
CPU004,T0010,96.0,1.0,0.0,3.0,0.0
CPU_ALL,T0010,86.4,0.8,0.0,12.8,0.0,,4
MEM,T0010,3789.0,-0.0,-0.0,1024.0,2903.2,-0.0,-0.0,1024.0,-0.0,281.9,577.3,-1.0,2.0,0.0,181.5
VM,T0010,30,0,0,2384,12760,-1,0,0,0,0,27,0,0,2541,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
PROC,T0010,5,0,2524.7,-1.0,-1.0,-1.0,1.0,-1.0,-1.0,-1.0
NET,T0010,2.6,0.1,2.8,0.1
NETPACKET,T0010,10.9,2.0,12.9,2.0
JFSFILE,T0010,59.0,0.0,0.5,59.0,24.3,4.5,4.5,4.5
DISKBUSY,T0010,0.0,0.0,0.0,0.0
DISKREAD,T0010,0.0,0.0,0.0,0.0
DISKWRITE,T0010,0.0,0.0,0.0,0.0
DISKXFER,T0010,0.0,0.0,0.0,0.0
DISKBSIZE,T0010,0.0,0.0,0.0,0.0
De todas essas linhas, somente a linha CPU_ALL importa, mais especificamente a terceira coluna que corresponde ao percentual de uso médio de todas as CPUs no momento da coleta.
Fazendo uma manipulação dos dados coletados durante a execução do pipeline com o grok
e depois com o dissect
podemos visualizar e comparar o consumo de CPU e o tempo de execução.
O pico inicial de processamento que vemos no gráfico é causado pela inicialização do Logstash, o platô seguinte corresponde ao processamento durante a análise das mensagens.
Analisando o gráfico vemos que o tempo para processar as 10 milhões de mensagens é basicamente o mesmo para os dois filtros testados nesse caso específico, mas temos uma diferença grande no processamento. Uma média de uso de CPU de 40% quando utilizamos o filtro dissect
em comparação com uma média de uso de CPU de mais de 60% quando utilizamos o filtro grok
.
Conclusão e Links
Dependendo do número de pipelines e da quantidade de eventos por segundo de cada um deles, dedicar um tempo para validar a possibilidade de troca do filtro grok
pelo dissect
é algo que pode otimizar bastante o desempenho durante o processo de análise e ingestão de dados, além de poder também refletir em redução de custos quando se tem uma infraestrutura em nuvem já que possibilita tanto o uso de máquinas menores, quanto menos consumo de créditos de cpu em alguns casos.
Nos casos onde os logs coletados seguem sempre a mesma estrutura, como acontece com logs de servidores web, servidores de aplicação, firewalls e roteadores, ou onde se tem controle sobre o formato dos logs gerados, o dissect
é o filtro ideal quando se utiliza o Logstash no processo de coleta e análise de logs.
Links
-
dissect
: documentação oficial -
grok
: documentação oficial
Top comments (0)