glassfish
  1. glassfish
  2. GLASSFISH-18705

Glassfish increasing CPU usage/ interrupting http-thread-pool after Broken pipe at sun / Glassfish 3.1.2 will die when compression is enabled.

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 3.1.2
    • Fix Version/s: 3.1.2
    • Component/s: grizzly-kernel
    • Labels:
      None
    • Environment:

      Glassfish 3.1.2
      Oracle JDK 1.6.0_32

      Description

      During reglar run in production, CPU usag starts growing after 12 to 24h hours after deploy. Cpu usage goes up based upon the cores in the system - here with 6 cores first usage of 1 core, then 2 etc. till all cores are used at 100% and system eventually dies. Growing is "level"based, meaning first 1 thread spins, then next etc.;

      Prior to the cpu-burn of a thread there is following log:

      Timestamp

      09.05.2012 16:21:59.726
      Log Level

      SEVERE
      Logger

      javax.enterprise.system.std.com.sun.enterprise.server.logging
      Name-Value Pairs

      _ThreadID=118;_ThreadName=Thread-2;
      Record Number

      328
      Message ID

      Complete Message

      java.io.IOException: Broken pipe at sun.nio.ch.FileDispatcher.write0(Native Method) at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:29) at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:69) at sun.nio.ch.IOUtil.write(IOUtil.java:40) at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:336) at com.sun.grizzly.util.OutputWriter.flushChannel(OutputWriter.java:108) at com.sun.grizzly.util.OutputWriter.flushChannel(OutputWriter.java:76) at com.sun.grizzly.http.SocketChannelOutputBuffer.flushChannel(SocketChannelOutputBuffer.java:417) at com.sun.grizzly.http.SocketChannelOutputBuffer.flushBuffer(SocketChannelOutputBuffer.java:489) at com.sun.grizzly.http.SocketChannelOutputBuffer.realWriteBytes(SocketChannelOutputBuffer.java:373) at com.sun.grizzly.tcp.http11.InternalOutputBuffer$OutputStreamOutputBuffer.doWrite(InternalOutputBuffer.java:894) at com.sun.grizzly.tcp.http11.filters.ChunkedOutputFilter.doWrite(ChunkedOutputFilter.java:167) at com.sun.grizzly.tcp.http11.filters.GzipOutputFilter$FakeOutputStream.write(GzipOutputFilter.java:223) at java.util.zip.GZIPOutputStream.finish(GZIPOutputStream.java:95) at java.util.zip.DeflaterOutputStream.close(DeflaterOutputStream.java:140) at com.sun.grizzly.tcp.http11.filters.GzipOutputFilter.recycle(GzipOutputFilter.java:186) at com.sun.grizzly.http.SocketChannelOutputBuffer.recycle(SocketChannelOutputBuffer.java:510) at com.sun.grizzly.http.ProcessorTask.finishResponse(ProcessorTask.java:838) at com.sun.grizzly.http.ProcessorTask.postResponse(ProcessorTask.java:771) at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:747) at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1045) at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:228) at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137) at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104) at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90) at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79) at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54) at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59) at com.sun.grizzly.ContextTask.run(ContextTask.java:71) at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532) at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513) at java.lang.Thread.run(Thread.java:662)

      soon after this, log starts getting polluted by:
      332 WARNING GRIZZLY0023: Interrupting idle Thread: http-thread-pool-8080(50).(details) com.sun.grizzly.config.GrizzlyServiceListener 09.05.2012 16:41:29.370 _ThreadID=122;_ThreadName=Thread-2;
      331 WARNING GRIZZLY0023: Interrupting idle Thread: http-thread-pool-8080(50).(details) com.sun.grizzly.config.GrizzlyServiceListener 09.05.2012 16:41:28.370 _ThreadID=122;_ThreadName=Thread-2;
      330 WARNING GRIZZLY0023: Interrupting idle Thread: http-thread-pool-8080(50).(details) com.sun.grizzly.config.GrizzlyServiceListener 09.05.2012 16:41:27.377 _ThreadID=122;_ThreadName=Thread-2;

      where each message is just:

      Timestamp

      09.05.2012 16:41:29.370
      Log Level

      WARNING
      Logger

      com.sun.grizzly.config.GrizzlyServiceListener
      Name-Value Pairs

      _ThreadID=122;_ThreadName=Thread-2;
      Record Number

      332
      Message ID

      Complete Message

      GRIZZLY0023: Interrupting idle Thread: http-thread-pool-8080(50).

      Problem is hitting more people:
      http://gregorbowie.wordpress.com/2012/05/03/java-glassfish-v3-high-cpu-and-memory-usage-locked-threads-death/
      http://home.java.net/forum/topic/glassfish/glassfish/glassfish-312-ubuntu-1004-lts-exceptions-serverlog-interrupting-idle-thread-http-thread-pool-808

      Beside this report I kindly ask for a workaround as current situation is I need to restart production-server every 20-24 hours;

      The behaviour is independent to the application that is deployed. Some days ago we had the exact same behaviour with the admin-thread-pool
      instead of the regular http-thread-pool;

      1. jstack.log.gz
        5 kB
        KBachl
      2. jvm.log.gz
        5 kB
        KBachl
      1. BusyWaitingOnGlassfish.png
        107 kB

        Activity

        Hide
        ftz2012 added a comment -

        @oleksiys: thanks, I looked at the thread dump and you are probably right. I will play with the idle thread time-out settings

        Show
        ftz2012 added a comment - @oleksiys: thanks, I looked at the thread dump and you are probably right. I will play with the idle thread time-out settings
        Hide
        fabiosf added a comment -

        Dear ftz2012, How are you?

        Did you find any solution to your problem? We switched to 3.1.2-2 by almost one year, but we still have a similar problem described by this thread.
        The patch has mitigated the original problem described by this thread. However, we still see in server.log many broken pipe exceptions and we have to restart our server at least once within 3 days (before the patch was twice a day). Maybe threads that don't get killed over time turns Glassfish to become unresponsive after a while.

        Have you any clue about this?

        Thanks

        Show
        fabiosf added a comment - Dear ftz2012, How are you? Did you find any solution to your problem? We switched to 3.1.2-2 by almost one year, but we still have a similar problem described by this thread. The patch has mitigated the original problem described by this thread. However, we still see in server.log many broken pipe exceptions and we have to restart our server at least once within 3 days (before the patch was twice a day). Maybe threads that don't get killed over time turns Glassfish to become unresponsive after a while. Have you any clue about this? Thanks
        Hide
        Exxenmann added a comment - - edited

        Hey everyone,

        "affected version: 3.1.2
        fixed version: 3.1.2"

        is pretty uninformative

        We are still having the Problem using:
        GlassFish Server Open Source Edition 3.1.2.2 (build 5)
        and
        java version "1.6.0_43"
        Java(TM) SE Runtime Environment (build 1.6.0_43-b01)
        Java HotSpot(TM) 64-Bit Server VM (build 20.14-b01, mixed mode)

        Which is the patched Open Source Glassfish Server Build? (and where to get it)?

        Thanks to all of you for your investigations!

        Show
        Exxenmann added a comment - - edited Hey everyone, "affected version: 3.1.2 fixed version: 3.1.2" is pretty uninformative We are still having the Problem using: GlassFish Server Open Source Edition 3.1.2.2 (build 5) and java version "1.6.0_43" Java(TM) SE Runtime Environment (build 1.6.0_43-b01) Java HotSpot(TM) 64-Bit Server VM (build 20.14-b01, mixed mode) Which is the patched Open Source Glassfish Server Build? (and where to get it)? Thanks to all of you for your investigations!
        Hide
        seanespn added a comment -

        I don't know if the GF team ever created a release with this fix in it.

        But you can download the patch jar attached to this ticket and apply yourself fairly easily - worked for us.

        Show
        seanespn added a comment - I don't know if the GF team ever created a release with this fix in it. But you can download the patch jar attached to this ticket and apply yourself fairly easily - worked for us.
        Hide
        Exxenmann added a comment -

        When I do:
        rm -rf generated
        rm -rf osgi-cache

        and then put them into glassfish3/modules

        I get this as on console and Glassfish doesnt start:

        Waiting for domain to start ..Error starting domain.
        The server exited prematurely with exit code 1.
        Before it died, it produced the following output:

        Launching GlassFish on Felix platform
        Completed shutdown of GlassFish runtime
        Exception in thread "main" java.lang.reflect.InvocationTargetException
        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 com.sun.enterprise.glassfish.bootstrap.GlassFishMain.main(GlassFishMain.java:97)
        at com.sun.enterprise.glassfish.bootstrap.ASMain.main(ASMain.java:55)
        Caused by: com.sun.enterprise.module.ResolveError: Failed to start Bundle Id [29] State [INSTALLED] [org.glassfish.main.core.kernel(Kernel Classes):3.1.2.1-SNAPSHOT]
        at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.start(OSGiModuleImpl.java:177)
        at org.jvnet.hk2.osgiadapter.OSGiModuleImpl$2$1$1.loadClass(OSGiModuleImpl.java:344)
        at com.sun.hk2.component.LazyInhabitant.loadClass(LazyInhabitant.java:124)
        at com.sun.hk2.component.LazyInhabitant.type(LazyInhabitant.java:99)
        at org.jvnet.hk2.component.Habitat$SelfListener.inhabitantIndexChanged(Habitat.java:1142)
        at org.jvnet.hk2.component.Habitat$3.inhabitantChanged(Habitat.java:601)
        at org.jvnet.hk2.component.Habitat$4.run(Habitat.java:642)
        at org.jvnet.hk2.component.SameThreadExecutor.execute(SameThreadExecutor.java:80)
        at org.jvnet.hk2.component.Habitat.doNotify(Habitat.java:632)
        at org.jvnet.hk2.component.Habitat.notify(Habitat.java:619)
        at org.jvnet.hk2.component.Habitat.notify(Habitat.java:605)
        at org.jvnet.hk2.component.Habitat.addIndex(Habitat.java:431)
        at org.jvnet.hk2.component.Habitat.addIndex(Habitat.java:424)
        at com.sun.hk2.component.InhabitantsParser.addIndex(InhabitantsParser.java:243)
        at com.sun.hk2.component.InhabitantsParser.add(InhabitantsParser.java:222)
        at com.sun.hk2.component.InhabitantsParser.parse(InhabitantsParser.java:174)
        at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.parseInhabitants(OSGiModuleImpl.java:376)
        at org.jvnet.hk2.osgiadapter.OSGiModulesRegistryImpl.parseInhabitants(OSGiModulesRegistryImpl.java:321)
        at com.sun.enterprise.module.common_impl.AbstractModulesRegistryImpl.createHabitat(AbstractModulesRegistryImpl.java:156)
        at com.sun.enterprise.module.bootstrap.Main.createHabitat(Main.java:459)
        at org.jvnet.hk2.osgiadapter.HK2Main.createHabitat(HK2Main.java:96)
        at com.sun.enterprise.glassfish.bootstrap.osgi.EmbeddedOSGiGlassFishRuntime.newGlassFish(EmbeddedOSGiGlassFishRuntime.java:89)
        at com.sun.enterprise.glassfish.bootstrap.GlassFishMain$Launcher.launch(GlassFishMain.java:113)
        ... 6 more
        Caused by: org.osgi.framework.BundleException: Unresolved constraint in bundle org.glassfish.main.core.kernel [29]: Unable to resolve 29.0: missing requirement [29.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.enterprise.admin.util)(version>=3.1.0)) [caused by: Unable to resolve 120.0: missing requirement [120.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.enterprise.config.serverbeans)(version>=3.1.0)) [caused by: Unable to resolve 38.0: missing requirement [38.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.grizzly.config.dom)(version>=1.9.0)) [caused by: Unable to resolve 130.0: missing requirement [130.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.grizzly)(version>=1.9.50)) [caused by: Unable to resolve 4.0: missing requirement [4.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.grizzly.tcp)(version>=1.9.50))]]]]
        at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:3826)
        at org.apache.felix.framework.Felix.startBundle(Felix.java:1868)
        at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:944)
        at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.start(OSGiModuleImpl.java:169)
        ... 28 more

        Command start-domain failed.

        Show
        Exxenmann added a comment - When I do: rm -rf generated rm -rf osgi-cache and then put them into glassfish3/modules I get this as on console and Glassfish doesnt start: Waiting for domain to start ..Error starting domain. The server exited prematurely with exit code 1. Before it died, it produced the following output: Launching GlassFish on Felix platform Completed shutdown of GlassFish runtime Exception in thread "main" java.lang.reflect.InvocationTargetException 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 com.sun.enterprise.glassfish.bootstrap.GlassFishMain.main(GlassFishMain.java:97) at com.sun.enterprise.glassfish.bootstrap.ASMain.main(ASMain.java:55) Caused by: com.sun.enterprise.module.ResolveError: Failed to start Bundle Id [29] State [INSTALLED] [org.glassfish.main.core.kernel(Kernel Classes):3.1.2.1-SNAPSHOT] at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.start(OSGiModuleImpl.java:177) at org.jvnet.hk2.osgiadapter.OSGiModuleImpl$2$1$1.loadClass(OSGiModuleImpl.java:344) at com.sun.hk2.component.LazyInhabitant.loadClass(LazyInhabitant.java:124) at com.sun.hk2.component.LazyInhabitant.type(LazyInhabitant.java:99) at org.jvnet.hk2.component.Habitat$SelfListener.inhabitantIndexChanged(Habitat.java:1142) at org.jvnet.hk2.component.Habitat$3.inhabitantChanged(Habitat.java:601) at org.jvnet.hk2.component.Habitat$4.run(Habitat.java:642) at org.jvnet.hk2.component.SameThreadExecutor.execute(SameThreadExecutor.java:80) at org.jvnet.hk2.component.Habitat.doNotify(Habitat.java:632) at org.jvnet.hk2.component.Habitat.notify(Habitat.java:619) at org.jvnet.hk2.component.Habitat.notify(Habitat.java:605) at org.jvnet.hk2.component.Habitat.addIndex(Habitat.java:431) at org.jvnet.hk2.component.Habitat.addIndex(Habitat.java:424) at com.sun.hk2.component.InhabitantsParser.addIndex(InhabitantsParser.java:243) at com.sun.hk2.component.InhabitantsParser.add(InhabitantsParser.java:222) at com.sun.hk2.component.InhabitantsParser.parse(InhabitantsParser.java:174) at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.parseInhabitants(OSGiModuleImpl.java:376) at org.jvnet.hk2.osgiadapter.OSGiModulesRegistryImpl.parseInhabitants(OSGiModulesRegistryImpl.java:321) at com.sun.enterprise.module.common_impl.AbstractModulesRegistryImpl.createHabitat(AbstractModulesRegistryImpl.java:156) at com.sun.enterprise.module.bootstrap.Main.createHabitat(Main.java:459) at org.jvnet.hk2.osgiadapter.HK2Main.createHabitat(HK2Main.java:96) at com.sun.enterprise.glassfish.bootstrap.osgi.EmbeddedOSGiGlassFishRuntime.newGlassFish(EmbeddedOSGiGlassFishRuntime.java:89) at com.sun.enterprise.glassfish.bootstrap.GlassFishMain$Launcher.launch(GlassFishMain.java:113) ... 6 more Caused by: org.osgi.framework.BundleException: Unresolved constraint in bundle org.glassfish.main.core.kernel [29] : Unable to resolve 29.0: missing requirement [29.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.enterprise.admin.util)(version>=3.1.0)) [caused by: Unable to resolve 120.0: missing requirement [120.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.enterprise.config.serverbeans)(version>=3.1.0)) [caused by: Unable to resolve 38.0: missing requirement [38.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.grizzly.config.dom)(version>=1.9.0)) [caused by: Unable to resolve 130.0: missing requirement [130.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.grizzly)(version>=1.9.50)) [caused by: Unable to resolve 4.0: missing requirement [4.0] osgi.wiring.package; (&(osgi.wiring.package=com.sun.grizzly.tcp)(version>=1.9.50))]]]] at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:3826) at org.apache.felix.framework.Felix.startBundle(Felix.java:1868) at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:944) at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.start(OSGiModuleImpl.java:169) ... 28 more Command start-domain failed.

          People

          • Assignee:
            Ryan Lubke
            Reporter:
            KBachl
          • Votes:
            10 Vote for this issue
            Watchers:
            11 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: