Spark Streaming任务调优实录记载

/bin/spark-submit --name jobname 
--driver-cores 2 --driver-memory 8g 
--num-executors 20 --executor-memory 18g 
--executor-cores 3 --conf spark.default.parallelism=120 
--conf "spark.executor.extraJavaOptions=-XX:+UseConcMarkSweepGC"
--driver-java-options "-XX:+UseConcMarkSweepGC" 
--master yarn-cluster 
--class  com.klordy.test.xxx 
--jars $jarpath  
${APP_HOME}/${MAINJAR} ${sparkconf} >> job.log &

./bin/spark-submit \
  --master yarn-cluster \
  --num-executors 100 \
  --executor-memory 6G \
  --executor-cores 4 \
  --driver-memory 1G \
  --conf spark.default.parallelism=1000 \
  --conf spark.storage.memoryFraction=0.5 \
  --conf spark.shuffle.memoryFraction=0.3 \
  --

  第一个例子中依据官网推荐的spark-streaming优化策略，通过--driver-java-options "-XX:+UseConcMarkSweepGC"设置了driver端垃圾回收策略为CMS，同时--conf "spark.executor.extraJavaOptions=-XX:+UseConcMarkSweepGC"设置executor端的垃圾回收器也用CMS，从而减少GC耗时。

  spark-streaming作业运行一段时间后，由于任务中有许多updateStateByKey算子，导致有较多的RDD数据需要持久化，但是测试过程中，设置了清除时间，超过某个时间的RDD数据会被清理，所以可以待作业运行了一段时间相对稳定后，查看UI中的Storage中统计的持久化的RDD数量，然后大致计算一共占用了多少内存，本人一个批次测试跨度是30S，然后每隔十分钟在updateStateByKey算子中对上个批次以前所有的key进行清空，也就是我的作业是计算每十分钟内一个指标，所以十分钟一到，之前的所有key就可以直接清空，运行了半个小时后，观察作业运行基本稳定，查看RDD缓存大致暂用60G左右的容量，而我分配给该任务的内存为num_executor*executor_memory=20*18=360G,如果用默认的spark.storage.memoryFraction，那么会有216G的内存是用来进行RDD持久化的，显然绝大多数情况下这部分内存是空闲浪费的，所以可以适当的调低spark.storage.memoryFraction，这里我们尝试分别设置为0.4、0.5，然后再依次分别调大spark.shuffle.memoryFraction的值，来测试。
  由于业务无需map端的排序，spark在进行shuffle时，默认的spark.shuffle.manager是sort，这种shuffle机制会在map端依据partition-key进行排序，这种排序对我们的业务是无意义的，所以调整spark.shuffle.manager为hash，启用HashShuffleManager，同时设置spark.shuffle.consolidateFiles为true，这个参数会尽量让map端为reduce生成文件时共享一个文件，从而减少map端生成的文件数量，具体参考https://cloud.tencent.com/developer/article/1029640中关于Spark Shuffle中原理的解析。修改了shuffle的机制后，再测试，选择批次时间为 6S和12S，分别用默认的sort和hash进行两轮测试，运行一个小时:

batch	shuffle	AvgTime
6s	sort	12s
6s	hash	8s
12s	hash	16s
12s	sort	18s

  很显然，用了hash后，每个批次平均处理时间减少了。但是至此运行时间久了还是无法会有延迟，我们继续进行调优。
  翻看Web UI的监控页面，看到了Executros中会显示一个Memory，这里会显示当前所有Executro的总内存和当前已用内存，经过观察，发现这里总内存为197G，我们在spark-submit中分配的总内存是360G，这里显示的是分配用来进行存储缓存RDD数据的内存，默认是spark.storage.memoryFraction这个参数控制的为0.6，此时我们可以在这个页面观察我们分配的这一部分内存的使用率，然后依据我们观察的结果合理调整spark.storage.memoryFraction和spark.shuffle.memoryFraction的值，Spark中总内存主要分为三部分，分别用于做RDD数据缓存、Shuffle数据缓存、任务执行内存，通过调整spark.storage.memoryFraction和spark.shuffle.memoryFraction合理调整这三块内存的比例合理充分的利用集群资源。
