Skip to main content

Extremely slow startup - JVMStatsProviderBootstrap the culprit?

Please note these java.net forums are being decommissioned and use the new and improved forums at https://community.oracle.com/community/java.
2 replies [Last post]
pdoubleya
Offline
Joined: 2004-02-09

Hi
This is with Glassfish 3.1.
We are trying to track down an issue where our Glassfish startup has become occasionally (but not consistently) painfully slow along with very high CPU (over 100% of 1 CPU) usage for the Glassfish process. Slow here means many minutes for loading a particular webapp, as opposed to 1-2 minutes.
Checking GC with VisualVM showed no problems - enough heap, infrequent collections - and the VE itself was not swapping.
On running several stack trace dumps back to back I found that the main thread was spending a lot of time in this section of code (across several stack trace dumps) - In particular, I was seeing the thread remain in the string pattern matching section started by org.glassfish.flashlight.datatree.impl.AbstractTreeNode.getNodesInternal(AbstractTreeNode.java:360).

"main" prio=10 tid=0x000000004efe1000 nid=0x163e runnable [0x000000004092e000]

   java.lang.Thread.State: RUNNABLE

        at java.lang.String.length(String.java:651)

        at java.util.regex.Matcher.getTextLength(Matcher.java:1140)

        at java.util.regex.Matcher.reset(Matcher.java:291)

        at java.util.regex.Matcher.<init>(Matcher.java:211)

        at java.util.regex.Pattern.matcher(Pattern.java:888)

        at org.glassfish.flashlight.datatree.impl.AbstractTreeNode.getNodesInternal(AbstractTreeNode.java:360)

        at org.glassfish.flashlight.datatree.impl.AbstractTreeNode.getNodes(AbstractTreeNode.java:331)

        at org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.resetChildNodeStatistics(StatsProviderManagerDelegateImpl.java:550)

        at org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.resetStatistics(StatsProviderManagerDelegateImpl.java:539)

        at org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.enableStatsProvider(StatsProviderManagerDelegateImpl.java:389)

        at org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.tryToRegister(StatsProviderManagerDelegateImpl.java:191)

        at org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.register(StatsProviderManagerDelegateImpl.java:157)

        at org.glassfish.external.probe.provider.StatsProviderManager.registerStatsProvider(StatsProviderManager.java:91)

        at org.glassfish.external.probe.provider.StatsProviderManager.register(StatsProviderManager.java:82)

        at org.glassfish.external.probe.provider.StatsProviderManager.register(StatsProviderManager.java:72)

        at org.glassfish.admin.monitor.jvm.JVMStatsProviderBootstrap.postConstruct(JVMStatsProviderBootstrap.java:92)

        at com.sun.hk2.component.AbstractCreatorImpl.inject(AbstractCreatorImpl.java:131)

        at com.sun.hk2.component.ConstructorCreator$1.run(ConstructorCreator.java:86)

        at java.security.AccessController.doPrivileged(Native Method)

        at com.sun.hk2.component.ConstructorCreator.initialize(ConstructorCreator.java:83)

        at com.sun.hk2.component.AbstractCreatorImpl.get(AbstractCreatorImpl.java:82)

        at com.sun.hk2.component.SingletonInhabitant.get(SingletonInhabitant.java:67)

        - locked <0x00002aab01bcf370> (a com.sun.hk2.component.SingletonInhabitant)

        at com.sun.hk2.component.EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)

        at com.sun.hk2.component.AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:76)

        at com.sun.enterprise.v3.server.AppServerStartup.run(AppServerStartup.java:326)

        at com.sun.enterprise.v3.server.AppServerStartup.start(AppServerStartup.java:135)

        - locked <0x00002aaac20b3228> (a com.sun.enterprise.v3.server.AppServerStartup)

        at com.sun.enterprise.glassfish.bootstrap.GlassFishImpl.start(GlassFishImpl.java:79)

        - locked <0x00002aaac20b3200> (a com.sun.enterprise.glassfish.bootstrap.GlassFishImpl)

        at com.sun.enterprise.glassfish.bootstrap.GlassFishMain$Launcher.launch(GlassFishMain.java:117)

        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)

I don't know if this is a red herring, but nothing else in the stack traces stood out as much as this did.
Any tips?
Thanks
Patrick

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
bnevins
Offline
Joined: 2005-03-28

I filed a high-priority bug:

http://java.net/jira/browse/GLASSFISH-16478

