前言
此前对于ELK问题接触较少,所以在问题排查阶段的动作相对较慢。所以希望记录此日志给以后遇到同类型问题时,提供一定的参考作用。帮助自己以后快速定位问题打下基础。
也希望给大家遇到自己不一样的问题时,提供一定的排查思路。
问题描述:
背景:
生产环境部署了ELK。kibana开放给开发人员,方便排查生产问题,查看服务日志。但是最近开发人员总是反馈日志“延迟”时间过长。经常好几个小时都无法查看到日志。
根据开发人员反馈的“延迟”现象,进行问题复现时的排查。
确定排查问题:
“日志收集延迟”
问题排查&分析:
Q1:开发反馈的“延迟”现象,是否确实属于日志收集延迟?
观察现象:由于是微服务,所以kibana收集了很多服务的。在问题复现时,通过观察其他服务的日志,没有发现日志有延迟的现象。
得出小结论1:开发反馈的日志“延迟”现象,只是出现在一个微服务上。其他服务并没有出现一样的问题。所以不一定是ELK组件出现性能问题导致延迟。ELK组件性能是否存在问题需要进一步验证。
Q2:验证ELK组件是否有性能问题?
1.同一时刻其他微服务没有日志延迟现象。所以ELK组件性能问题怀疑的可能性不高。
2.问题复现时。通过观察和业务反馈。日志有长达4小时的内容没有在kibana展示。如果只是的性能问题,日志消费延迟4小时时间太久,不太可能有这么严重的性能问题。
3.kibana监控限制elasticsearch、logstash、kibana的性能没有明显问题。
得出小结论2: ELK没有明显的性能瓶颈的现象,导致可能会出现的4小时日志延迟现象。所以有没有可能ELK组件中的elasticsearch和logstash在问题发生时出现不可写入的现象,kibana在问题发生时是否有不可展示日志现象。
Q3:ELK组件在问题发生时是否有不可写入或不可展示问题?
1.验证是否是ES有数据但是kibana为展示?
可通过es插件或者kibana的dev tools进行es的查询
示例
GET deployment_2021.07.19/_search
{
"query": {
"bool": {
"must": [
{"match" : {"applicationName" : "csc-oim-service-imgovs"}},
{"match" : {"@timestamp" : "2021-07-19T09:00:00.000Z"}}
]
}
}
}
经排查,出现问题的时间段(kibana未有日志展示的时间段),elasticsearch也未插叙到有日志数据。所以不是es有数据,但kibana为展示的情况。
2.是否是elasticsearch不可写入数据?
POST请求格式: index_name/type
POST deployment_2021.07.25/tcp
{
"applicationName": "apptest",
"message": "20210725test",
"@timestamp": "2021-07-25T11:50:00.000Z"
}
通过kibana查询新插入的数据
关于时间戳的小提示:
1.时间戳结尾的Z是标识时区zero时区(UTC偏移0)
2.kibana的容器时区为东八区,所以展示的时候会自动+8
3.时间戳的T不代表什么。就只是一个默认的分隔符
ps:在问题复现时,通过POST给对应的微服务手动写入过日志信息。elasticsearch可以正常查询到文档。Kibana也能正常展示信息。
目前为止,排除了elasticsearch和kibana的问题
Q4:是否是logstash无法写入数据?
我们的logstash用法不是常规的去读取日志文件然后写入elasticsearch。而实通过input tcp组件,通过服务主动向logstash 9250端口推送日志,然后logstash 通过output elasticsearch写到es。
虽然所有服务都是发送到同一个logstash,且其他服务在问题复现时可以正常推送日志,基本可以排除logstash出现问题。但是为追求严谨,还是验证一下logstash的写入是否正常。
通过nc命令向logstash tcp端口写入数据。(由于是tcp端口,nc命令成功后不会断开,需要手动断开)
echo "{\"applicationName\": \"csc-oim-service-imgovs\",\"@timestamp\": \"2021-07-26T08:33:00.001Z\",\"message\": \"xxxxx for logstash\"}" | nc 172.24.27.205 32529
ps:32529端口映射了logstash的9250端口。
通过logstash写入多条数据。但是从es中查询却查询不到数据 。
示例:es中查询此前用nc命令插入的其中一条数据
ps:无意间将kibana自动刷新日志打开,5s刷新一次。断层的日志随着时间的推移又出来了。也从侧面反映了服务应该把日志给到logstash了,但是logstash消费似乎除了点状况,日志给到es给的太慢。
验证这一想法:
我在下午16:57分搜索13点27分22秒的日志。es显示无数据。此时最新的日志,只有13点27分21秒的。
可能有两种情况:1.服务没有把日志给logstash;2.logstash消费太慢,13点27分22秒的日志还没有消费到。
经过漫长的等待,在下午17:19分,又有了更新的日志。可以看到是下午13点28分16秒的日志
从以上观察不难看出。业务日志相隔一分钟,我却等待了近20分钟。
为了避免:“es中有数据,只是kibana展示时没展示出来”这一干扰项。我又继续查询了es中该业务13点30分-59分的日志,确保在kibana展示最新日志为29分时,es中确实没有更加新的日志了。
经过极其漫长的等待北京时间18点,下午13点30的日志终于出来了。
得出小结论3:有可能是logstash的性能问题,如消费太慢。导致日志迟迟不能写入elasticsearch。
Q5:logstash性能问题排查
排查过程中,又过了一遍logstash性能问题。虽然logstash收到和发出的events数目完全一致,表面看上去是logstash只要收到了消息都推给es了。但是看了一下节点性能情况,发现cpu的负载非常高。这可能成为突破口。
解决办法:扩容机器,增加CPU和内存。然后继续观察情况。
解决方案:
本人真实环境是基于kops的k8s集群。
所以使用kops命令对此节点进行了扩容。CPU和内存都进行了升配。
具体操作步骤略。