这里经过一段时间的观察executro中used memory的内存变化，发现由于任务中使用了非常多的updateStateByKey算子，导致内存消耗较多，但是对于我们分配的197G而言，会有相当大一部分内存一直是空闲的，故此我们需要调整占用比例了。
  不过呢，在这期间我们发现其中某一部分的任务会耗时越来越长，我们点击进stage中查看具体耗时，查看某个stage耗时，查看其中的Stages中的Event Timeline，看任务耗时最多的其实还是Executor Computing Time，我观察的任务批次60S，但是这个stage自己就消耗了30S，耗时十分多，而查看具体耗时绝大部分时间是在计算，所以可以选择调整分配给计算的内存占比，减少Storage RDD的内存分配，看看能不能有所改观。
  再次尝试参数调整spark.storage.memoryFraction=0.4，同时尝试给spark.shuffle.memoryFraction=0.25，然后设置spark.shuffle.file.buffer=64k调整shuffle溢写时的kvbuffer数组大小，减少磁盘IO次数，还和之前一样60S一个批次，进行观察。
很不幸这里参数配置时忘记调整spark.shuffle.manager参数为hash，用了sort，所以刚好借此机会对比一下在刚才那一套相同参数下，hash和sort作为shuffle策略的效率对比，结果如下(运行20min)：

batch	shuffle	AvgTime
60s	sort	52.15s
60s	hash	54s

  调整了map端的kvbuffer大小后，发现部分任务的shuffle时间反而更长了，之前shuffle是较为正常的，现在会偶尔出现几个任务的shuffle耗时特别长导致整个stage任务耗时较长，待会再把spark.shuffle.file.buffer=64k参数调整给取消，查看任务变化情况。暂时不知道为什么把spark.shuffle.file.buffer设置调大反而导致shuffle时间变长。
  这期间尝试了调整spark.default.parallelism=240，之前是120，发现集群资源利用的更好了，参考官网说的设置为num_cores*num_executor*2~3，发现任务运行时间有了很好的提示，从之前的50s+直接变成了均值49s。
  继续观察耗时长的stage，观察发现部分耗时长的是由于GC时间看起来很长，观察Tasks列表中的GC Time发现GC耗时占据任务时间比例普遍达到了总任务耗时的10%以上，对此我们需要查看GC的详细信息，在spark-submit中添加--conf "spark.executor.extraJavaOptions=-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps重启应用让对应executor们在进行GC的时候打印出GC的详细信息，启动应用后，随意找一个耗时较长的stage，观察这个stage的所有tasks，找到其中GC耗时较多的，去它所在的机器中去查看对应的日志，本人公司集群是Spark on Yarn，对应executor的运行日志存储路径在配置文件中设置，查看其中的stdout，观察发现如下日志:

