glassfish
  1. glassfish
  2. GLASSFISH-19893

performance hotspot in org.glassfish.jersey.server.ApplicationHandler.initialize

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 4.0_b79
    • Fix Version/s: 4.0_b87_RC3
    • Component/s: jax-rs
    • Labels:
      None

      Description

      During a profiling run, the Jersey service startup in GF takes 8763 ms, and 6165 ms of that is in one method:

      18.1% - 6,165 ms - 1 inv. org.glassfish.jersey.server.ApplicationHandler.initialize

      Is it expected that this method would take quite a bit a time?

      None of the methods that are called by that method take nearly that much time:

      • validate takes 1491ms
      • 37 invocations of org.glassfish.jersey.server.model.Resource.from take 1302 ms

      Nothing else takes more than 1000 ms.

      Note: the times are distorted because of the profiling so just compare the relative times. The 18% is the total CPU time of the process.

        Activity

        Hide
        Tom Mueller added a comment -

        This issue has been created as JERSEY-1795.

        This issue will be kept open until there is a resolution in GlassFish for JERSEY-1795.

        Show
        Tom Mueller added a comment - This issue has been created as JERSEY-1795 . This issue will be kept open until there is a resolution in GlassFish for JERSEY-1795 .
        Hide
        Marek Potociar added a comment -

        Targeting for a fix after 4.0 release.

        Show
        Marek Potociar added a comment - Targeting for a fix after 4.0 release.
        Hide
        Tom Mueller added a comment -

        Marking the fix for 4.0 until we determine that a fix in this area is not necessary to meeting the developer scenario benchmark requirement for 4.0.

        Show
        Tom Mueller added a comment - Marking the fix for 4.0 until we determine that a fix in this area is not necessary to meeting the developer scenario benchmark requirement for 4.0.
        Hide
        Hong Zhang added a comment -

        (Update the issue with the information from email exchanges on loading weld-integration module)

        This initialization has triggered the loading of the weld-integration jar (stack trace below). We need to look into whether we can avoid loading CDI related things in the initialization.

        Module [44] started org.glassfish.main.web.weld-integration

        -----------------------------------
        Inhabitants / stack combination
        -----------------------------------

        ---------------------------
        Complete thread stack Trace
        ---------------------------
        java.lang.Thread.getStackTrace(Thread.java:1567)
        com.sun.enterprise.module.common_impl.TracingUtilities.traceState(TracingUtilities.java:96)
        com.sun.enterprise.module.common_impl.TracingUtilities.traceStarted(TracingUtilities.java:85)
        org.jvnet.hk2.osgiadapter.HK2Main$1.bundleChanged(HK2Main.java:195)
        org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:868)
        org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:789)
        org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:514)
        org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4403)
        org.apache.felix.framework.Felix.startBundle(Felix.java:2092)
        org.apache.felix.framework.BundleImpl.start(BundleImpl.java:955)
        org.jvnet.hk2.osgiadapter.OSGiModuleImpl.start(OSGiModuleImpl.java:210)
        org.jvnet.hk2.osgiadapter.OsgiPopulatorPostProcessor$1.loadClass(OsgiPopulatorPostProcessor.java:77)
        org.jvnet.hk2.internal.ServiceLocatorImpl.loadClass(ServiceLocatorImpl.java:1639)
        org.jvnet.hk2.internal.ServiceLocatorImpl.reifyDescriptor(ServiceLocatorImpl.java:362)
        org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2135)
        org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:93)
        com.sun.enterprise.naming.impl.NamedNamingObjectManager.tryNamedProxies(NamedNamingObjectManager.java:126)
        com.sun.enterprise.naming.impl.JavaURLContext.lookup(JavaURLContext.java:166)
        com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:471)
        com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:438)
        javax.naming.InitialContext.lookup(InitialContext.java:411)
        javax.naming.InitialContext.lookup(InitialContext.java:411)
        org.glassfish.jersey.gf.cdi.CdiComponentProvider.beanManagerFromJndi(CdiComponentProvider.java:222)
        org.glassfish.jersey.gf.cdi.CdiComponentProvider.initialize(CdiComponentProvider.java:133)
        org.glassfish.jersey.server.ApplicationHandler.initialize(ApplicationHandler.java:353)
        org.glassfish.jersey.server.ApplicationHandler.access$500(ApplicationHandler.java:147)
        org.glassfish.jersey.server.ApplicationHandler$3.run(ApplicationHandler.java:270)
        org.glassfish.jersey.internal.Errors$2.call(Errors.java:249)
        org.glassfish.jersey.internal.Errors$2.call(Errors.java:246)
        org.glassfish.jersey.internal.Errors.process(Errors.java:275)
        org.glassfish.jersey.internal.Errors.process(Errors.java:257)
        org.glassfish.jersey.internal.Errors.processWithException(Errors.java:246)
        org.glassfish.jersey.server.ApplicationHandler.<init>(ApplicationHandler.java:267)
        org.glassfish.jersey.server.ContainerFactory.createContainer(ContainerFactory.java:79)
        org.glassfish.admin.rest.adapter.JerseyContainerCommandService.getJerseyContainer(JerseyContainerCommandService.java:157)
        org.glassfish.admin.rest.adapter.JerseyContainerCommandService.exposeContext(JerseyContainerCommandService.java:150)
        org.glassfish.admin.rest.adapter.JerseyContainerCommandService.access$000(JerseyContainerCommandService.java:84)
        org.glassfish.admin.rest.adapter.JerseyContainerCommandService$1.call(JerseyContainerCommandService.java:100)
        org.glassfish.admin.rest.adapter.JerseyContainerCommandService$1.call(JerseyContainerCommandService.java:97)
        java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
        java.util.concurrent.FutureTask.run(FutureTask.java:166)
        java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        java.lang.Thread.run(Thread.java:722)

        Show
        Hong Zhang added a comment - (Update the issue with the information from email exchanges on loading weld-integration module) This initialization has triggered the loading of the weld-integration jar (stack trace below). We need to look into whether we can avoid loading CDI related things in the initialization. Module [44] started org.glassfish.main.web.weld-integration ----------------------------------- Inhabitants / stack combination ----------------------------------- --------------------------- Complete thread stack Trace --------------------------- java.lang.Thread.getStackTrace(Thread.java:1567) com.sun.enterprise.module.common_impl.TracingUtilities.traceState(TracingUtilities.java:96) com.sun.enterprise.module.common_impl.TracingUtilities.traceStarted(TracingUtilities.java:85) org.jvnet.hk2.osgiadapter.HK2Main$1.bundleChanged(HK2Main.java:195) org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:868) org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:789) org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:514) org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4403) org.apache.felix.framework.Felix.startBundle(Felix.java:2092) org.apache.felix.framework.BundleImpl.start(BundleImpl.java:955) org.jvnet.hk2.osgiadapter.OSGiModuleImpl.start(OSGiModuleImpl.java:210) org.jvnet.hk2.osgiadapter.OsgiPopulatorPostProcessor$1.loadClass(OsgiPopulatorPostProcessor.java:77) org.jvnet.hk2.internal.ServiceLocatorImpl.loadClass(ServiceLocatorImpl.java:1639) org.jvnet.hk2.internal.ServiceLocatorImpl.reifyDescriptor(ServiceLocatorImpl.java:362) org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2135) org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:93) com.sun.enterprise.naming.impl.NamedNamingObjectManager.tryNamedProxies(NamedNamingObjectManager.java:126) com.sun.enterprise.naming.impl.JavaURLContext.lookup(JavaURLContext.java:166) com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:471) com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:438) javax.naming.InitialContext.lookup(InitialContext.java:411) javax.naming.InitialContext.lookup(InitialContext.java:411) org.glassfish.jersey.gf.cdi.CdiComponentProvider.beanManagerFromJndi(CdiComponentProvider.java:222) org.glassfish.jersey.gf.cdi.CdiComponentProvider.initialize(CdiComponentProvider.java:133) org.glassfish.jersey.server.ApplicationHandler.initialize(ApplicationHandler.java:353) org.glassfish.jersey.server.ApplicationHandler.access$500(ApplicationHandler.java:147) org.glassfish.jersey.server.ApplicationHandler$3.run(ApplicationHandler.java:270) org.glassfish.jersey.internal.Errors$2.call(Errors.java:249) org.glassfish.jersey.internal.Errors$2.call(Errors.java:246) org.glassfish.jersey.internal.Errors.process(Errors.java:275) org.glassfish.jersey.internal.Errors.process(Errors.java:257) org.glassfish.jersey.internal.Errors.processWithException(Errors.java:246) org.glassfish.jersey.server.ApplicationHandler.<init>(ApplicationHandler.java:267) org.glassfish.jersey.server.ContainerFactory.createContainer(ContainerFactory.java:79) org.glassfish.admin.rest.adapter.JerseyContainerCommandService.getJerseyContainer(JerseyContainerCommandService.java:157) org.glassfish.admin.rest.adapter.JerseyContainerCommandService.exposeContext(JerseyContainerCommandService.java:150) org.glassfish.admin.rest.adapter.JerseyContainerCommandService.access$000(JerseyContainerCommandService.java:84) org.glassfish.admin.rest.adapter.JerseyContainerCommandService$1.call(JerseyContainerCommandService.java:100) org.glassfish.admin.rest.adapter.JerseyContainerCommandService$1.call(JerseyContainerCommandService.java:97) java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) java.util.concurrent.FutureTask.run(FutureTask.java:166) java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) java.lang.Thread.run(Thread.java:722)
        Hide
        Tom Mueller added a comment -

        Reassigning to Martin since he is looking into this.

        Show
        Tom Mueller added a comment - Reassigning to Martin since he is looking into this.
        Hide
        martin.mares added a comment -

        FROM MAIL CONVERSATION:

        I made several different measurements:
        A) visualvm CPU profiling: Resource.from average CPU duration is 1.5 ms and 18 resp. 37 iterations
        B) Overal Jersey initialisation on my environment with lazy loading (loads for first command call) takes 850 - 950 ms => 30ms is under standard deviation and is hardly seen able.
        C) I add logging into Resource.from method of Jersey. In most cases it takes 0-2ms. Only one exception is main resource it takes 55 ms on my environment and 77 ms on my Oracle virtual development environment.
        D) I start official performance test on GF with reduced JAX-RS resources (from 37 to 18) and without. There is no difference.

        Result. I can not reproduce issue with Resource.from() and I will stop
        work on this point.

        Show
        martin.mares added a comment - FROM MAIL CONVERSATION: I made several different measurements: A) visualvm CPU profiling: Resource.from average CPU duration is 1.5 ms and 18 resp. 37 iterations B) Overal Jersey initialisation on my environment with lazy loading (loads for first command call) takes 850 - 950 ms => 30ms is under standard deviation and is hardly seen able. C) I add logging into Resource.from method of Jersey. In most cases it takes 0-2ms. Only one exception is main resource it takes 55 ms on my environment and 77 ms on my Oracle virtual development environment. D) I start official performance test on GF with reduced JAX-RS resources (from 37 to 18) and without. There is no difference. Result. I can not reproduce issue with Resource.from() and I will stop work on this point.
        Hide
        martin.mares added a comment -

        TOM:
        How much did the validation time go down when the number of resources was reduced?

        MARTIN:
        Validation, more exactly: ApplicationHandler.validate() method duration is aprox. 125ms for original resource set and 105ms for reduced resource set. While whole init time for Jersey oscillates between 900-960ms on my environment.

        Show
        martin.mares added a comment - TOM: How much did the validation time go down when the number of resources was reduced? MARTIN: Validation, more exactly: ApplicationHandler.validate() method duration is aprox. 125ms for original resource set and 105ms for reduced resource set. While whole init time for Jersey oscillates between 900-960ms on my environment.
        Hide
        martin.mares added a comment -

        TOM:
        What is the rough break down of the 900 ms the way you see it?

        Show
        martin.mares added a comment - TOM: What is the rough break down of the 900 ms the way you see it?
        Hide
        Tom Mueller added a comment -

        Martin, please continue to work on evaluating what takes more than 900 ms to initialize. This is huge relative to the rest of the server initialization time. I also suspect that this initialization time is effecting the overall devx_web test run.

        Here's a simple test that would seem to demonstrate this. I ran two versions of a script. The first is like the devx_web test:

        asadmin start-domain
        time asadmin deploy helloworld.war
        asadmin undeploy helloworld
        asadmin stop-domain

        The second is similar, except it adds a sleep 3 after the start-domain:

        asadmin start-domain
        sleep 3
        time asadmin deploy helloworld.war
        asadmin undeploy helloworld
        asadmin stop-domain

        In the second test, the server is given time to finish the Jersey/command framework initialization before the deploy starts. If this initialization is not effecting the benchmark time, then this test should show deploy times that are the same in both versions. Here are the results:

        no sleep: 3.34 sec (average of 10 runs)
        with sleep: 2.77 sec (average of 10 runs)

        This shows that the initial deployment of an application could be over a half a second faster if the server was really ready to process a command after the domain is started.

        Show
        Tom Mueller added a comment - Martin, please continue to work on evaluating what takes more than 900 ms to initialize. This is huge relative to the rest of the server initialization time. I also suspect that this initialization time is effecting the overall devx_web test run. Here's a simple test that would seem to demonstrate this. I ran two versions of a script. The first is like the devx_web test: asadmin start-domain time asadmin deploy helloworld.war asadmin undeploy helloworld asadmin stop-domain The second is similar, except it adds a sleep 3 after the start-domain: asadmin start-domain sleep 3 time asadmin deploy helloworld.war asadmin undeploy helloworld asadmin stop-domain In the second test, the server is given time to finish the Jersey/command framework initialization before the deploy starts. If this initialization is not effecting the benchmark time, then this test should show deploy times that are the same in both versions. Here are the results: no sleep: 3.34 sec (average of 10 runs) with sleep: 2.77 sec (average of 10 runs) This shows that the initial deployment of an application could be over a half a second faster if the server was really ready to process a command after the domain is started.
        Hide
        martin.mares added a comment -

        Tom:
        Today I was back in this task. Trying determine what we can do and what initialization is consist of. I found following possibilities - topics for future investigation (overal init is 900ms):

        1. install of base set of Jersey Binders (about 20 binders) takes 240ms. - TODO: Investigate these binders
        2. Validation: 120ms - TODO: Ask Jersey to be possible switch it off. As I wrote before reduction of resources does not help much
        3. Resources introspection: 100ms - TODO: Try to use programmatic API. But I am expecting that it helps just tens of milis.
        4. Stage building 110ms - TODO: Just try to understand this process. But I don't thing that it will be place to reduce init time
        5. Initialisation of component providers 90ms - TODO: Check if we need it and what is it.
        Show
        martin.mares added a comment - Tom: Today I was back in this task. Trying determine what we can do and what initialization is consist of. I found following possibilities - topics for future investigation (overal init is 900ms): install of base set of Jersey Binders (about 20 binders) takes 240ms. - TODO: Investigate these binders Validation: 120ms - TODO: Ask Jersey to be possible switch it off. As I wrote before reduction of resources does not help much Resources introspection: 100ms - TODO: Try to use programmatic API. But I am expecting that it helps just tens of milis. Stage building 110ms - TODO: Just try to understand this process. But I don't thing that it will be place to reduce init time Initialisation of component providers 90ms - TODO: Check if we need it and what is it.
        Hide
        martin.mares added a comment -

        Currently I have two major ideas:
        a) Reflect older idea from Marek and ask Jersey to make validation optional based some configuration variable. Validation takes 120ms on my environment.
        b) Currently working on Jersey's plugin to ServiceFinder implementation. It is already plug-able but I want to ask for revision or maybe small API improvement from Jersey team. I don't want to destroy something. If my measurements are OK my plugin can improve performance for aprox 200ms.
        Overal initialization takes 900ms these two improvements can change it to 600ms. It looks good - so, cross fingers.

        Show
        martin.mares added a comment - Currently I have two major ideas: a) Reflect older idea from Marek and ask Jersey to make validation optional based some configuration variable. Validation takes 120ms on my environment. b) Currently working on Jersey's plugin to ServiceFinder implementation. It is already plug-able but I want to ask for revision or maybe small API improvement from Jersey team. I don't want to destroy something. If my measurements are OK my plugin can improve performance for aprox 200ms. Overal initialization takes 900ms these two improvements can change it to 600ms. It looks good - so, cross fingers.
        Hide
        martin.mares added a comment -
        • What is the impact on the customer of the bug?

        Solution improves performance of Jersey initialization in metter of time and footprint. Jersey initialization is part of start sequence but running in parallel with other staff.

        • What is the cost/risk of fixing the bug?

        This fix has 3 parts:

        1. switch of deployed Jersey application model validation - reduce init duration by 120 ms on my laptop - low risk
        2. reduce number of deployed Jersey providers - reduce init duration by 20 ms and reduce footprint - middle risk
        3. remove non necessary resource auto discovery in Jersey initialization by providing own custom provider - reduce init duration about 100ms - middle risk
        • Is there an impact on documentation or message strings?

        No

        • Which tests should QA (re)run to verify the fix did not destabilize GlassFish?

        CLI tests

        • Which is the targeted build of 4.0 for this fix?

        neerest

        • If this an integration of a new version of a component from another project,
          what are the changes that are being brought in? This might be list of
          Jira issues from that project or a list of revision messages.

        N/A

        Show
        martin.mares added a comment - What is the impact on the customer of the bug? Solution improves performance of Jersey initialization in metter of time and footprint. Jersey initialization is part of start sequence but running in parallel with other staff. What is the cost/risk of fixing the bug? This fix has 3 parts: switch of deployed Jersey application model validation - reduce init duration by 120 ms on my laptop - low risk reduce number of deployed Jersey providers - reduce init duration by 20 ms and reduce footprint - middle risk remove non necessary resource auto discovery in Jersey initialization by providing own custom provider - reduce init duration about 100ms - middle risk Is there an impact on documentation or message strings? No Which tests should QA (re)run to verify the fix did not destabilize GlassFish? CLI tests Which is the targeted build of 4.0 for this fix? neerest If this an integration of a new version of a component from another project, what are the changes that are being brought in? This might be list of Jira issues from that project or a list of revision messages. N/A
        Hide
        martin.mares added a comment -

        svn 61705

        Show
        martin.mares added a comment - svn 61705

          People

          • Assignee:
            martin.mares
            Reporter:
            Tom Mueller
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: