(DEPRECATED) Apache Flink User Mailing List archive.

Flink program，Full GC (System.gc()）

classic Classic list List threaded Threaded
♦
♦
 4 messages Options
陈Darling
Reply | Threaded
Open this post in threaded view
♦
♦
|

Flink program，Full GC (System.gc()）

陈Darling

Flink Version: 1.8.1

deploy：standalone

state.backend.fs.memory-threshold=128k

A very very simple flink program and without other jar dependended；

But trigger full gc every hour by Full GC (System.gc() in jobmanager

Jobmanager 



I only find this where called System.gc()，but not sure  when will be call? 

Has anyone encountered a similar situation?

/**
 * Gets an estimate of the size of the free heap memory.
 * 
 * NOTE: This method is heavy-weight. It triggers a garbage collection to reduce fragmentation and get
 * a better estimate at the size of free memory. It is typically more accurate than the plain version
 * {@link #getSizeOfFreeHeapMemory()}.
 * 
 * @return An estimate of the size of the free heap memory, in bytes.
 */
public static long getSizeOfFreeHeapMemoryWithDefrag() {
   // trigger a garbage collection, to reduce fragmentation
   System.gc();
   
   return getSizeOfFreeHeapMemory();
}



   ..
  317  14972.571: [GC (Allocation Failure) 14972.572: [ParNew: 1870848K->236623K(1870848K), 0.0318714 secs] 2910945K->1276963K(3298304K), 0.0321537 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
  318  15024.592: [GC (Allocation Failure) 15024.592: [ParNew: 1840207K->267264K(1870848K), 0.0420305 secs] 2880547K->1309499K(3298304K), 0.0422980 secs] [Times: user=0.12 sys=0.00, real=0.04 secs] 
  319: 15049.334: [Full GC (System.gc()) 15049.334: [CMS: 1042235K->322292K(1427456K), 0.2932806 secs] 1552421K->322292K(3298304K), [Metaspace: 63049K->63049K(1105920K)], 0.2938379 secs] [Times: user=0.30 sys=0.00, real=0.29 secs] 
  320  15068.400: [GC (Allocation Failure) 15068.400: [ParNew: 1603548K->219691K(1870848K), 0.0244228 secs] 1925840K->541984K(3298304K), 0.0246696 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
  321  15157.833: [GC (Allocation Failure) 15157.833: [ParNew: 1823275K->169121K(1870848K), 0.0271608 secs] 2145568K->491414K(3298304K), 0.0274543 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
  ...
  676  30481.818: [GC (Allocation Failure) 30481.819: [ParNew: 1813938K->267264K(1870848K), 0.0423833 secs] 2864487K->1320335K(3298304K), 0.0425678 secs] [Times: user=0.12 sys=0.00, real=0.05 secs] 
  677  30557.470: [GC (Allocation Failure) 30557.470: [ParNew: 1870781K->267264K(1870848K), 0.0356143 secs] 2923853K->1330480K(3298304K), 0.0358636 secs] [Times: user=0.11 sys=0.00, real=0.04 secs] 
  678: 30615.513: [Full GC (System.gc()) 30615.513: [CMS: 1063216K->325191K(1427456K), 0.4150118 secs] 2772924K->325191K(3298304K), [Metaspace: 63756K->63756K(1107968K)], 0.4156102 secs] [Times: user=0.42 sys=0.00, real=0.41 secs] 
  679  30649.417: [GC (Allocation Failure) 30649.417: [ParNew: 1603486K->154121K(1870848K), 0.0236163 secs] 1928677K->479312K(3298304K), 0.0238171 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] 
  680  30734.471: [GC (Allocation Failure) 30734.471: [ParNew: 1757698K->164639K(1870848K), 0.0318273 secs] 2082889K->489830K(3298304K), 0.0320078 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 
  ...
  838  37620.283: [GC (Allocation Failure) 37620.283: [ParNew: 1819345K->267264K(1870848K), 0.0350667 secs] 2675979K->1123898K(3298304K), 0.0352966 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
  839  37696.182: [GC (Allocation Failure) 37696.182: [ParNew: 1870725K->267264K(1870848K), 0.0318628 secs] 2727360K->1124191K(3298304K), 0.0320820 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
  840: 37736.562: [Full GC (System.gc()) 37736.562: [CMS: 856927K->326386K(1427456K), 0.3860904 secs] 2420047K->326386K(3298304K), [Metaspace: 63914K->63914K(1107968K)], 0.3867480 secs] [Times: user=0.39 sys=0.00, real=0.38 secs] 
  841  37786.710: [GC (Allocation Failure) 37786.710: [ParNew: 1603475K->160119K(1870848K), 0.0211419 secs] 1929861K->486506K(3298304K), 0.0214152 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 
  842  37868.276: [GC (Allocation Failure) 37868.276: [ParNew: 1763703K->156520K(1870848K), 0.0274233 secs] 2090090K->482907K(3298304K), 0.0277311 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
  ...
  957  43291.423: [GC (Allocation Failure) 43291.424: [ParNew: 1870848K->267264K(1870848K), 0.0422492 secs] 2779218K->1208332K(3298304K), 0.0425675 secs] [Times: user=0.13 sys=0.00, real=0.04 secs] 
  958  43301.420: [GC (Allocation Failure) 43301.420: [ParNew: 1870766K->267264K(1870848K), 0.0514803 secs] 2811834K->1324858K(3298304K), 0.0517214 secs] [Times: user=0.16 sys=0.00, real=0.06 secs] 
  959: 43348.937: [Full GC (System.gc()) 43348.937: [CMS: 1057594K->326740K(1427456K), 0.3976217 secs] 1966751K->326740K(3298304K), [Metaspace: 63978K->63978K(1107968K)], 0.3982278 secs] [Times: user=0.40 sys=0.00, real=0.40 secs] 
  960  43388.807: [GC (Allocation Failure) 43388.807: [ParNew: 1603565K->215196K(1870848K), 0.0229975 secs] 1930306K->541937K(3298304K), 0.0232834 secs] [Times: user=0.07 sys=0.00, real=0.02 secs] 
  961  43473.412: [GC (Allocation Failure) 43473.413: [ParNew: 1818755K->159795K(1870848K), 0.0279802 secs] 2145495K->486536K(3298304K), 0.0282288 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 
Xintong Song
Reply | Threaded
Open this post in threaded view
♦
♦
|

Re: Flink program，Full GC (System.gc()）

Xintong Song
Hi Andrew,

The behavior you described doesn't looks like a problem to me. I mean what are the bad consequences for having a full GC (which takes less than 0.5 second) per hour?

The full GC is not necessarily triggered by explicitly calling "System.gc()" in Flink. JVM also does that automatically, as long as there are continuous activities of creating / destroying objects in heap, e.g., due to heartbeats. Please refer to java garbage collection documents [1] for more details.

Thank you~

Xintong Song



On Tue, Aug 13, 2019 at 1:04 PM Andrew Lin <[hidden email]> wrote:

Flink Version: 1.8.1

deploy：standalone

state.backend.fs.memory-threshold=128k

A very very simple flink program and without other jar dependended；

But trigger full gc every hour by Full GC (System.gc() in jobmanager

Jobmanager 



I only find this where called System.gc()，but not sure  when will be call? 

Has anyone encountered a similar situation?

/**
 * Gets an estimate of the size of the free heap memory.
 * 
 * NOTE: This method is heavy-weight. It triggers a garbage collection to reduce fragmentation and get
 * a better estimate at the size of free memory. It is typically more accurate than the plain version
 * {@link #getSizeOfFreeHeapMemory()}.
 * 
 * @return An estimate of the size of the free heap memory, in bytes.
 */
public static long getSizeOfFreeHeapMemoryWithDefrag() {
   // trigger a garbage collection, to reduce fragmentation
   System.gc();
   
   return getSizeOfFreeHeapMemory();
}



   ..
  317  14972.571: [GC (Allocation Failure) 14972.572: [ParNew: 1870848K->236623K(1870848K), 0.0318714 secs] 2910945K->1276963K(3298304K), 0.0321537 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
  318  15024.592: [GC (Allocation Failure) 15024.592: [ParNew: 1840207K->267264K(1870848K), 0.0420305 secs] 2880547K->1309499K(3298304K), 0.0422980 secs] [Times: user=0.12 sys=0.00, real=0.04 secs] 
  319: 15049.334: [Full GC (System.gc()) 15049.334: [CMS: 1042235K->322292K(1427456K), 0.2932806 secs] 1552421K->322292K(3298304K), [Metaspace: 63049K->63049K(1105920K)], 0.2938379 secs] [Times: user=0.30 sys=0.00, real=0.29 secs] 
  320  15068.400: [GC (Allocation Failure) 15068.400: [ParNew: 1603548K->219691K(1870848K), 0.0244228 secs] 1925840K->541984K(3298304K), 0.0246696 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
  321  15157.833: [GC (Allocation Failure) 15157.833: [ParNew: 1823275K->169121K(1870848K), 0.0271608 secs] 2145568K->491414K(3298304K), 0.0274543 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
  ...
  676  30481.818: [GC (Allocation Failure) 30481.819: [ParNew: 1813938K->267264K(1870848K), 0.0423833 secs] 2864487K->1320335K(3298304K), 0.0425678 secs] [Times: user=0.12 sys=0.00, real=0.05 secs] 
  677  30557.470: [GC (Allocation Failure) 30557.470: [ParNew: 1870781K->267264K(1870848K), 0.0356143 secs] 2923853K->1330480K(3298304K), 0.0358636 secs] [Times: user=0.11 sys=0.00, real=0.04 secs] 
  678: 30615.513: [Full GC (System.gc()) 30615.513: [CMS: 1063216K->325191K(1427456K), 0.4150118 secs] 2772924K->325191K(3298304K), [Metaspace: 63756K->63756K(1107968K)], 0.4156102 secs] [Times: user=0.42 sys=0.00, real=0.41 secs] 
  679  30649.417: [GC (Allocation Failure) 30649.417: [ParNew: 1603486K->154121K(1870848K), 0.0236163 secs] 1928677K->479312K(3298304K), 0.0238171 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] 
  680  30734.471: [GC (Allocation Failure) 30734.471: [ParNew: 1757698K->164639K(1870848K), 0.0318273 secs] 2082889K->489830K(3298304K), 0.0320078 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 
  ...
  838  37620.283: [GC (Allocation Failure) 37620.283: [ParNew: 1819345K->267264K(1870848K), 0.0350667 secs] 2675979K->1123898K(3298304K), 0.0352966 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
  839  37696.182: [GC (Allocation Failure) 37696.182: [ParNew: 1870725K->267264K(1870848K), 0.0318628 secs] 2727360K->1124191K(3298304K), 0.0320820 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
  840: 37736.562: [Full GC (System.gc()) 37736.562: [CMS: 856927K->326386K(1427456K), 0.3860904 secs] 2420047K->326386K(3298304K), [Metaspace: 63914K->63914K(1107968K)], 0.3867480 secs] [Times: user=0.39 sys=0.00, real=0.38 secs] 
  841  37786.710: [GC (Allocation Failure) 37786.710: [ParNew: 1603475K->160119K(1870848K), 0.0211419 secs] 1929861K->486506K(3298304K), 0.0214152 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 
  842  37868.276: [GC (Allocation Failure) 37868.276: [ParNew: 1763703K->156520K(1870848K), 0.0274233 secs] 2090090K->482907K(3298304K), 0.0277311 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
  ...
  957  43291.423: [GC (Allocation Failure) 43291.424: [ParNew: 1870848K->267264K(1870848K), 0.0422492 secs] 2779218K->1208332K(3298304K), 0.0425675 secs] [Times: user=0.13 sys=0.00, real=0.04 secs] 
  958  43301.420: [GC (Allocation Failure) 43301.420: [ParNew: 1870766K->267264K(1870848K), 0.0514803 secs] 2811834K->1324858K(3298304K), 0.0517214 secs] [Times: user=0.16 sys=0.00, real=0.06 secs] 
  959: 43348.937: [Full GC (System.gc()) 43348.937: [CMS: 1057594K->326740K(1427456K), 0.3976217 secs] 1966751K->326740K(3298304K), [Metaspace: 63978K->63978K(1107968K)], 0.3982278 secs] [Times: user=0.40 sys=0.00, real=0.40 secs] 
  960  43388.807: [GC (Allocation Failure) 43388.807: [ParNew: 1603565K->215196K(1870848K), 0.0229975 secs] 1930306K->541937K(3298304K), 0.0232834 secs] [Times: user=0.07 sys=0.00, real=0.02 secs] 
  961  43473.412: [GC (Allocation Failure) 43473.413: [ParNew: 1818755K->159795K(1870848K), 0.0279802 secs] 2145495K->486536K(3298304K), 0.0282288 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 
陈Darling
Reply | Threaded
Open this post in threaded view
♦
♦
|

Fwd: Flink program，Full GC (System.gc()）

陈Darling
Hi Xintong,

Thanks for your answer！

I also think that is not  a big problem because it’ takes less than 0.5 second。I only want to find what was caused. 

"JVM also does that automatically, as long as there are continuous activities of creating / destroying objects in heap”


I also find some answers like yours：


“You may be interested to know that IBM provide a command-line option to disable System.gc() entirely. To get the behaviour, add -Xdisableexplicitgc to your command-line (the equivalent Sun option is -XX:+DisableExplicitGC). However, completely disabling System.gc() may have unintended consequences, because some System.gc() calls are useful and necessary (those which are used to generate seeds for crypto operations, or to free up resources associated with NIO buffers, for example) [1].”




Darling 
Andrew D.Lin





下面是被转发的邮件：

发件人: Xintong Song <[hidden email]>
主题: 回复： Flink program，Full GC (System.gc()）
日期: 2019年8月13日 GMT+8 下午10:24:13
收件人: Andrew Lin <[hidden email]>
抄送: user <[hidden email]>
陈Darling
Reply | Threaded
Open this post in threaded view
♦
♦
|

Fwd: Full GC (System.gc()）rmi.dgc

陈Darling
In reply to this post by 陈Darling


Regular full gc because rmi.dgc
Trigger one hour by default， 3600000ms

We can change the default value by setting the fallowing parameters。Recommended to increase
-Dsun.rmi.dgc.client.gcInterval=7200000 -Dsun.rmi.dgc.server.gcInterval=7200000

The Sun ONE Application Server uses RMI in the Administration module for monitoring. Garbage cannot be collected in RMI based distributed applications without occasional local collections, so RMI forces a periodic full collection. The frequency of these collections can be controlled with the property -sun.rmi.dgc.client.gcInterval. For example, - java -Dsun.rmi.dgc.client.gcInterval=3600000 specifies explicit collection once per hour instead of the default rate of once per minute [1].



下面是被转发的邮件：

发件人: Andrew Lin <[hidden email]>
主题: Flink program，Full GC (System.gc()）
日期: 2019年8月13日 GMT+8 下午6:59:23
收件人: [hidden email]


Flink Version: 1.8.1

deploy：standalone

state.backend.fs.memory-threshold=128k

A very very simple flink program and without other jar dependended；

But trigger full gc every hour by Full GC (System.gc() in jobmanager

Jobmanager 



I only find this where called System.gc()，but not sure  when will be call? 

Has anyone encountered a similar situation?

/**
 * Gets an estimate of the size of the free heap memory.
 * 
 * NOTE: This method is heavy-weight. It triggers a garbage collection to reduce fragmentation and get
 * a better estimate at the size of free memory. It is typically more accurate than the plain version
 * {@link #getSizeOfFreeHeapMemory()}.
 * 
 * @return An estimate of the size of the free heap memory, in bytes.
 */
public static long getSizeOfFreeHeapMemoryWithDefrag() {
   // trigger a garbage collection, to reduce fragmentation
   System.gc();
   
   return getSizeOfFreeHeapMemory();
}



   ..
  317  14972.571: [GC (Allocation Failure) 14972.572: [ParNew: 1870848K->236623K(1870848K), 0.0318714 secs] 2910945K->1276963K(3298304K), 0.0321537 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
  318  15024.592: [GC (Allocation Failure) 15024.592: [ParNew: 1840207K->267264K(1870848K), 0.0420305 secs] 2880547K->1309499K(3298304K), 0.0422980 secs] [Times: user=0.12 sys=0.00, real=0.04 secs] 
  319: 15049.334: [Full GC (System.gc()) 15049.334: [CMS: 1042235K->322292K(1427456K), 0.2932806 secs] 1552421K->322292K(3298304K), [Metaspace: 63049K->63049K(1105920K)], 0.2938379 secs] [Times: user=0.30 sys=0.00, real=0.29 secs] 
  320  15068.400: [GC (Allocation Failure) 15068.400: [ParNew: 1603548K->219691K(1870848K), 0.0244228 secs] 1925840K->541984K(3298304K), 0.0246696 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
  321  15157.833: [GC (Allocation Failure) 15157.833: [ParNew: 1823275K->169121K(1870848K), 0.0271608 secs] 2145568K->491414K(3298304K), 0.0274543 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
  ...
  676  30481.818: [GC (Allocation Failure) 30481.819: [ParNew: 1813938K->267264K(1870848K), 0.0423833 secs] 2864487K->1320335K(3298304K), 0.0425678 secs] [Times: user=0.12 sys=0.00, real=0.05 secs] 
  677  30557.470: [GC (Allocation Failure) 30557.470: [ParNew: 1870781K->267264K(1870848K), 0.0356143 secs] 2923853K->1330480K(3298304K), 0.0358636 secs] [Times: user=0.11 sys=0.00, real=0.04 secs] 
  678: 30615.513: [Full GC (System.gc()) 30615.513: [CMS: 1063216K->325191K(1427456K), 0.4150118 secs] 2772924K->325191K(3298304K), [Metaspace: 63756K->63756K(1107968K)], 0.4156102 secs] [Times: user=0.42 sys=0.00, real=0.41 secs] 
  679  30649.417: [GC (Allocation Failure) 30649.417: [ParNew: 1603486K->154121K(1870848K), 0.0236163 secs] 1928677K->479312K(3298304K), 0.0238171 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] 
  680  30734.471: [GC (Allocation Failure) 30734.471: [ParNew: 1757698K->164639K(1870848K), 0.0318273 secs] 2082889K->489830K(3298304K), 0.0320078 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 
  ...
  838  37620.283: [GC (Allocation Failure) 37620.283: [ParNew: 1819345K->267264K(1870848K), 0.0350667 secs] 2675979K->1123898K(3298304K), 0.0352966 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
  839  37696.182: [GC (Allocation Failure) 37696.182: [ParNew: 1870725K->267264K(1870848K), 0.0318628 secs] 2727360K->1124191K(3298304K), 0.0320820 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
  840: 37736.562: [Full GC (System.gc()) 37736.562: [CMS: 856927K->326386K(1427456K), 0.3860904 secs] 2420047K->326386K(3298304K), [Metaspace: 63914K->63914K(1107968K)], 0.3867480 secs] [Times: user=0.39 sys=0.00, real=0.38 secs] 
  841  37786.710: [GC (Allocation Failure) 37786.710: [ParNew: 1603475K->160119K(1870848K), 0.0211419 secs] 1929861K->486506K(3298304K), 0.0214152 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 
  842  37868.276: [GC (Allocation Failure) 37868.276: [ParNew: 1763703K->156520K(1870848K), 0.0274233 secs] 2090090K->482907K(3298304K), 0.0277311 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
  ...
  957  43291.423: [GC (Allocation Failure) 43291.424: [ParNew: 1870848K->267264K(1870848K), 0.0422492 secs] 2779218K->1208332K(3298304K), 0.0425675 secs] [Times: user=0.13 sys=0.00, real=0.04 secs] 
  958  43301.420: [GC (Allocation Failure) 43301.420: [ParNew: 1870766K->267264K(1870848K), 0.0514803 secs] 2811834K->1324858K(3298304K), 0.0517214 secs] [Times: user=0.16 sys=0.00, real=0.06 secs] 
  959: 43348.937: [Full GC (System.gc()) 43348.937: [CMS: 1057594K->326740K(1427456K), 0.3976217 secs] 1966751K->326740K(3298304K), [Metaspace: 63978K->63978K(1107968K)], 0.3982278 secs] [Times: user=0.40 sys=0.00, real=0.40 secs] 
  960  43388.807: [GC (Allocation Failure) 43388.807: [ParNew: 1603565K->215196K(1870848K), 0.0229975 secs] 1930306K->541937K(3298304K), 0.0232834 secs] [Times: user=0.07 sys=0.00, real=0.02 secs] 
  961  43473.412: [GC (Allocation Failure) 43473.413: [ParNew: 1818755K->159795K(1870848K), 0.0279802 secs] 2145495K->486536K(3298304K), 0.0282288 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 


PastedGraphic-1.png (17K) Download Attachment
Free forum by Nabble Edit this page