question Spark Job long GC pauses in Support Questions

question Spark Job long GC pauses in Support Questions https://community.cloudera.com/t5/Support-Questions/Spark-Job-long-GC-pauses/m-p/282690#M210140 <P>Hi,</P> <P> </P> <P>I am running a Spark Job as below:</P> <P> </P> <P><SPAN><SPAN>/spark-submit --master yarn --deploy-mode client --name sparktest </SPAN><SPAN>--num-executors 500</SPAN> <SPAN>--executor-memory 30g</SPAN> <SPAN>--driver-memory 16g --queue apps_aup --conf</SPAN> <SPAN>spark.yarn.executor.memoryOverhead=2000</SPAN> <SPAN>--conf spark.driver.maxResultSize=12g --conf</SPAN> <SPAN>spark.executor.cores=2</SPAN> <SPAN>--conf</SPAN> <SPAN>spark.task.cpus=2</SPAN> <SPAN>--conf</SPAN> <A href="http://spark.network.timeout=600/" target="_blank" rel="noopener">spark.network.timeout=600</A> <SPAN>--conf spark.blacklist.enabled=true --conf "spark.executor.extraJavaOptions=</SPAN><SPAN>-verbose:gc -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=8 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps</SPAN><SPAN>"<BR /><BR />The Job runs successfully, but everytime it runs there are some of the tasks which run into long GC Pauses.<BR /><BR /></SPAN></SPAN></P> <P><SPAN><SPAN>I could see following when troubleshooting GC:</SPAN></SPAN></P> <P><SPAN><SPAN> </SPAN></SPAN></P> <P>A.) </P> <DIV class="panel"> <DIV class="panelHeader"><STRONG>Observation for GC -  Executor ID 2</STRONG></DIV> <DIV class="panelContent"> <P>1.  GC options Used:</P> <P> </P> <DIV class="code panel"> <DIV class="codeContent panelContent"> <PRE>-verbose:gc -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=8 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps</PRE> </DIV> </DIV> <P> </P> <P>2. Executor Details :</P> <P> </P> <DIV class="code panel"> <DIV class="codeContent panelContent"> <PRE>spark.executor.memory = 30GB Storage Memory of Executor = 17GB spark.executor.instances = 500</PRE> </DIV> </DIV> <P> </P> <DIV class="table-wrap"> <TABLE> <TBODY> <TR> <TD>Executor ID</TD> <TD>2</TD> </TR> </TBODY> </TABLE> </DIV> <P> </P> <P>3. Task Details : </P> <DIV class="table-wrap"> <TABLE> <TBODY> <TR> <TD>Task Time = 19 min , GC Time =<SPAN> </SPAN><STRONG>16</STRONG><SPAN> </SPAN>min</TD> <TD>Input Data Size =<SPAN> </SPAN><STRONG>217.9</STRONG><SPAN> </SPAN>MB</TD> <TD>Shuffle Write Size = 651.8 MB</TD> </TR> </TBODY> </TABLE> </DIV> <P>The above shows that the Total GC time  on Executor ID 2, was very high. it was around 16 minutes.</P> </DIV> </DIV> <P> </P> <P>B.) <STRONG>GC Analysis for Sample Executor ID 2</STRONG></P> <DIV class="panel"> <DIV class="panelContent"> <P><STRONG>Full GC time:</STRONG></P> <DIV class="code panel"> <DIV class="codeContent panelContent"> <PRE>The Full GC Count happened 7 times. The total time <SPAN class="code-keyword">for</SPAN> these 7  Full GC was 10 min 38 sec 190 ms. Hence, the  average Full GC time was 1 min 31 sec 170 ms. The Average Interval between Full GC Interval was 1 min 59 sec 524 ms.</PRE> </DIV> </DIV> <P>Full GC Size :</P> <DIV class="code panel"> <DIV class="codeContent panelContent"> <PRE>The reclaimed data size  from the full GC was 1.56 gb </PRE> </DIV> </DIV> <P><STRONG>Minor GC :</STRONG></P> <DIV class="code panel"> <DIV class="codeContent panelContent"> <PRE>The Total Minor GC count was 20 The total time <SPAN class="code-keyword">for</SPAN> Minor GC was 5 min 32 sec 380 ms The average time <SPAN class="code-keyword">for</SPAN> Minor GC was 16 sec 619 ms  Each of these Minor GC happened at an interval <SPAN class="code-keyword">for</SPAN> approximately 1 min 631 ms During these 20 Minor GC the Total size of Data reclaimed was 33.65 GB</PRE> </DIV> </DIV> </DIV> </DIV> <P> </P> <P> C.)</P> <DIV class="code panel"> <DIV class="codeContent panelContent"> <PRE>The Total objects created by application added to be around 45.15 GB. The <SPAN class="code-object">Object</SPAN> creation rate by the application was around 40 MB/s. The Total Objects which got promoted from youngGen to oldGen in each GC cycle was around 8 GB. These objects were promoted on an average rate of 7 MB/s There was around 18 Allocation Failures, which indicated that the object creation rate was higher than the free heap space in the younGen. This lead to 18 Minor GC cycles (out of 20 total minor GC) to free up younGen and promote objects from younGen to OldGen.</PRE> </DIV> </DIV> <P> </P> <P>D.) GC Time :</P> <DIV class="panel"> <DIV class="panelHeader"><STRONG>GC Time - real, user, sys</STRONG></DIV> <DIV class="panelContent"> <P>The longest Full GC was around 5 minutes :</P> <DIV class="code panel"> <DIV class="codeContent panelContent"> <PRE>722.599: [Full GC (Ergonomics) [PSYoungGen: 1304054K->0K(7388672K)] [ParOldGen: 9194816K->10418042K(14044160K)] 10498870K->10418042K(21432832K), [Metaspace: 56010K->56010K(1099776K)], 303.5027565 secs] </PRE> </DIV> </DIV> <P>Here I see - </P> <DIV class="code panel"> <DIV class="codeContent panelContent"> <PRE>[Times: user=711.36 sys=35.16, real=303.50 secs]</PRE> </DIV> </DIV> <P>The time spend for GC for system was 35.16 second.<BR />The user time was 711.36 seconds. This is the time added by each GC thread.<BR />The User + Sys = 746.52 seconds. </P> <P>The Real Time was only 303.50 seconds (5.05 Minutes). This was the actual time which was spend in GC.  This looks good from the Cluster Perspective since the system time was only 35.16. The system looks good (CPU cycles free) to perform the GC.</P> </DIV> </DIV> <P> </P> <P><SPAN><SPAN>The GC log analysis is from the GCeasy link :</SPAN></SPAN></P> <TABLE border="1"> <TBODY> <TR> <TD><SPAN><SPAN><A href="https://gceasy.io/my-gc-report.jsp?p=c2hhcmVkLzIwMTkvMTEvMTEvLS1nY19zcGFya18zLnR4dC0tMTktNTItNQ==&channel=WEB" target="_blank" rel="noopener">https://gceasy.io/my-gc-report.jsp?p=c2hhcmVkLzIwMTkvMTEvMTEvLS1nY19zcGFya18zLnR4dC0tMTktNTItNQ==&channel=WEB</A> </SPAN></SPAN></TD> </TR> </TBODY> </TABLE> <P><SPAN><SPAN> </SPAN></SPAN></P> <P> </P> <P><SPAN><SPAN>The GC logs shows:</SPAN></SPAN></P> <TABLE border="1"> <TBODY> <TR> <TD>426.481: [Full GC (Ergonomics) [PSYoungGen: 1520503K->200302K(5950464K)] [ParOldGen: 6657880K->7368200K(10468864K)] 8178383K->7568503K(16419328K), [Metaspace: 55722K->55722K(1097728K)], 142.3782071 secs] [Times: user=329.05 sys=12.63, real=142.38 secs]<BR />572.138: [GC (Allocation Failure) [PSYoungGen: 3949678K->1623296K(6054400K)] 11317879K->9192449K(16523264K), 40.8130588 secs] [Times: user=99.07 sys=2.21, real=40.81 secs]<BR />633.942: [GC (Allocation Failure) [PSYoungGen: 5372672K->1304054K(7388672K)] 12941825K->10498870K(17857536K), 88.6569824 secs] [Times: user=212.32 sys=6.40, real=88.66 secs]<BR />722.599: [Full GC (Ergonomics) [PSYoungGen: 1304054K->0K(7388672K)] [ParOldGen: 9194816K->10418042K(14044160K)] 10498870K->10418042K(21432832K), [Metaspace: 56010K->56010K(1099776K)], 303.5027565 secs] [Times: user=711.36 sys=35.16, real=303.50 secs]<BR />1060.380: [GC (Allocation Failure) [PSYoungGen: 4968960K->208K(7355392K)] 15387002K->10418258K(21399552K), 0.1422739 secs] [Times: user=0.23 sys=0.50, real=0.14 secs]<BR />1090.725: [GC (Allocation Failure) [PSYoungGen: 4969168K->352K(8035840K)] 15387218K->10418410K(22080000K), 0.0677690 secs] [Times: user=0.19 sys=0.34, real=0.07 secs]<BR />1124.474: [GC (Allocation Failure) [PSYoungGen: 5606752K->256K(5606912K)] 16024810K->10418322K(19651072K), 0.0516994 secs] [Times: user=0.20 sys=0.17, real=0.05 secs]<BR />1157.440: [GC (Allocation Failure) [PSYoungGen: 5606656K->368K(8077312K)] 16024722K->10418434K(22121472K), 0.0649818 secs] [Times: user=0.18 sys=0.33, real=0.07 secs]</TD> </TR> </TBODY> </TABLE> <P> </P> <P><SPAN><SPAN>The Spark UI shows that the Input Data Size is 217 MB:<span class="lia-inline-image-display-wrapper lia-image-align-inline" image-alt="Screen Shot 2019-11-11 at 10.10.39 PM.png" style="width: 999px;"><img src="https://community.cloudera.com/t5/image/serverpage/image-id/25266iD1550C215C4C0DEB/image-size/large?v=v2&px=999" role="button" title="Screen Shot 2019-11-11 at 10.10.39 PM.png" alt="Screen Shot 2019-11-11 at 10.10.39 PM.png" /></span></SPAN></SPAN></P> <P> </P> <P> </P> <P><SPAN><SPAN>Why is the GC Pause so high for a Input data of only 217 MB?</SPAN></SPAN></P> <P><SPAN><SPAN>What does the Input refer here?</SPAN></SPAN></P> Tue, 12 Nov 2019 13:46:33 GMT PARTOMIA09 2019-11-12T13:46:33Z