线上风暴：事故排查与应对实战（一）

浮雷
911 阅读11分钟

前言

线上系统的稳定性和可靠性是一个至关重要的问题。我们应该如何快速识别、排查并解决问题，以保障系统的稳定运行和用户体验？在本系列文章中——“线上风暴：事故排查与应对实战”，我将分享一系列case来探讨线上事故的排查过程。

在这个系列中，每一个case都是我在日常工作中碰到的真实事故，希望与大家一起探讨如何利用日志、监控和其他诊断工具有效定位问题，以及在问题解决后如何总结经验、优化系统，以防止类似问题的再次发生。

一、现象

  • 1、在ES服务的日志中看到有大量的OutOfMemoryError。
{"@timestamp":"2023-03-31T12:26:14.541Z", "log.level": "WARN", "message":"An exception 'java.lang.OutOfMemoryError: unable to create native thread: possibly out of memory or process/resource limits reached' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch[knn-elasticsearch-1][transport_worker][T#8]","log.logger":"io.netty.channel.AbstractChannelHandlerContext","elasticsearch.cluster.uuid":"JaFfYr0ORf-QvZ4iFeYXIw","elasticsearch.node.id":"UrRU47zUSA67b2QwMIM6Ng","elasticsearch.node.name":"knn-elasticsearch-1","elasticsearch.cluster.name":"knn-elasticsearch","error.type":"java.lang.OutOfMemoryError","error.message":"unable to create native thread: possibly out of memory or process/resource limits reached","error.stack_trace":"java.lang.OutOfMemoryError: unable to create native thread: possibly out of memory or process/resource limits reached\n\tat java.base/java.lang.Thread.start0(Native Method)\n\tat java.base/java.lang.Thread.start(Thread.java:802)
  • 2、在kibana中es的集群健康状态为红色（也就是主分片未能成功分配） 1dad8f7e967a7d0ce4168cdadf265c01.png
  • 3、segment可以看到明显上升，接近11100个segment。
  • 4、部分查询可以正常执行，但是时间较平时长很多（30秒以上）。

二、初步猜想

  • 1、JVM参数设置不合理，最大堆、最小堆、堆外内存设置得较少（ES使用netty进行网络通信，Netty使用直接内存进行缓冲），或者因为内存泄漏原因导致ES节点崩溃。
  • 2、因上线新的查询逻辑（数据量超过4亿，并且查询中包含prefix、wildcard查询），并且QA进行长时间压测（2个小时），可能是因为查询压力 + 写入压力，导致es崩溃。
  • 3、因宿主机负载较高，ES在申请内存时失败导致大量OutOfMemoryError，并且最终被宿主机kill掉。

三、排查过程

1、ES JVM分析

1.1 线上ES JVM参数

[-Xshare:auto, -Des.networkaddress.cache.ttl=60, -Des.networkaddress.cache.negative.ttl=10, -Djava.security.manager=allow, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -XX:-OmitStackTraceInFastThrow, -XX:+ShowCodeDetailsInExceptionMessages, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dio.netty.allocator.numDirectArenas=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Dlog4j2.formatMsgNoLookups=true, -Djava.locale.providers=SPI,COMPAT, --add-opens=java.base/java.io=ALL-UNNAMED, -XX:+UseG1GC, -Djava.io.tmpdir=/tmp/elasticsearch-11838727956479555030, -XX:+HeapDumpOnOutOfMemoryError, -XX:+ExitOnOutOfMemoryError, -XX:HeapDumpPath=data, -XX:ErrorFile=logs/hs_err_pid%p.log, -Xlog:gc*,gc+age=trace,safepoint:file=logs/gc.log:utctime,pid,tags:filecount=32,filesize=64m, -Des.cgroups.hierarchy.override=/, -Xms16384m, -Xmx16384m, -XX:MaxDirectMemorySize=8589934592, -XX:InitiatingHeapOccupancyPercent=30, -XX:G1ReservePercent=25, -Des.path.home=/usr/share/elasticsearch, -Des.path.conf=/usr/share/elasticsearch/config, -Des.distribution.flavor=default, -Des.distribution.type=docker, -Des.bundled_jdk=true]", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.node.Node","elasticsearch.node.name":"knn-elasticsearch-1","elasticsearch.cluster.name":"knn-elasticsearch"}

