4 Replies Latest reply on Jun 8, 2009 11:12 PM by andygibson.contact.andygibson.net

    profiling pages and conversations

    jeanluc

      I would like to log the processing time for a page and a conversation (not as in actively debugging a problem with a profiler).


      Pages



      For pages, I'm particularly interested in the Render Response phase. If I enable DEBUG logging I can see entries for org.ajax4jsf.event.AjaxPhaseListener, but what I'm looking for is something stateful (over a page) so I can keep the before timestamp and dump the difference (and the page name as well). Is there something built into Seam that I can tap for this, perhaps?


      Conversations


      For conversations, I'm interested in the overall time, from begin to end. I looked at events but org.jboss.seam.beginConversation and org.jboss.seam.endConversation appear to only be called for long-running conversations. Not all of my conversations are long-running now, isn't there a mechanism to intercept the lifecycle of short-lived conversations?


      Thanks,
      -jl

        • 1. Re: profiling pages and conversations
          andygibson.contact.andygibson.net

          I used a log phase listener as a really clumsy way to profile pages. While it may not be 'accurate' it does indicate the scale of the time taken for a page to render (i.e. 78ms vs 2045ms).




          import javax.faces.event.PhaseEvent;
          import javax.faces.event.PhaseId;
          import javax.faces.event.PhaseListener;
          
          import org.jboss.seam.log.LogProvider;
          import org.jboss.seam.log.Logging;
          
          public class LogPhaseListener implements PhaseListener {
          
               private static final long serialVersionUID = 1L;
          
               public long startTime;
          
               private static final LogProvider log = Logging
                         .getLogProvider(LogPhaseListener.class);
          
               public void afterPhase(PhaseEvent event) {
                    if (event.getPhaseId() == PhaseId.RENDER_RESPONSE) {
                         long endTime = System.nanoTime();
                         long diffMs = (long) ((endTime - startTime) * 0.000001);
                         if (log.isDebugEnabled()) {
                              log.debug("Execution Time = " + diffMs + "ms");
                         }
                    }
                    if (log.isDebugEnabled()) {
                         log.debug("Executed Phase " + event.getPhaseId());
                    }
               }
          
               public void beforePhase(PhaseEvent event) {
          
                    if (event.getPhaseId() == PhaseId.RESTORE_VIEW) {
                         startTime = System.nanoTime();
                    }
               }
          
               public PhaseId getPhaseId() {
                    return PhaseId.ANY_PHASE;
               }
          
          }
          
          



          Just add this code and define it in the faces config xml file as a phase listener.


           <lifecycle>
            <phase-listener>package-name.LogPhaseListener</phase-listener>
           </lifecycle>
          



          As for short running conversations, the duration of a short lived conversation is the same as the request lifespan roughly speaking. It may vary from page to page since they can get re-used and therefore some may require creation and others are already created and may already contain data you need, other times, depending on how you navigate through your app when profiling, the results will be different.


          If you are looking for a rough method of profiling, this should do, I have an app with hundreds of people on it daily that hasn't had any problems and using this method I was able to locate and remove bottle necks. Of course, if you are profiling activity by the nanosecond and dealing with millions of users, you may need something a little more accurate and a little less clumsy.


          Cheers,


          Andy Gibson

          • 2. Re: profiling pages and conversations
            jeanluc

            Excellent, thank you. Do you happen to know if it's possible to detect whether a view is hit for the very first time (and thus has the response times much longer)? It's not very likely (after all, compilation of pages is done on demand and whether it has been such a case may not be propagated further), but just in case it can be known...


            Thanks again.

            • 3. Re: profiling pages and conversations
              jeanluc

              Just a follow-up to my own message, I looked inside the JSF event and the reachable objects from it but haven't found any flag telling whether it was the first hit. So if possible at all, I think the solution would have to peek inside the same cache that the JSF engine itself uses to determine whether to compile the view. I am not sure, though, that it's possible to access that cache from within a phase listener before the engine compiles the view. So if even the first JSF phase happens after the compilation, this wouldn't work.

              • 4. Re: profiling pages and conversations
                andygibson.contact.andygibson.net

                Do you happen to know if it's possible to detect whether a view is hit for the very first time

                I can't think of a simple way to do this, but checking JSF view compilation probably isn't what you want to do since going into a view for the first time isn't the same as going into a page without a conversation. Compiled JSF View can be re-used across page, if not for all instances of that page needed, but that is separate from the state of the conversation.
                You can go back in to a specific page and it may used the compiled view, but you may or may not have a conversation active.


                On possible way is to have a value in the conversation i.e. #{firstTime} and you can test for that value and if isn't there, it's a new conversation, and if it is, then this is a re-used conversation. If it isn't there, add it as a value so you will find it next time. One easy way to do this is create a factory method that is triggered when you try and find the value.
                Note that I could be talking rubbish though and the creation time for conversations is negligible (and it probably is). However, if you are using an existing conversation all the time, chances are that it already has some data in it which may act as an unintended cache for data which should be current.


                Personally, I like to always cut off conversation propagation so I don't end up with a few conversations that keep on getting re-used and carry large amounts of data around with it. Plus I get fresh data anytime I am working on an entity.


                Cheers,


                Andy Gibson