请先关注 [低调大师] 公众号 优秀的自媒体个人博客,低调大师,许军

低调大师

您现在的位置是:首页>文章详情

文章详情

记Structured Streaming 2.3.1的OOM排查过程

2018-09-26 219热度

记Structured Streaming 2.3.1的OOM排查过程

缘起

最近在使用Structured Streaming开发一套自助配置SQL的来生成流式作业的平台,在测试的过程中发现有些作业长时间运行后会有Executor端的OOM,起初以为是代码的问题,几经review和重构代码,都没有解决,无奈开始了这次OOM的问题排查之路。

干货

出现的问题

Structured Streaming 作业长时间运行后,会出现如下问题

可以看到spark为我们提供的统计信息,Task的GC时间占到了Task执行时间的70%,起初以为配置的内存不够,但是反复调大内存均出现此问题。

出现这种问题之后,紧接着就会出现Executor和Driver间心跳异常,或者Executor假死的状态,一般出现这类假死、jvm没有响应的问题大都可初步判断为是因为Jvm的Full GC而造成的Stop the World现象。

紧接着再过一段时间之后,在Executor的日志中会出现java.lang.OutOfMemoryError: Java heap space这类异常,导致Executor挂掉。

综上现象,初步推测是因为Executor端出现了内存泄漏。

收集信息

由于作业是从hermes平台提交的,目前的hermes平台还没有提供提交Spark任务打印jvm的gc日志的功能。故决定在线下集群上自己配置一个Spark的客户端,在spark-default.conf里配置driver和executor运行时的jvm参数,使其在进行gc时将gc信息打印出来,配置如下:

spark.executor.extraJavaOptions -verbose:gc -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:OnOutOfMemoryError='kill -9 %p' spark.driver.extraJavaOptions -verbose:gc -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:OnOutOfMemoryError='kill -9 %p' 

这几个参数的意思是配置jvm在发生gc时打印gc的详情信息,当发生OOM异常时,使用kill -9 杀死jvm。

一段GC 日志大概长这样:

