4

I was just trying out some profiling experiments with my JSF project using Netbeans based Profiler. However I found a very surprising results. I found JSF's FacesServlet.service() method to be consuming most of the time while requests were being served. I do serve content from databases into my JSF pages but still I found major time lag was due to high self time of service() method.

Here is the snapshot of the profiling results:- See the high self-time of FacesServlet service() method

Why is this happening, what's happening so expensive within this method that causes such high self time ?

I am running Myfaces 2.1.12 in Production mode on Tomcat 7.0.42.

Edit:

As rightly pointed out by @mkienenb in his answer below, during the above profiling test I excluded the org.apache.myfaces methods, so I did a fresh profiling test & I'm posting below the new result snapshot.

enter image description here

But you can still see that a lot of time overhead is caused due to self times of Myfaces/JSF methods.

Rajat Gupta
  • 25,853
  • 63
  • 179
  • 294

2 Answers2

2

I'm not an expert on profiling, but I'm pretty sure that "self-time" includes all methods that are not explicitly profiled elsewhere. For some reason it appears that you are not profiling "org.apache.myfaces" methods individually, but only javax.faces methods.

So that's going to make all JSF execution time show up under javax.faces.webapp.FacesServlet.services().

You need to adjust your package exclusion choices. I don't use NetBeans so I can't tell you specifically how that's done.

mkienenb
  • 56
  • 3
  • yeah you were right.. **"it appears that you are not profiling "org.apache.myfaces" methods individually, but only javax.faces methods."**, what you said was found true but still you see `javax.faces` methods + `org.apache.myfaces` methods, both belong to jsf so would you accept any framework that has such a high overhead ? Is it acceptable!? – Rajat Gupta Sep 09 '13 at 18:18
  • Until you break down exactly where the processing time is going, it's hard to say it's a "high overhead". Also, the primary point of a JSF application is to serve JSF pages, so I'd expect the framework to be the primary load -- 75% in this case. There was a recent article series on JSF that you might want to read. It compares JSF performance to other frameworks. [http://content.jsfcentral.com/c/journal_articles/view_article_content?groupId=35702&articleId=66621&version=2.3] – mkienenb Sep 09 '13 at 18:34
  • **Until you break down exactly where the processing time is going, it's hard to say..**- I hope my updated question with new snapshot image somewhat reveals what you're asking for. – Rajat Gupta Sep 09 '13 at 18:41
  • **75%** load *just* due to frontend framework in a high traffic database based application ?!! ok?! – Rajat Gupta Sep 09 '13 at 18:43
  • I think you are still not breaking it down enough. How do you know that your own code isn't being included in the 43% attributed to service()? Turn off all of the package filtering and look at the real breakdown of the service() call. – mkienenb Sep 09 '13 at 19:03
  • I'm sure that my code isn't being included in the 43% attributed to service() because while profiling I only filtered out the core Java classes, so all my methods are included & also I can see them in the snapshot. For e.g. `px10.channelController.init()` is the method that retrieves from database & process all data to be shown for page. – Rajat Gupta Sep 09 '13 at 19:23
1

Hmmm, what are the parameters of FacesServlet.service()? is that servlet request and servlet response? seems like a typical request from your browser and response from your app/server.

It is quite obvious that your code-and-or-usage-of-your-dependencies are the cause of the time it takes for FacesServlet.service() to complete. Wow, it seems as though your usage of prettyfaces dependency is causing most of the lengthy time it takes for FacesServlet.service() to complete.

On Sat, Sep 7, 2013 at 2:24 AM, Anton Gavazuk wrote:

Process an incoming request, and create the corresponding response, by executing the request processing lifecycle.

If the request and response arguments to this method are not instances of HttpServletRequest and HttpServletResponse, respectively, the results of invoking this method are undefined.

This method must respond to requests that start with the following strings by invoking the sendError method on the response argument (cast to HttpServletResponse), passing the code HttpServletResponse.SC_NOT_FOUND as the argument.

So this method is actually wrapping up all underlying processing: jsf actions, business services, interaction with db - thus its time is always the biggest

In response to OP and to demonstrate what Anton (from myfaces list) stated above,

(1) Prior to beginning this request, my browser displayed the 'session timeout' page, so I clicked OK, which did a simple request to the server to respond with the login page. the screen captures below will show you that, such a simple request, yielded response time so quick that FacesServlet.service() was not found.

Figure 1a

Figure 1b

(2) After the login page was rendered in my browser, I clicked the Login button and my app does several operations (check database for user id, verify password stored in database, and then navigates to and renders a page which does a database retrieval, which can take a few seconds, depending on the number of user actions completed on the current date (it is user audit trail data/page), and of course, the page is rendered in the browser, after all of that. I searched for FacesServlet.service() several times until no more occurrences found. in the screen captures below, you will see that FacesServlet.service() 'time' is caused by the time it takes to complete other/underlying/invoked operations/processes.

Figure 2a

Figure 2b

Figure 2c

Figure 2d

Figure 2e

Figure 2f

Figure 2g

(3) On the Audit Trail page, I clicked an option which will invoke an AJAX request/response, which will do a database retrieval that can/will take longer than the database retrieval in #2 above, and then the AJAX response will be rendered in the browser. The screen captures below will show you, again, that FacesServlet.service() 'time' is caused by the time it takes to complete other/underlying/invoked operations/processes.

Figure 3a

Figure 3b

(4) Next/finally, I decided to click a menubar option, which does a database retrieval to show data in the database, based on the current date, and navigates to and/or renders a different page in the browser. The screen captures below will show you, again, that FacesServlet.service() 'time' is caused by the time it takes to complete other/underlying/invoked operations/processes.

Figure 4a

Figure 4b

Figure 4c

I am running Myfaces 2.1.12 in Production mode on Tomcat 7.0.42.

Me too...via TomEE+ 1.6.0 'snapshot' (2013-September-06 version/build)

Howard
  • 792
  • 8
  • 43
  • Nice that you presented another set of results which are very contrasting when compared to mine, but does that answer my question or justify my results ? I don't think so. – Rajat Gupta Sep 08 '13 at 03:53
  • Did you provide multiple screen captures that show your entire set of results, listed under FacesServlet.service(), as I did? I don't think so. If you really want attention from MyFaces team, then open a bug report. Better yet, you might want to file the bug report to PrettyFaces, or ask the question in prettyfaces forum (or mail list). – Howard Sep 08 '13 at 11:10
  • I thought whatever I provided was sufficient, if not so you could have asked for anything more required instead of posting an unnecessary long answer that actually doesn't answer the question.Anyway I really appreciate the efforts you put & I thank you for that. – Rajat Gupta Sep 08 '13 at 11:14
  • Btw why do you think its relevant to prettyfaces ? – Rajat Gupta Sep 08 '13 at 11:18
  • my response proves a point better than a short-and-one-screen-capture response. :) does ocpsoft... == prettyfaces? :) I see plenty of occurrences there. I also see JUEL, retrieveCurrentLOB(), and other code referenced in px10.Controllers package. when looking at a stacktrace, I find it better to look from bottom up instead of the top. the 'caused by' is at the bottom. same in this case, FacesServlet.service() is 'caused by' everything from bottom-to-top. :) it would be nice to see your entire set of results, so we can do the math and see that it 'causes' the 'self time' of FacesServlet.service – Howard Sep 08 '13 at 11:45
  • in my answer, i gave a brief description of what my app was doing during each (faces servlet) request/response. can you provide a brief description of what your app is designed/expected-to-do during this (faces servlet) request/response? i already know that you're using pretty faces (most likely for URLs, i'm not a user of pretty faces, I only heard about it), also, I see that your 'LOB' code is getting data from database. PrimeFaces 4.0 (snapshot) is 'now' offering a [Deferred Content Loading](http://blog.primefaces.org/?p=2826) which may be able to help, or you write similar implementation. – Howard Sep 08 '13 at 11:57
  • I think one of us is confused about what **Self Time** actually means. I suggest to please have a look at this question & answer: http://stackoverflow.com/questions/11581686/what-does-netbeans-profilers-self-time-actually-mean – Rajat Gupta Sep 08 '13 at 13:39
  • Since you are still confused with self time and searching for related articles about self time, I decided to offer this one as well, [VisualVM and Self Time](http://stackoverflow.com/questions/14626475/visualvm-and-self-time), for you; GIYF as well. – Howard Sep 09 '13 at 12:23
  • I did that for your clarification. Did you carefully read what was written in the answer I sent you the link. Now I would just advise you to consult your expert colleague on this topic regarding self time as you're not hearing me:) Good luck! :) – Rajat Gupta Sep 09 '13 at 14:33
  • remember who is asking the question and who answered. i have no questions regarding 'self time'. i'm going with the answer that I provided. hope you find the answer that you're looking for. a picture is worth 1000 words, and i provided many 'pictures' (smile). – Howard Sep 09 '13 at 18:01