On 4/27/2011 2:44 AM, forums@java.net wrote:
> Hi
>
> This is with Glassfish 3.1.
>
> We are trying to track down an issue where our Glassfish startup has
> become
> occasionally (but not consistently) painfully slow along with very
> high CPU
> (over 100% of 1 CPU) usage for the Glassfish process. Slow here means
> many
> minutes for loading a particular webapp, as opposed to 1-2 minutes.
>
> Checking GC with VisualVM showed no problems - enough heap, infrequent
> collections - and the VE itself was not swapping.
>
> On running several stack trace dumps back to back I found that the main
> thread was spending a lot of time in this section of code (across several
> stack trace dumps) - In particular, I was seeing the thread remain in the
> string pattern matching section started by
> org.glassfish.flashlight.datatree.impl.AbstractTreeNode.getNodesInternal(AbstractTreeNode.java:360).
>
>
> "main" prio=10 tid=0x000000004efe1000 nid=0x163e runnable
> [0x000000004092e000] java.lang.Thread.State: RUNNABLE at
> java.lang.String.length(String.java:651) at
> java.util.regex.Matcher.getTextLength(Matcher.java:1140) at
> java.util.regex.Matcher.reset(Matcher.java:291) at
> java.util.regex.Matcher.(Matcher.java:211) at
> java.util.regex.Pattern.matcher(Pattern.java:888) at
> org.glassfish.flashlight.datatree.impl.AbstractTreeNode.getNodesInternal(AbstractTreeNode.java:360)
>
> at
> org.glassfish.flashlight.datatree.impl.AbstractTreeNode.getNodes(AbstractTreeNode.java:331)
>
> at
> org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.resetChildNodeStatistics(StatsProviderManagerDelegateImpl.java:550)
>
> at
> org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.resetStatistics(StatsProviderManagerDelegateImpl.java:539)
>
> at
> org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.enableStatsProvider(StatsProviderManagerDelegateImpl.java:389)
>
> at
> org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.tryToRegister(StatsProviderManagerDelegateImpl.java:191)
>
> at
> org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.register(StatsProviderManagerDelegateImpl.java:157)
>
> at
> org.glassfish.external.probe.provider.StatsProviderManager.registerStatsProvider(StatsProviderManager.java:91)
>
> at
> org.glassfish.external.probe.provider.StatsProviderManager.register(StatsProviderManager.java:82)
>
> at
> org.glassfish.external.probe.provider.StatsProviderManager.register(StatsProviderManager.java:72)
>
> at
> org.glassfish.admin.monitor.jvm.JVMStatsProviderBootstrap.postConstruct(JVMStatsProviderBootstrap.java:92)
>
> at
> com.sun.hk2.component.AbstractCreatorImpl.inject(AbstractCreatorImpl.java:131)
>
> at
> com.sun.hk2.component.ConstructorCreator$1.run(ConstructorCreator.java:86)
> at java.security.AccessController.doPrivileged(Native Method) at
> com.sun.hk2.component.ConstructorCreator.initialize(ConstructorCreator.java:83)
>
> at
> com.sun.hk2.component.AbstractCreatorImpl.get(AbstractCreatorImpl.java:82)
> at
> com.sun.hk2.component.SingletonInhabitant.get(SingletonInhabitant.java:67)
> - locked <0x00002aab01bcf370> (a
> com.sun.hk2.component.SingletonInhabitant)
> at
> com.sun.hk2.component.EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)
>
> at
> com.sun.hk2.component.AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:76)
>
> at
> com.sun.enterprise.v3.server.AppServerStartup.run(AppServerStartup.java:326)
>
> at
> com.sun.enterprise.v3.server.AppServerStartup.start(AppServerStartup.java:135)
>
> - locked <0x00002aaac20b3228> (a
> com.sun.enterprise.v3.server.AppServerStartup) at
> com.sun.enterprise.glassfish.bootstrap.GlassFishImpl.start(GlassFishImpl.java:79)
>
> - locked <0x00002aaac20b3200> (a
> com.sun.enterprise.glassfish.bootstrap.GlassFishImpl) at
> com.sun.enterprise.glassfish.bootstrap.GlassFishMain$Launcher.launch(GlassFishMain.java:117)
>
> 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)
> I don't know if this is a red herring, but nothing else in the stack
> traces
> stood out as much as this did.
>
> Any tips?
>
> Thanks
>
> Patrick
>
>
>
>
> --
>
> [Message sent by forum member 'pdoubleya']
>
> View Post: http://forums.java.net/node/795868
>
>

