What is going on with java GC? PermGen space is filling up?

Question

I dont know what is going on with my java process. This process is an indexing process. It reads documents from a set of zip files, and adds them to the lucene index. The GC log shows that it is just running continuously Full GC.

4959.569: [Full GC 19960K->19960K(10617856K), 0.1648590 secs]
4959.764: [Full GC 19960K->19960K(10617856K), 0.1650240 secs]
4959.959: [Full GC 19960K->19960K(10617856K), 0.1649380 secs]
4960.154: [Full GC 19960K->19960K(10617856K), 0.1650000 secs]
4960.350: [Full GC 19960K->19960K(10617856K), 0.1648900 secs]

As far as I can interpret these lines, the size of objects before and after is around 19M, but why is it running it like all the time?

The thread dump looks like this:

........[Unloading class sun.reflect.GeneratedConstructorAccessor1]
[Unloading class sun.reflect.GeneratedConstructorAccessor2]
[Unloading class sun.reflect.GeneratedConstructorAccessor3]
2012-01-13 12:55:24
Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.4-b02 mixed mode):

"org.cxv.CXVIndexer.main()" prio=10 tid=0x00007f4540474000 nid=0x4b15 waiting on condition [0x00007f453f5ed000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.lucene.index.DocFieldProcessorPerThread.abort(DocFieldProcessorPerThread.java:72)
        at org.apache.lucene.index.DocumentsWriter.abort(DocumentsWriter.java:424)
        - locked <0x000000034ab44fb8> (a org.apache.lucene.index.DocumentsWriter)
        at org.apache.lucene.index.DocumentsWriter.flush(DocumentsWriter.java:659)
        - locked <0x000000034ab44fb8> (a org.apache.lucene.index.DocumentsWriter)
        at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3623)
        - locked <0x000000034aacf660> (a org.apache.lucene.index.IndexWriter)
        at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3588)
        at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1858)
        at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1822)
        at org.cxv.IndexCreator.close(IndexCreator.java:25)
        at org.cxv.CXVIndexer.doIndexing(CXVIndexer.java:41)
        at org.cxv.CXVIndexer.main(CXVIndexer.java:75)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:297)
        at java.lang.Thread.run(Thread.java:662)

"Low Memory Detector" daemon prio=10 tid=0x00007f4540003800 nid=0x4b0a runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x00007f4540001000 nid=0x4b09 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x000000004032d800 nid=0x4b08 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x000000004032b800 nid=0x4b07 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Surrogate Locker Thread (Concurrent GC)" daemon prio=10 tid=0x0000000040329800 nid=0x4b06 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x000000004030c800 nid=0x4b05 in Object.wait() [0x00007f453fdfc000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000034a6613a8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
        - locked <0x000000034a6613a8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x0000000040305000 nid=0x4b04 in Object.wait() [0x00007f453fefd000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000034a6627c0> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x000000034a6627c0> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x0000000040111000 nid=0x4af7 in Object.wait() [0x00007f4563c79000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000034aadf6f8> (a java.lang.Thread)
        at java.lang.Thread.join(Thread.java:1186)
        - locked <0x000000034aadf6f8> (a java.lang.Thread)
        at org.codehaus.mojo.exec.ExecJavaMojo.joinThread(ExecJavaMojo.java:415)
        at org.codehaus.mojo.exec.ExecJavaMojo.joinNonDaemonThreads(ExecJavaMojo.java:405)
        at org.codehaus.mojo.exec.ExecJavaMojo.execute(ExecJavaMojo.java:317)
        at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:107)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:209)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:84)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:59)
        at org.apache.maven.lifecycle.internal.LifecycleStarter.singleThreadedBuild(LifecycleStarter.java:183)
        at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:161)
        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:319)
        at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:156)
        at org.apache.maven.cli.MavenCli.execute(MavenCli.java:534)
        at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:196)
        at org.apache.maven.cli.MavenCli.main(MavenCli.java:141)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:290)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:230)
        at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:409)
        at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:352)

"VM Thread" prio=10 tid=0x00000000402fe000 nid=0x4b03 runnable 

"Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x0000000040120000 nid=0x4af8 runnable 

"Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x0000000040122000 nid=0x4af9 runnable 

"Gang worker#2 (Parallel GC Threads)" prio=10 tid=0x0000000040123800 nid=0x4afa runnable 

"Gang worker#3 (Parallel GC Threads)" prio=10 tid=0x0000000040125800 nid=0x4afb runnable 

"Gang worker#4 (Parallel GC Threads)" prio=10 tid=0x0000000040127800 nid=0x4afc runnable 

"Gang worker#5 (Parallel GC Threads)" prio=10 tid=0x0000000040129000 nid=0x4afd runnable 

"Gang worker#6 (Parallel GC Threads)" prio=10 tid=0x000000004012b000 nid=0x4afe runnable 

"Gang worker#7 (Parallel GC Threads)" prio=10 tid=0x000000004012d000 nid=0x4aff runnable 

"Concurrent Mark-Sweep GC Thread" prio=10 tid=0x0000000040220800 nid=0x4b02 runnable 
"Gang worker#0 (Parallel CMS Threads)" prio=10 tid=0x000000004021c800 nid=0x4b00 runnable 

"Gang worker#1 (Parallel CMS Threads)" prio=10 tid=0x000000004021e800 nid=0x4b01 runnable 

"VM Periodic Task Thread" prio=10 tid=0x000000004033a000 nid=0x4b0b waiting on condition 

JNI global references: 1154

Heap
 par new generation   total 153344K, used 0K [0x0000000340000000, 0x000000034a660000, 0x000000034a660000)
  eden space 136320K,   0% used [0x0000000340000000, 0x0000000340000000, 0x0000000348520000)
  from space 17024K,   0% used [0x00000003495c0000, 0x00000003495c0000, 0x000000034a660000)
  to   space 17024K,   0% used [0x0000000348520000, 0x0000000348520000, 0x00000003495c0000)
 concurrent mark-sweep generation total 10464512K, used 19960K [0x000000034a660000, 0x00000005c91a0000, 0x0000000780000000)
 concurrent-mark-sweep perm gen total 2097152K, used 2097151K [0x0000000780000000, 0x0000000800000000, 0x0000000800000000)

From the thread dump, it looks like the 2G perm gen is filling up. Does it really need that much space for perm gen?

Your PermGen is completely full up. It means that there is creation of Class objects it can't handle because of a lack of space. First try : raise your PermGen level with `-XX:MaxPermSize=3G` and watch it rising with VisualVM. Watch the number of loaded classes, and see if it reaches a certain level — Grooveek, Jan 13 '12 at 13:48
Can you give us a clue as to what your 'java process' actually is please? Is it a server, a desktop application, what? — Matthew Farwell, Jan 13 '12 at 13:49
@MatthewFarwell yes, it is a server. It is an indexing process. It reads documents from a set of zip files, and adds them to the lucene index. — user3111525, Jan 13 '12 at 13:51

score 7 · Accepted Answer · edited Nov 21 '13 at 23:56

7

This will happen if your memory is fragmented, or there is nothing to clean up. It happens often when you are close to the maximum memory size.

I have never heard of anyone needing a 2 G per gen size. Are you sure its not the young and tenured spaces you need to be looking at?

BTW: intern()ed String are placed in the main heap spaces in Java 7. Before Java 7, they used to be placed into the perm gen space, which makes it a bad idea to make too much data interned()

edited Nov 21 '13 at 23:56

Saurin

39
3

answered Jan 13 '12 at 14:00

Peter Lawrey

525,659
79
751
1,130

Try using a collector that compacts the old gen (e.g. ParallelOldGC) and see if you run into the same problem with perm space. – Paul Medcraft Jan 14 '12 at 11:47

score 1 · Answer 2 · answered Jul 26 '12 at 15:15

In my case, PermGen was filling up and provoking full GCs because my use of JAXB was dynamically creating classes. To debug this, I saw that monitoring PermGen via JMX console corresponded directly to the full GC (using -verbose:gc). Further, using -verbose:class showed me that it was my JAXB usage.

score 1 · Answer 3 · answered Jan 13 '12 at 13:57

1

The permanent generation (perm gen) in JVMs with generational garbage collection contain "permanent" data which does not get collected. This memory segment consists mainly of class definitions loaded by the system classloader, so if your program loads lots of classes (e.g. has many large dependencies) then this space will fill up. Note that classes (typically) will not get unloaded unless you are using a custom classloader (i.e. other than the default, system classloader).

See this guide for information about sizing the perm gen space.

answered Jan 13 '12 at 13:57

maerics

151,642
46
269
291

so, you also think there is a problem with perm gen? – user3111525 Jan 13 '12 at 13:59
@frankmoss: not necessarily a problem, no; it just might be that you are loading a "large" number of dependent classes (or other data stored in the perm gen) and must increase the perm gen heap space accordingly. – maerics Jan 13 '12 at 14:01

score 0 · Answer 4 · answered Jan 13 '12 at 13:55

0

Without looking at your application in detail, it's hard to say. However, the usual culprits for using permgen space are interned strings (search for .intern() in your code base) and dynamic code generation.

answered Jan 13 '12 at 13:55

Simon Nickerson

42,159
20
102
127

What is going on with java GC? PermGen space is filling up?

4 Answers4

Linked