8 Replies Latest reply: Jan 15, 2010 5:44 AM by 800341 RSS

    FULL GC happens every 3 seconds

    843798
      Our application runs on Jboss-4.2.1.GA on Windows 2003 with 1.5.0_11 64-bit java
      java version "1.5.0_11"
      Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_11-b03)
      Java HotSpot(TM) 64-Bit Server VM (build 1.5.0_11-b03, mixed mode)
      NOTE: Our application uses Hibernate and Spring and Client application talks over RMI to our application.

      Some time back the performance of our application really dropped and we saw that GC was happening very frequently so we added the following parameters to control the frequent GC.

      This fixed the issue and every thing was working fine for a while and recently again the performance dropped really bad, this time we saw that a FULL GS is happening every 3 to 4 seconds.

      Here is a snapshot of the GC log
      4947.522: [Full GC 794153K->660654K(934144K), 3.2550211 secs]
      4951.129: [Full GC 795246K->662649K(934144K), 3.0934485 secs]
      4954.505: [Full GC 797241K->659436K(934144K), 4.0668057 secs]
      4958.838: [Full GC 794028K->659892K(934144K), 3.1585596 secs]
      4962.252: [Full GC 794484K->660532K(934144K), 3.2631397 secs]
      4965.800: [Full GC 795124K->660816K(934144K), 3.2850792 secs]
      4969.470: [Full GC 795408K->659146K(934144K), 3.8331614 secs]
      4973.547: [Full GC 793738K->659801K(934144K), 3.3380928 secs]
      4977.143: [Full GC 794393K->660286K(934144K), 3.7536836 secs]
      4981.454: [Full GC 794878K->660600K(934144K), 4.0316665 secs]
      4985.775: [Full GC 795192K->659256K(934144K), 4.3867282 secs]
      4990.466: [Full GC 793848K->659881K(934144K), 3.2915828 secs]
      4994.053: [Full GC 794473K->660415K(934144K), 3.3071425 secs]
      4997.596: [Full GC 795007K->661241K(934144K), 3.4741858 secs]
      We also see that the CPU utilization of the java process always spikes up to 100%

      Please help me resolve this issue.
        • 1. Re: FULL GC happens every 3 seconds
          843798
          - Try to reproduce the behaviour on your development machine.
          - Grab a profiler (I suggest JVisualVM for easy starting)
          - User profiler on environment where you reproduced the behaviour
          • 2. Re: FULL GC happens every 3 seconds
            796085
            The CPU is that high because it's busy doing GC. Cause and effect.

            Go back through your source code repository and identify likely changes from around the time when it "dropped really bad".

            The problem is simple. You are creating too much garbage for the JVM to handle.

            The solution is less simple. Increasing the memory might delay the problem for a bit, but at best you will just end up with longer gaps between GCs, each of which will take much longer. Really, you need to identify why you're creating so much garbage.
            • 3. Re: FULL GC happens every 3 seconds
              843798
              Thanks for your reply.

              There has been no change to the code in the recent couple of months the only change before the GC issue is that we added some additional data to the SeedData of our application which gets loaded to the memory during the server startup.

              This issue is not occurring in a 32bit Java.

              Thanks,
              Muthu
              • 4. Re: FULL GC happens every 3 seconds
                796085
                Adding more seed data that gets loaded during server startup sounds to me exactly like the sort of thing that's going to have impact on the application's memory profile! If the heap has more "permanent" data in it now, there is less space for your normal operational garbage which means it needs to be collected more frequently.

                Also notice that there is a bigger overhead for a 64 bit system in the sense that "pointers" in the JVMs internal data structures (e.g. the heap) will all be twice as big (unless you use the JVM compressed pointer option) so if you haven't increased your heap size to compensate then that will also be a source of stress on the heap. Anecdotally, I would start with a heap 50% bigger for a 64 bit app.

                But really, to understand what wrong, you're going to need to invest some of your own time and effort and attach one of the many heap analysis tools to the running system and see exactly how much memory there is free in a stable state and where the objects that are being garbage collected are being created, etc.
                • 5. Re: FULL GC happens every 3 seconds
                  843798
                  Thanks Danny. I am working on setting of the profiler and get more information. I will post the results soon.

                  Edited by: Muthukumaran_M on Jan 11, 2010 8:14 AM
                  • 6. Re: FULL GC happens every 3 seconds
                    843798
                    We try hard to reproduce this issue in almost 3 to 4 environments with the same data and similar load as our production, we couldn't reproduce the issues.

                    This happens only in production and we also noticed that we have a Xmx set to 3 GB, but the java process always sticks around 1.5 GB in the TaskManager even during the FULL GC is happening. What I don't understand is why full GC is happening if the Java process still has 1.5GB left.

                    The other thing this that we noticed is that the full GC is happening even during non-peek hours, but the frequency of the full GC happening is less when compared to peek hours, which is every 3-4 seconds.

                    Unfortunately we couldn't get any monitoring tool in place in production, I was able to the GC log.

                    I understand that I need to do more investigation, please help me with your expert advice.
                    • 7. Re: FULL GC happens every 3 seconds
                      843798
                      We try hard to reproduce this issue in almost 3 to 4 environments with the same data and similar load as our production, we couldn't reproduce the issues.

                      This happens only in production and we also noticed that we have a Xmx set to 3 GB, but the java process always sticks around 1.5 GB in the TaskManager even during the FULL GC is happening. What I don't understand is why full GC is happening if the Java process still has 1.5GB left.

                      The other thing this that we noticed is that the full GC is happening even during non-peek hours, but the frequency of the full GC happening is less when compared to peek hours, which is every 3-4 seconds.

                      Unfortunately we couldn't get any monitoring tool in place in production, I was able to the GC log.

                      I understand that I need to do more investigation, please help me with your expert advice.
                      • 8. Re: FULL GC happens every 3 seconds
                        800341
                        could you pls post the complete list of VM args