0.756: [Full GC (System) 0.756: [CMS: 0K->1696K(204800K), 0.0347096 secs] 11488K->1696K(252608K), [CMS Perm : 10328K->10320K(131072K)], 0.0347949 secs] [Times: user=0.06 sys=0.00, real=0.05 secs] 1.728: [GC 1.728: [ParNew: 38272K->2323K(47808K), 0.0092276 secs] 39968K->4019K(252608K), 0.0093169 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2.642: [GC 2.643: [ParNew: 40595K->3685K(47808K), 0.0075343 secs] 42291K->5381K(252608K), 0.0075972 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 4.349: [GC 4.349: [ParNew: 41957K->5024K(47808K), 0.0106558 secs] 43653K->6720K(252608K), 0.0107390 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs] 

排查过程

等了好久终于又等到Executor假死的现象,通过yarn提供的日志链接,看到这个Executor的GC日志一直在刷,正在进行疯狂的Full GC, 因为Spark是运行在yarn集群上的,所以只能委托公司的OP兄弟,把发生OOM但还没挂掉的Executor的内存镜像保存下来:

jmap -dump:live,format=b,file=dump.hprof $pid 

将生成的dump.hprof文件下载到本地,使用java自带的jvisualvm工具打开,将类名根据大小排序,得到如下图:

可以看到byte[]类型的对象占了将近1G的内存,明显是发生了内存泄漏。双击这行:

发现除了绝大多数的字节数组都是65560长度,且内容全为0,而且在右下侧的窗口里发现引用这些字节数组的类都是EPollArrayWrapper类,经过查找发现存在如下类型的类,其数量均为14823,

  • sun.nio.ch.EPollArrayWrapper
  • sun.nio.ch.EPollSelectorImpl
  • sun.nio.ch.SelectorImpl (实现了 java.nio.channels.Selector)
  • org.apache.kafka.common.network.Selector
  • org.apache.kafka.clients.NetworkClient
  • org.apache.kafka.clients.consumer.internals.Fetcher
  • org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient
  • org.apache.kafka.clients.consumer.internals.ConsumerCoordinator
  • org.apache.kafka.common.metrics.Metrics
  • org.apache.kafka.common.metrics.JmxReporter

这些都是kafka包里的类,但是名没有发现KafkaConsumer或者KafkaProducer类,而且从日志中看,发现每个批次都会有KafkaConsumer被创建,于是怀疑是KafkaConsumer多次被创建,但是没有回收干净而导致的内存泄漏,查看源码,发现存在如下引用链:

每次创建KafkaConsumer并进行网络通信后,都会把内部的一些监控信息注册到MBeanServer中,这样在MBeanServer中就存在了如上图的引用链,但是在KafkaConsumer对象被回收的时候,并没有调用其close方法,也就是并没有回收这些对象,这样就造成了内存泄漏。

那么问题来了,为什么会创建如此之多的KafkaConsumer,Structured Streaming没有复用KafkaConsumer的机制么?这显然是不可能的。 所以,我们需要查找在什么情况下会需要额外的创建KafkaConsumer,以及为什么这些创建出来的KafkaConsumer没有被调用close呢。

在Structured Streaming中,整合kafka的代码在

<dependency> <groupId>org.apache.spark</groupId> <artifactId>spark-sql-kafka-0-10_2.11</artifactId> <version>2.3.1</version> </dependency> 

包的KafkaSourceRDD类中,通过添加日志,我们定位到问题代码在compute方法中。

首先介绍一下KafkaDataConsumer.acquire方法的作用,它会返回一个经过封装的KafkaDataConsumer

 def acquire( topicPartition: TopicPartition, kafkaParams: ju.Map[String, Object], useCache: Boolean): KafkaDataConsumer = synchronized { val key = new CacheKey(topicPartition, kafkaParams) val existingInternalConsumer = cache.get(key) lazy val newInternalConsumer = new InternalKafkaConsumer(topicPartition, kafkaParams) if (TaskContext.get != null && TaskContext.get.attemptNumber >= 1) { // If this is reattempt at running the task, then invalidate cached consumer if any and // start with a new one. if (existingInternalConsumer != null) { // Consumer exists in cache. If its in use, mark it for closing later, or close it now. if (existingInternalConsumer.inUse) { existingInternalConsumer.markedForClose = true } else { existingInternalConsumer.close() } } cache.remove(key) // Invalidate the cache in any case NonCachedKafkaDataConsumer(newInternalConsumer) } else if (!useCache) { // If planner asks to not reuse consumers, then do not use it, return a new consumer NonCachedKafkaDataConsumer(newInternalConsumer) } else if (existingInternalConsumer == null) { // If consumer is not already cached, then put a new in the cache and return it cache.put(key, newInternalConsumer) newInternalConsumer.inUse = true CachedKafkaDataConsumer(newInternalConsumer) } else if (existingInternalConsumer.inUse) { // If consumer is already cached but is currently in use, then return a new consumer NonCachedKafkaDataConsumer(newInternalConsumer) } else { // If consumer is already cached and is currently not in use, then return that consumer existingInternalConsumer.inUse = true CachedKafkaDataConsumer(existingInternalConsumer) } } 

代码中的useCache参数为true,所以我们只看下面的三个分支就可以了:

  1. 看cache里是否有指定分区的KafkaConsumer,没有的话会创建一个,放到缓存中,并标记位正在使用的状态
  2. 如果有的话,但是是正在被使用的状态,会创建一个新的,不被缓存的
  3. 存在且为可用状态,直接标记为正在使用

我们在compute方法中看到,在下面的else分支里,当任务完成是,会回调迭代器的closeIfNeed方法,底层会调用到KafkaDataConsumer.release方法,针对被缓存的KafkaDataConsumer,将其状态标记位可被使用的状态,而针对不被缓存的KafkaDataConsumer,直接调用其close方法。这个逻辑在compute方法的else分支里是没有问题的。

问题出在compute的if(range.fromOffset == range.untilOffset)的时候,这里直接返回了一个空的迭代器,而并没有将上面获取到的consumer关闭,这就造成了KafkaConsumer内对象的泄漏。

之后在github上找到了修复相关问题的提交: https://github.com/apache/spark/commit/14b50d7fee58d56cb8843994b1a423a6b475dcb5

修复了这个问题,修复的方法就是在返回空的迭代器之前将之前获取到的consumer关闭即可。 但是修复的代码是要发布在2.3.2版本中的,所以我们只能将spark-sql-kafka的源码包下载,集成到项目中来修复这个bug。

收藏 (0)

相关文章

    文章评论

    共有0条评论来说两句吧...