FacesConfigBeanNameResolver takes 40-200ms/invocation, 400-500ms/req (GF3.1)

Splash Forums PrettyFaces Users FacesConfigBeanNameResolver takes 40-200ms/invocation, 400-500ms/req (GF3.1)

This topic contains 8 replies, has 4 voices, and was last updated by  Lincoln Baxter III 6 years, 3 months ago.

Viewing 9 posts - 1 through 9 (of 9 total)
  • Author
    Posts
  • #17967

    ringerc
    Participant

    Hi

    A search of the archives for FacesConfigBeanNameResolver didn’t reveal anything, so:

    I’ve been suffering from very slow requests since I added Seam 3 Faces and PrettyFaces to my project. I’m using Glassfish 3.1 with weld-osgi-bundle updated to 1.1.1 as required by Seam 3. Requests often take 400-500ms to complete. This includes AJAX requests, so some pages take several seconds to render. During this time, server-side CPU use is maxed out.

    I have a WEB-INF/pretty-config.xml containing only the XML header and the top-level <pretty-config/> element with its namespaces. No rules are defined. If I remove the config file entirely then no change is observed.

    Enabling trace-level logging in JSF shows that the delays occur after Mojarra has finished its processing lifecycle – after it logs that RENDER_RESPONSE is completed “including any phaselisteners”. The delays are after that, during filter processing.

    Some time with the debugger showed that whenever I paused Glassfish’s execution and examined the state of the http thread associated with the test request, Glassfish was busy deep in Xerces, called via apache commons digester from FacesConfigBeanNameResolver.processFacesConfig as called by AnnotationConfigurationProvider.loadConfiguration during PrettyConfigurator.configure . Some sample stack traces follow.

    After enabling prettyfaces tracing, I can see that FacesConfigBeanNameResolver is invoked seven times in a simple request for a “hello world” Facelets page in my app – one without templates, RichFaces use, etc. By comparing the time the invocation was logged vs the time when the next log message not emitted by FacesConfigBeanNameResolver appears, I can see that none of these invocations take less than 40ms. Most take 50ms, but one takes 128ms and one takes 242ms. I’ll include a log excerpt below.

    Has this been observed elsewhere? I can reproduce it reliably on all three of my dev machines – two on Ubuntu, one on Windows 7. The Ubuntu machines are on OpenJDK 1.6.0_22 and the Windows machine is on the Sun JDK 1.6.0 update 26 (latest).

    I’m putting together a minimal test case now, but wanted to ask about others’ experiences in the mean time.

    Here are some stack traces captured by pausing Glassfish’s execution after the Mojarra RENDER_RESPONSE phase ends. Each is a trace of the http servlet that was processing the test page request.

    http://pastebin.com/X6rvGQdF

    … and here’s the Glassfish log output from a test request with TRACE level logging for PrettyFaces enabled:

    http://pastebin.com/V27wgAtm

    (Edits: remove inline exception traces, move to pastebin for readability of this post)

    #21073

    Thank you very much for bringing this up! I guess this has something to do with a performance issue we recently fixed in the current trunk.

    Could you perhaps give the latest snapshot a try?

    https://github.com/ocpsoft/prettyfaces/wiki/Snapshots

    My guess is also that this only happens in the project stage “Development”, correct?

    #21074

    ringerc
    Participant

    It’s certainly not as bad in PROJECT_STAGE Production . Interesting.

    I’ll try the latest snapshot and report back.

    I’ve put together a stripped-down testcase with just the RichFaces, Seam 3 Faces and PrettyFaces dependencies I rely on and a single “hello world” Facelets page. It was performing fine on the same server my real project was having issues on, with PROJECT_STAGE set to Development. Adding WEB-INF/beans.xml to enable CDI appears to trigger the performance issues, though I’m doing a few tests to confirm that that’s repeatable. If it is, I’ll post the testcase and check it against the snapshot.

    #21075

    domdorn
    Participant

    PrettyFaces reloads the configuration for every request if the project stage is not set to Production, to allow changing the configuration while developing.

    Loading it 7 times in a request seems to be a mistake, we’ll have to check.

    #21076

    ringerc
    Participant

    OK, timing tests done on the testcase using PrettyFaces 3.2.1 and 3.3.0-SNAPSHOT.

    3.3.0-SNAPSHOT is *much* faster, returning results in about 34ms quite consistently with my testcase, instead of between 300ms and 2400ms for 3.2.1.

    In my real app I’m seeing a similarly dramatic improvement. Thanks *very* much for looking at this and for your time and work on prettyfaces.

    I don’t even use PrettyFaces directly at present. It’s just a hard dependency for Seam 3 Faces under Glassfish 3.1 . I suspect I’ll land up wanting to use it before this project is done, though, especially once 3.3 hits stable.

    I’ll keep tracking the SNAPSHOT releases and report any hiccups. Thanks again.

    #21077

    Just to clear things up a bit. The current stable release of PrettyFaces (3.2.1) reloads the configuration once per request if the application runs in project stage “Development”. Unfortunately this may cause performance issues, because the configuration reloads even on requests for CSS files and images.

    So we changed this in the current trunk. Now the configuration reloads once every 2 seconds. This should give much better performance for the developer mode in must cases.

    However I see no reason why PrettyFaces should reload the configuration more than once per request. Perhaps this is a bug in the PrettyFaces integration of Seam Faces? Does it really happen more than once per request or could this be caused by CSS files or images on the page?

    #21078

    domdorn
    Participant

    @christian: without looking at the code: could it be we’re seeing a CDI lifecycle issue here? like that the configuration bean is created multiple times and we parse the configuration in the constructor instead of a @PostConstruct method? That would explain why the configuration is parsed more than once per request.

    #21079

    Yeah, I think this could be possible. I don’t know much about the PrettyFaces integration layer that Brian wrote, but I think something like this could happen.

    I’ll have a deeper at this later as soon as I find some time. I have to prepare a pull request for Seam Faces regarding some other issue anyway! :)

    #21080

    Interesting. I’m actually not too familiar with this myself either, so I’ll dig in when I get a chance as well.

Viewing 9 posts - 1 through 9 (of 9 total)

You must be logged in to reply to this topic.

Comments are closed.