最近遇到一个新的问题,当使用filebeat加载历史日志文件的时候,大量的数据会被加入到kafka队列,logstash会从队列里面读取大量的event发送到ES端。最开始的表现形式是:
logstash一直不断的往ES发送信息,ES里面的数据也一直在增加,日志的写入量远大于原始的日志量,并且没有停止的迹象。
经查看kafka的consumer checker,发现队列的offset一直没有发生偏移。即kafka一直没有得到logstash的消费确认,认为消息一直没有被消费。我们知道,在整个ELK的流程中,logstash的input从kafka上取数据,经由filter,output插件,发到ES,只有ES返回成功之后,logstash才会更新kakfa的offset,如果ES返回失败,则logstash不会更新kafka的offset,并会尝试重新发送消息,值到成功为止。这个问题在我们这里引起了严重的问题,即kakfka里面的消息一直没有被消费,logstash一直在重试,但实际上数据却已经插入到了ES当中,导致ES的index不停增大,system load evarage一直在增大,响应更慢。
这个问题的发现,需要打开logstash的debug log (在logstash.yml文件里面加入):
log.level: info
这时,在log里面会发现类似的打印:
[ERROR][logstash.outputs.elasticsearch] Retrying individual actions
[INFO ] [logstash.outputs.elasticsearch] retrying failed action with response code: 429 ({"type"=>"**es_rejected_execution_exception**", "reason"=>"rejected execution of org.elasticsearch.transport.TransportService$7@742302a0 on EsThreadPoolExecutor[bulk, queue capacity = 200, org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor@6ae23e0c[Running, pool size = 8, active threads = 8, queued tasks = 206, completed tasks = 5502508]]"})
[ERROR][logstash.outputs.elasticsearch] Attempted to send a bulk request to elasticsearch' but Elasticsearch appears to be unreachable or down! {:error_message=>"Elasticsearch Unreachable: [http://elastic:xxxxxx@10.60.33.105:9200/][Manticore::SocketTimeout] Read timed out", :class=>"LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError", :will_retry_in_seconds=>2}
elasticsearch的REST API若返回状态代码429({“type”=>”es_rejected_execution_exception“, “reason”=>”rejected execution of org.elasticsearch.transport.TransportService),这意味着ES已经没法再处理新进的消息了(ES cluster is not able to keep up with the incoming requests, )
同时,通过x-pack查看ES集群的运行状态:
发现,虽然CPU的使用率只有60%,但系统的load average已经达到10,代表系统已经是在1.2倍负荷的状态下运行。(服务器是8核,2.2G的主频)
(在多处理器系统中,负载均值是基于内核的数量决定的。以 100% 负载计算,1.00 表示单个处理器,而 2.00 则说明有两个双处理器,那么 4.00 就说明主机具有四个处理器)
这个说明什么情况?因为CPU的使用率并不是特别高,但系统的负载却很高,我们猜测系统的主要负载是在io上。再返回来观察logstash的log:
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Retrying individual actions
[2017-07-10T11:17:02,084][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
[2017-07-10T11:17:02,085][ERROR][logstash.outputs.elasticsearch] Action
我们发现,在很多的时间内,反复提示429的错误,代表logstash在不断的,快速的给ES发送bulk reuqest。我们查看logstash的配置发现,默认的配置是:
# How many events to retrieve from inputs before sending to filters+workers#
pipeline.batch.size: 125
## How long to wait before dispatching an undersized batch to filters+workers# Value is in milliseconds.#
pipeline.batch.delay: 5
这里的单位是milliseconds,即每个logstash的instance,每秒会发送200条request到ES集群,这个会导致ES集群的网络io过载
那么,是不是说我们需要把每个batch之间的间隔缩短,把每次batch的size调大?比如batch.size = 1500, batch.delay = 500,已防止出现429的问题?
经过测试,这样是可行的。
但为什么ES的集群会在200 bulk request的情况下会报错?随便一个web server都不会处理不了200条request吧?
查了一下ES的配置文档,发现少配了个数据,具体是vi /etc/security/limits.conf:
ES针对每条request,无论是bulk request还是其他的,都会有一个线程来对request进行处理,对应的,线程会打开一个文件套接字,来生成对应segment file,如果ES可使用的线程数(npro)和文件数(nofile)没有配置,那就有可能出现429的问题
修改ES的配置后,缩小了batch delay, 发现无效,现行的解决方案还是得将batch.delay设值为大于200ms