--
Oracle
Byron Nevins | Principal MTS
Phone: +1 6503958992

Green Oracle Oracle is committed to
developing practices and products that help protect the environment

924 Guest
Offline
Joined: 2011-04-27

Hi

This is with Glassfish 3.1.

We are trying to track down an issue where our Glassfish startup has become
occasionally (but not consistently) painfully slow along with very high CPU
(over 100% of 1 CPU) usage for the Glassfish process. Slow here means  many
minutes for loading a particular webapp, as opposed to 1-2 minutes.

Checking GC with VisualVM showed no problems - enough heap, infrequent
collections - and the VE itself was not swapping.

On running several stack trace dumps back to back I found that the main
thread was spending a lot of time in this section of code (across several
stack trace dumps) - In particular, I was seeing the thread remain in the
string pattern matching section started by
org.glassfish.flashlight.datatree.impl.AbstractTreeNode.getNodesInternal(AbstractTreeNode.java:360).

"main" prio=10 tid=0x000000004efe1000 nid=0x163e runnable
[0x000000004092e000] java.lang.Thread.State: RUNNABLE at
java.lang.String.length(String.java:651) at
java.util.regex.Matcher.getTextLength(Matcher.java:1140) at
java.util.regex.Matcher.reset(Matcher.java:291) at
java.util.regex.Matcher.(Matcher.java:211) at
java.util.regex.Pattern.matcher(Pattern.java:888) at
org.glassfish.flashlight.datatree.impl.AbstractTreeNode.getNodesInternal(AbstractTreeNode.java:360)
at
org.glassfish.flashlight.datatree.impl.AbstractTreeNode.getNodes(AbstractTreeNode.java:331)
at
org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.resetChildNodeStatistics(StatsProviderManagerDelegateImpl.java:550)
at
org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.resetStatistics(StatsProviderManagerDelegateImpl.java:539)
at
org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.enableStatsProvider(StatsProviderManagerDelegateImpl.java:389)
at
org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.tryToRegister(StatsProviderManagerDelegateImpl.java:191)
at
org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.register(StatsProviderManagerDelegateImpl.java:157)
at
org.glassfish.external.probe.provider.StatsProviderManager.registerStatsProvider(StatsProviderManager.java:91)
at
org.glassfish.external.probe.provider.StatsProviderManager.register(StatsProviderManager.java:82)
at
org.glassfish.external.probe.provider.StatsProviderManager.register(StatsProviderManager.java:72)
at
org.glassfish.admin.monitor.jvm.JVMStatsProviderBootstrap.postConstruct(JVMStatsProviderBootstrap.java:92)
at
com.sun.hk2.component.AbstractCreatorImpl.inject(AbstractCreatorImpl.java:131)
at com.sun.hk2.component.ConstructorCreator$1.run(ConstructorCreator.java:86)
at java.security.AccessController.doPrivileged(Native Method) at
com.sun.hk2.component.ConstructorCreator.initialize(ConstructorCreator.java:83)
at com.sun.hk2.component.AbstractCreatorImpl.get(AbstractCreatorImpl.java:82)
at com.sun.hk2.component.SingletonInhabitant.get(SingletonInhabitant.java:67)
- locked <0x00002aab01bcf370> (a com.sun.hk2.component.SingletonInhabitant)
at
com.sun.hk2.component.EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)
at
com.sun.hk2.component.AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:76)
at
com.sun.enterprise.v3.server.AppServerStartup.run(AppServerStartup.java:326)
at
com.sun.enterprise.v3.server.AppServerStartup.start(AppServerStartup.java:135)
- locked <0x00002aaac20b3228> (a
com.sun.enterprise.v3.server.AppServerStartup) at
com.sun.enterprise.glassfish.bootstrap.GlassFishImpl.start(GlassFishImpl.java:79)
- locked <0x00002aaac20b3200> (a
com.sun.enterprise.glassfish.bootstrap.GlassFishImpl) at
com.sun.enterprise.glassfish.bootstrap.GlassFishMain$Launcher.launch(GlassFishMain.java:117)
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)
I don't know if this is a red herring, but nothing else in the stack traces
stood out as much as this did.

Any tips?

Thanks

Patrick

 

--

[Message sent by forum member 'pdoubleya']

View Post: http://forums.java.net/node/795868