上边比较核心的几个参数：-Xss1m、-XX:+UseG1GC、-Xms16384m（16gb）、-Xmx16384m（16gb）、-XX:MaxDirectMemorySize=8589934592（8gb）、G1ReservePercent=25，整体来看-Xms、-Xmx、-Xss设置是合理的，只有-XX:MaxDirectMemorySize、G1ReservePercent设置的值稍微大一些，但是仅凭这些参数还看不出来问题。

1.2 线上ES JVM日志分析

对线上崩溃节点的jvm日志进行分析（17:30 ~ 20:00），可以得到下边的分析结果：

之前猜测堆内存吃满导致分配失败，目前从日志中看起来并不是这样，堆的最大使用量在这个时间段也不到12GB，并且垃圾回收仍然是有效的（每次回收都能收回掉3GB ~ 3.5GB左右空间），并且在日志中没有出现直接内存分配失败的日志，初步排除因JVM参数设置不合理的原因。

2、压测导致集群崩溃

经QA反馈，15点左右开始压测，单线程的依次查询看时延（一种类型检索一个线程查询5分钟），没有并发，持续到17点左右。下边先来看看崩溃节点在这段时间的负载情况：

从上边的图中可以看出，从3点到5点这个过程中，无论是JVM的堆、I/O、CPU使用率、以及系统负载均没有明显的剧烈变化。这一点在JVM G1垃圾收集器的日志中也能体现出现：

崩溃节点elasticsearch-1节点的的监控截图如下：

上边的图是elasticsearch-1节点中下午5点~8点的状态信息，从上边的图中我们可以看到：

  • 1、elasticsearch-1节点大概在31号下午6.45分崩溃。
  • 2、在崩溃前系统负载有一个明显的上升（5 -> 20），以及I/O读写也存在一定程度上的上升（400 -> 900）

2.2 现象解释

排查到这一步时，我们已经可以解释前边我们观察到的几个现象：

  • 1、在kibana中es的集群健康状态为红色：因为elasticsearch-1节点在6.45分左右崩溃，所以当某个索引主分片落在该节点的索引时，由于ES的分片调度策略（不能将一个索引的所有分片全部调度到一个节点中）， 相当于产生了数据丢失，所以此时集群的状态为红色，即此时集群“不可用”。
  • 2、部分查询可以正常执行，但是时间较平时长很多： 当ES集群处于红色状态，部分查询（主分片落在elasticsearch-0中）仍然是可以执行的，只不过此时的查询结果不一定正常，并且由于所有的负载都集中到elasticsearch-0中，此时查询性能较正常会更慢。

3、宿主机资源耗尽

3.1 理论分析

在前边初步排除掉JVM参数问题以及压测导致集群崩溃的原因，最后我们在考虑是不是因为服务器资源紧张，导致操作系统直接kill掉ES的java进程，linux在下边的一些场景下可能会kill掉java进程：

  • OOM Killer：当系统内存资源耗尽时，内核中的OOM（Out of Memory）Killer会尝试杀死一些进程以释放内存。OOM Killer会根据OOM分数（OOM Score）来选择要杀死的进程，OOM分数越高，进程被杀死的可能性越大。如果Java进程消耗了大量内存并使系统内存不足，它可能会被OOM Killer杀掉。
  • 超出资源限制：如果Java进程超出了系统或用户设置的资源限制（例如，CPU、内存或文件描述符数量等），CentOS可能会杀死Java进程。这些限制可以在/etc/security/limits.conf文件中设置。
  • Java进程阻塞或挂起：如果Java进程被阻塞或挂起，导致其无法响应系统信号，系统可能会杀死该进程。
  • 系统重启或关机：在系统重启或关机过程中，正在运行的Java进程可能会被终止。

在上边的这些可能性中，第一个OOM Killer是最有可能的，首先ES占用了32GB的内存资源，并且由于最大堆、最小堆为16GB，虽然没有达到参数上限，但此时操作系统资源已经耗尽，这个时候ES仍然尝试分配内存，最终被操作系统kill掉。

3.2 实际验证

  • 1、现场的服务器中有配置的普罗米修斯，但是现场OP配置的存储有一些问题，导致无法回溯超过几个小时以前的数据，所以现在无法通过普罗米修斯来确认当天的机器负载情况。
  • 2、在排查的过程中通过普罗米修斯查看当天宿主机资源情况，发现68、69的日常资源负载（内存使用率超过60%）较高，该现象可以作为该推论的的实际依据。
  • 3、使用原生的linux指令查看被操作系统kill掉的进程：
$ grep -i "killed process" /var/log/messages
$ dmesg | grep -i "killed process"

但是上边的两个指令，在宿主机中没有定位到对应时间的kill记录。所以排查到当前这一步，最有可能的原因还没有得到事故当时的日志验证。

四、解决方案

4.1 服务高可用

经过前边的分析我们可以看出来，无论是因为集群中的哪一个节点资源耗尽导致ES节点下线，都将会导致整个集群崩溃，因为只有两个节点（一些特殊原因造成），所以为了保证ES集群的高可用，非常有必要增加一个节点，来保证ES集群中至少有三个节点，这样当集群中的任意一个节点崩溃都不会直接导致ES集群崩溃。

4.2 性能优化

ES的查询、写入优化能够在一定程度上减少ES的资源使用量，所以我们可以分别从写入、查询优化两部分来分别尝试优化，但是注意，这些优化或多或少都会从其他方面付出一些“代价”，例如数据实时性、数据一致性、以及增加数据丢失可能性等等，所以在选择优化方案时需要综合考虑各方面的影响。

4.2.1 写入优化

  • 降低refresh_interval，在ES中默认是1秒钟就会产生一个segment，这会增加segment的数量已经导致执行更多的Merge policy（CPU密集型）操作，可以将当前的refresh_interval=30s调整为refresh_interval=45s/60s，
  • 调整ES Crash Safe策略：主要由两个参数index.translog.durability（在es中的translog类似于mysql中的redo log）、index.translog.sync_interval来进行控制；index.translog.durability默认值是request（每次请求都会执行fsyncs），所以可以考虑将值调整为async（异步刷盘），然后再设置刷盘的间隔时间（index.translog.sync_interval） ，该参数默认是5s，可以适当提高该值。但是注意不要设置得太大，否则可能导致丢失大量数据。
  • 控制indexing内存消耗：我们可以在集群层面配置index.indexing_pressure.memory.limit来限制indexing所使用的内存比例，避免因为indexing使用大量内存导致性能下降甚至节点崩溃。
  • 定期删除过期索引：针对过车数据的索引（每天一个），当时间跨度较长时，会产生大量的索引以及分片数，而每个分片都是一个独立的Lucene索引，Elasticsearch需要为每个分片维护额外的元数据，包括分片状态、分片大小等。大量的分片意味着更多的元数据需要维护，这会增加集群的管理开销。所以我们可以使用索引生命周期管理（ILM）：通过ILM策略自动合并、收缩和删除旧的索引，从而降低索引和分片的数量。

4.2.2 查询优化

这部分是一个比较大的话题，这里不进行展开，我们需要根据自己的业务需求来进行定向优化。

  • 冷热分离：将热点数据直接存放在SSD中能够极大（相差2~3个数量级）的增加随机读写的能力，这样对复杂的大量数据查询聚合操作，能够降低读延迟，同时也可以针对冷、热节点进行定向配置，例如热节点可以增加一些资源用来处理更多的查询和写入，而冷节点则可以适当减少一些资源配置，提高资源利用率。同样我们可以使用ES生态提供的索引生命周期管理（ILM）功能。通过为索引定义不同的生命周期阶段（如热、温和冷阶段），并将索引自动迁移到相应的阶段，就可以实现数据的冷热分离。
  • 利用缓存：在不涉及到打分的查询中，我们可以使用filter来代替must。

五、总结

  • 1、上边的这次事故，其实完全可以在服务部署的时候通过高可用的方案最大程度避免该问题，只不过由于在私有化环境部署时由于各种原因导致只给ES集群分配了两个节点，当集群中节点只有两个时，此时集群完全没有高可用的能力，只要挂掉其中一个就会导致整体服务不可用。
  • 2、日志、监控在运维中非常重要，本次排查过程中最终的结论因为现场无法回溯到当时服务器的实际情况，所以无法得到直观的印证。同时，当机器资源上升到一定阈值时，良好的监控报警机制也能够最大程度上避免集群进一步恶化。

本次故障排查分享就到这里，希望看到这篇文章的小伙伴们可以留言分享你的看法，相互交流学习，共同进步。

avatar
文章
阅读
粉丝