18.934: [GC18.934: [ParNew: 1226816K->71680K(1380160K), 0.0614490 secs] 1415192K->260056K(18721024K), 0.0615490 secs] [Times: user=0.72 sys=0.01, real=0.06 secs] 
19.860: [GC19.861: [ParNew: 1298496K->43244K(1380160K), 0.0463230 secs] 1486872K->231621K(18721024K), 0.0464220 secs] [Times: user=0.54 sys=0.01, real=0.05 secs] 
20.664: [GC20.664: [ParNew: 1270060K->59542K(1380160K), 0.0588580 secs] 1458437K->247919K(18721024K), 0.0589440 secs] [Times: user=0.66 sys=0.00, real=0.05 secs] 
21.495: [GC21.495: [ParNew: 1286358K->81768K(1380160K), 0.0622300 secs] 1474735K->270144K(18721024K), 0.0623150 secs] [Times: user=0.65 sys=0.01, real=0.06 secs] 
22.214: [GC22.214: [ParNew: 1308584K->101297K(1380160K), 0.0573460 secs] 1496960K->289674K(18721024K), 0.0574640 secs] [Times: user=0.62 sys=0.01, real=0.06 secs] 
22.975: [GC22.975: [ParNew: 1328113K->124404K(1380160K), 0.0647480 secs] 1516490K->312781K(18721024K), 0.0648590 secs] [Times: user=0.76 sys=0.00, real=0.06 secs] 
23.782: [GC23.782: [ParNew: 1351220K->123238K(1380160K), 0.0864080 secs] 1539597K->326165K(18721024K), 0.0865180 secs] [Times: user=0.69 sys=0.02, real=0.09 secs] 
24.584: [GC24.584: [ParNew: 1350054K->129683K(1380160K), 0.0915830 secs] 1552981K->346860K(18721024K), 0.0916970 secs] [Times: user=0.73 sys=0.02, real=0.10 secs] 
25.583: [GC25.583: [ParNew: 1356499K->125823K(1380160K), 0.0880290 secs] 1573676K->357677K(18721024K), 0.0881410 secs] [Times: user=0.71 sys=0.02, real=0.09 secs] 
26.418: [GC26.418: [ParNew: 1352639K->135719K(1380160K), 0.0909370 secs] 1584493K->382237K(18721024K), 0.0910270 secs] [Times: user=0.67 sys=0.02, real=0.09 secs] 
27.409: [GC27.409: [ParNew: 1362535K->153344K(1380160K), 0.1056040 secs] 1609053K->413965K(18721024K), 0.1057030 secs] [Times: user=0.82 sys=0.04, real=0.10 secs] 
28.395: [GC28.395: [ParNew: 1380160K->153344K(1380160K), 0.1521850 secs] 1640781K->442886K(18721024K), 0.1523000 secs] [Times: user=0.96 sys=0.04, real=0.16 secs] 
29.405: [GC29.406: [ParNew: 1380160K->117953K(1380160K), 0.1223770 secs] 1669702K->436084K(18721024K), 0.1224870 secs] [Times: user=0.94 sys=0.02, real=0.13 secs] 
30.324: [GC30.324: [ParNew: 1344490K->116616K(1380160K), 0.1082250 secs] 1662620K->475410K(18721024K), 0.1083490 secs] [Times: user=0.82 sys=0.03, real=0.11 secs] 
31.213: [GC31.214: [ParNew: 1343432K->78066K(1380160K), 0.0863530 secs] 1702226K->461992K(18721024K), 0.0864690 secs] [Times: user=0.81 sys=0.01, real=0.09 secs] 
32.069: [GC32.069: [ParNew: 1304882K->100064K(1380160K), 0.0513260 secs] 1688808K->483990K(18721024K), 0.0514380 secs] [Times: user=0.62 sys=0.00, real=0.05 secs] 
...

  可以很明显看到task运行期间有极其频繁的Minor GC，而且堆的总大小为18721024K接近18G，但是年轻代大小才1380160K大约1.2G，由于年轻代大小不够，从而导致频繁的Minor GC，所以这里自然想到调整年轻代分配大小，我们把内存调整为12G再设置年轻代为2G大小试试应用情况：--conf "spark.executor.extraJavaOptions=-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xmn2048M运行20min发现每个批次平均处理时间还是49s，因为仍然偶尔会有几个批次的GC时间较长，导致平均耗时减少的不是很多(提升了大约0.5s)，由于发现基本没有发生FULL GC，耗时集中在Minor GC，很显然老年代内存是观察下来是十分充足的，这次勇敢的再尝试调整年轻代为4G试试，发现这样调整作用并不大，平均处理时间没大的改善，不过处理时间很诡异的是总是会不定期出现一些批次处理时间特别慢，导致平均耗时较多，查看各个耗时多的批次，发现某些任务会出现某一台机器中GC处理时间特别漫长，但是观察其中的GC日志没有发现有FULL GC的出现，初步观察是在Minor GC的时候，耗时特别长，原因还需要排查，未完待续。