myfaces-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jakob Korherr <jakob.korh...@gmail.com>
Subject Re: [Trinidad] Trinidad consuming 80-90% CPU
Date Mon, 11 Jan 2010 15:00:40 GMT
Maybe it happens when accessing the value from the Map with
"#{bean.get['memid']}", because the Map is not properly synchronized, thus
its internal structure is broken and thus it is running in infinite loops.

Are your resources properly synchronized?

Just a guess in the blue...

Regards,
Jakob Korherr

2010/1/11 Ravi Kapoor <ravikapoor101@gmail.com>

> Another thing, most of our EL expressions are one of the following types
>
> "#{bean.active}"
> or
> "#{bean.get['memid']}"
>
> Parsing of these expressions probably happens within org.apache.myfaces.*
> classes. These are fairly basic EL expressions and should not be taking
> much
> time. We know, the final getter method is not taking much time.
>
> Do you know if the page (and EL expressions) are parsed each time a page is
> rendered? If pages are parsed only once, then the parsing time should also
> be almost negligible.
>
> - Ravi
>
> On Mon, Jan 11, 2010 at 8:28 AM, Ravi <ravikapoor101@gmail.com> wrote:
>
> >
> > Matthias,
> >
> > If the issue is in bean, it should show up in my analysis. Also
> getProperty
> > is only 40% CPU, there is additional 45% cpu consumed by rest of the
> > trinidad classes totaling 85% total CPU, all within org.apache.myfaces.*
> > classes
> >
> > Ravi
> >
> >
> >
> > Matthias Wessendorf wrote:
> >
> >> Ravi,
> >>
> >> spoke to a guy that does performance testing/improvement for Oracle
> >> Applications. He said that there is some % CPU in Trindad but I would
> >> not give it more them 20%. The heavy hitters is getClientId (Blake -
> >> see dev@ thread - is doing some optimization there).
> >>
> >> Now if getProperty is some el expression and expression is expensive
> >> the problem is in expression not in Trinidad (perhaps that is the case
> >> where you have el epression but beans behind it are not that good).
> >>
> >> -Matthias
> >>
> >> On Mon, Jan 11, 2010 at 6:45 AM, Ravi Kapoor <ravikapoor101@gmail.com>
> >> wrote:
> >>
> >>> Hi Jan-Kees,
> >>>
> >>> You are right, the getProperty method is only taking 2K units. However
> if
> >>> I
> >>> dig deeper, I find that most of the cumulative time is being spent
> within
> >>> Trinidad classes. The final call to java getters consumes negligible
> >>> time.
> >>>
> >>> I was unable to create thread structure like you showed (JProbe keeps
> >>> getting crashed). But I took another screenshot that shows almost
> similar
> >>> details you are looking for. It highlights the classes that are taking
> >>> maximum time (cumulative time again) but as you can see, all the
> classes
> >>> are
> >>> just trinidad classes.
> >>>
> >>>
> http://docs.google.com/Doc?docid=0AbuQsSDG0X9_ZGhraHFwejJfNGRjcGNiN2hk&hl=en
> >>>
> >>> Regards,
> >>> Ravi
> >>>
> >>> On Sun, Jan 10, 2010 at 12:54 PM, Jan-Kees van Andel <
> >>> jankeesvanandel@gmail.com> wrote:
> >>>
> >>>  Hey Ravi,
> >>>>
> >>>> Looking at your JProbe screenshots for the second time, I think you're
> >>>> misinterpreting the graphs (but I haven't used JProbe before, so I
> >>>> might be mistaking ;-) ).
> >>>>
> >>>> In your first screenshot (upper left corner) you can see the total
> >>>> time the getProperty method takes.
> >>>> This includes its self time and the time taken by its children. Its
> >>>> self time is 2781 and the child time is 29609.
> >>>> A large portion (around 85%) comes from the getLocalProperty and
> >>>> ValueBinding.getValue methods.
> >>>>
> >>>> However, these two methods don't do much, since they delegate to other
> >>>> methods to do the real work. Maybe even invoking application code,
> >>>> like managed beans.
> >>>>
> >>>> Can you provide a more detailed call tree with more info about the
> >>>> child methods that are invoked? I'm especially interested in the
> >>>> methods that are called by getLocalProperty and ValueBinding.getValue
> >>>> and their children. I'm not that familiar with JProbe, but I'm sure
it
> >>>> supports something like a call tree
> >>>> (
> >>>>
> >>>>
> http://www.ej-technologies.com/products/jprofiler/images/whatsnew/exceptional_methods_calltree.png
> >>>> ),
> >>>> so you can see the problematic method.
> >>>>
> >>>> Regards,
> >>>> Jan-Kees
> >>>>
> >>>>
> >>>> 2010/1/10 Ravi <ravikapoor101@gmail.com>:
> >>>>
> >>>>> Matthias, I think websphere 6.1 does not support JSF 1.2. I will
> >>>>> doublecheck, let me know if this is incorrect. This mans I cannot
try
> >>>>> trinidad version 1.2.12
> >>>>>
> >>>>> I will try out 1.0.11 release, but that is a minor release update
and
> I
> >>>>> seriously doubt if it will fix such a performance issue.
> >>>>>
> >>>>> What other options do we have? Is there a way we can get somebody
> >>>>>
> >>>> familiar
> >>>>
> >>>>> with trinidad architecture/code to look at this issue? This can
even
> be
> >>>>> a
> >>>>> paid assignment.
> >>>>>
> >>>>> Regards
> >>>>> Ravi
> >>>>>
> >>>>>
> >>>>> Matthias Wessendorf wrote:
> >>>>>
> >>>>>> Hello Ravi,
> >>>>>>
> >>>>>> I wonder what our last release for JSF 1.1 (1.0.11) does?
> >>>>>>
> >>>>>> Not sure, perhaps you may also try the JSF 1.2 version ? (1.2.12)
> >>>>>> The JSF 1.2 version is the one that is best supported, these
days.
> >>>>>>
> >>>>>> Trinidad 2.0 is now in alpha stage, and I can understand that
you
> >>>>>> don't want to update on that version, now
> >>>>>>
> >>>>>> -Matthias
> >>>>>>
> >>>>>> On Sun, Jan 10, 2010 at 4:56 AM, Ravi <ravikapoor101@gmail.com>
> >>>>>> wrote:
> >>>>>>
> >>>>>>> Scott, we do not have CPUs available. The time trinidad
is
> consuming
> >>>>>>> is
> >>>>>>> supposed to be doing some other work. Hence this is costing
us real
> >>>>>>> dollars
> >>>>>>> and hence our time and effort to resolve this.
> >>>>>>>
> >>>>>>> This is not initial hit of page. I always ignore the first
hit on
> all
> >>>>>>> pages,
> >>>>>>> I am only measuring CPU from 2nd hit onwards.
> >>>>>>>
> >>>>>>> Ravi
> >>>>>>>
> >>>>>>>
> >>>>>>> Scott O'Bryan wrote:
> >>>>>>>
> >>>>>>>> I don't know.  I'm of the camp that if the CPU time
is available,
> >>>>>>>> use
> >>>>>>>> it.  That said, is this load consistant or are you just
testing an
> >>>>>>>> initial hit of each page.
> >>>>>>>>
> >>>>>>>> Sent from my iPhone
> >>>>>>>>
> >>>>>>>> On Jan 8, 2010, at 11:25 PM, Ravi <ravikapoor101@gmail.com>
> wrote:
> >>>>>>>>
> >>>>>>>>  Hi Jan-Kees,
> >>>>>>>>>
> >>>>>>>>> Now that I am reading your message again, I do want
to answer
> your
> >>>>>>>>> questions in detail. First I agree reflection is
cheap, that is
> why
> >>>>>>>>> reflection is not my concern. Time being spent in
reflection is
> >>>>>>>>> almost negligible compared to time being spent in
trinidad
> classes.
> >>>>>>>>>
> >>>>>>>>> Secondly IO and locking etc contribute to clock
time but not to
> CPU
> >>>>>>>>> time. e.g. for IO, the thread may be in a wait state
waiting for
> >>>>>>>>> data to arrive. In this case, the clock keeps ticking
but such a
> >>>>>>>>> wait does not need CPU. My numbers are specifically
CPU time.
> Which
> >>>>>>>>> means trinidad is not waiting but executing CPU
instructions.
> >>>>>>>>>
> >>>>>>>>> This is why the user load is also irrelevant (high
load leads to
> >>>>>>>>> adding clock time but not to CPU time). But since
you asked, to
> get
> >>>>>>>>> these numbers, I am not doing a load testing. I
am simply loading
> 4
> >>>>>>>>> screens 4 times in order (total 16 screens).
> >>>>>>>>>
> >>>>>>>>> Regards
> >>>>>>>>> Ravi
> >>>>>>>>>
> >>>>>>>>>
> >>>>>>>>>
> >>>>>>>>> Jan-Kees van Andel wrote:
> >>>>>>>>>
> >>>>>>>>>> I'm not sure, but I doubt the mailing list supports
attachments.
> >>>>>>>>>> Maybe you could provide a link to some image
hosting site?
> >>>>>>>>>> My first thought, reflection is darn cheap,
especially since
> Java
> >>>>>>>>>> 5
> >>>>>>>>>> and even more since Java 6. I'm no IBM JVM specialist,
but I
> don't
> >>>>>>>>>> think there are major differences with HotSpot...
Compared with
> >>>>>>>>>> SQL
> >>>>>>>>>> queries, backend transactions, web service calls,
etc.
> reflective
> >>>>>>>>>> method invocations really don't make a difference.
> >>>>>>>>>> Having said that, what kind of application are
you testing? Does
> >>>>>>>>>>
> >>>>>>>>> this
> >>>>
> >>>>> application have any I/O, locking or other expensive things that
may
> >>>>>>>>>> be the cause of the CPU-time imbalance?
> >>>>>>>>>> Also, what kind of load are you simulating on
your application?
> >>>>>>>>>> Long
> >>>>>>>>>> sessions with not much users? Lots of short
sessions?
> Hyperactive
> >>>>>>>>>> users without any pauses?
> >>>>>>>>>> /JK
> >>>>>>>>>> Ps. How did you configure your profiler? Sampling
or
> >>>>>>>>>> tracing/instrumentation? Although I don't think
it makes a
> >>>>>>>>>>
> >>>>>>>>> difference
> >>>>
> >>>>> in this case, sampling is less accurate...
> >>>>>>>>>> 2010/1/8 Ravi Kapoor <ravikapoor101@gmail.com>:
> >>>>>>>>>>
> >>>>>>>>>>> The actual call to getter method is only
using 2% CPU. Rest 38%
> >>>>>>>>>>> is
> >>>>>>>>>>> being
> >>>>>>>>>>> used within trinidad classes.
> >>>>>>>>>>> I am attaching two screenshots to give you
more details.
> >>>>>>>>>>>
> >>>>>>>>>>> In first screenshot, you can see at the
top left corner, total
> >>>>>>>>>>> CPU
> >>>>>>>>>>> units
> >>>>>>>>>>> taken by getProperty are 32391
> >>>>>>>>>>> getProperty calls javax.faces.el.ValueBinding.getValue
which
> >>>>>>>>>>> calls
> >>>>>>>>>>> org.apache.myfaces.el.PropertyResolverImpl.getValue
which calls
> >>>>>>>>>>> org.apache.myfaces.el.PropertyResolverImpl.getProperty
which
> >>>>>>>>>>> calls
> >>>>>>>>>>> java.lang.reflect.Method.invoke.
> >>>>>>>>>>>
> >>>>>>>>>>> In second screenshot you can see that Method.invoke
is using
> only
> >>>>>>>>>>> 1781 units
> >>>>>>>>>>> of CPU. Rest of the time is being spent
within trinidad
> classes.
> >>>>>>>>>>>
> >>>>>>>>>>> Does this help? Also the rest of trinidad
using 45% CPU usage
> is
> >>>>>>>>>>> also highly
> >>>>>>>>>>> concerning.
> >>>>>>>>>>>
> >>>>>>>>>>> Thanks
> >>>>>>>>>>> Ravi
> >>>>>>>>>>>
> >>>>>>>>>>>
> >>>>>>>>>>> On Fri, Jan 8, 2010 at 1:47 PM, Jan-Kees
van Andel
> >>>>>>>>>>> <jankeesvanandel@gmail.com> wrote:
> >>>>>>>>>>>
> >>>>>>>>>>>> Hey,
> >>>>>>>>>>>>
> >>>>>>>>>>>> Is it possible that the getProperty
indirectly invokes some
> >>>>>>>>>>>> expensive
> >>>>>>>>>>>> computation? For example, do you have
lots of logic inside
> your
> >>>>>>>>>>>> getters?
> >>>>>>>>>>>>
> >>>>>>>>>>>> Regards,
> >>>>>>>>>>>> Jan-Kees
> >>>>>>>>>>>>
> >>>>>>>>>>>>
> >>>>>>>>>>>> 2010/1/8 Ravi Kapoor <ravikapoor101@gmail.com>:
> >>>>>>>>>>>>
> >>>>>>>>>>>>> Hi Matthias,
> >>>>>>>>>>>>>
> >>>>>>>>>>>>> Here are the details:
> >>>>>>>>>>>>>
> >>>>>>>>>>>>> Server: Websphere 6.1
> >>>>>>>>>>>>>
> >>>>>>>>>>>>> Trinidad version: 1.0.7  (We cant
upgrade to 2.0 until we
> >>>>>>>>>>>>> upgrade
> >>>>>>>>>>>>> websphere
> >>>>>>>>>>>>> which will happen in due course.
Even then if this issue has
> >>>>>>>>>>>>> not
> >>>>>>>>>>>>> been
> >>>>>>>>>>>>> addressed, the problem may exist
in 2.0 as well.)
> >>>>>>>>>>>>>
> >>>>>>>>>>>>> OS: Windows (Even though I am measuring
numbers on windows
> but
> >>>>>>>>>>>>> I
> >>>>>>>>>>>>> do not
> >>>>>>>>>>>>> think this is OS specific)
> >>>>>>>>>>>>>
> >>>>>>>>>>>>>
> >>>>>>>>>>>>> Let me know if you need to know
anything else.
> >>>>>>>>>>>>>
> >>>>>>>>>>>>> Regards
> >>>>>>>>>>>>> Ravi
> >>>>>>>>>>>>>
> >>>>>>>>>>>>>
> >>>>>>>>>>>>>
> >>>>>>>>>>>>> On Fri, Jan 8, 2010 at 1:09 AM,
Matthias Wessendorf
> >>>>>>>>>>>>> <matzew@apache.org>wrote:
> >>>>>>>>>>>>>
> >>>>>>>>>>>>>  Hello Ravi,
> >>>>>>>>>>>>>>
> >>>>>>>>>>>>>> some more background would be
good, e.g. what version of
> >>>>>>>>>>>>>> Trinidad etc.
> >>>>>>>>>>>>>>
> >>>>>>>>>>>>>> -Matthias
> >>>>>>>>>>>>>>
> >>>>>>>>>>>>>> On Thu, Jan 7, 2010 at 11:25
PM, Ravi Kapoor
> >>>>>>>>>>>>>> <ravikapoor101@gmail.com
> >>>>>>>>>>>>>> wrote:
> >>>>>>>>>>>>>>
> >>>>>>>>>>>>>>> Has anybody done performance
tests on trinidad application.
> I
> >>>>>>>>>>>>>>> have an
> >>>>>>>>>>>>>>> application and it appears
that it is taking 80-90% of CPU
> in
> >>>>>>>>>>>>>>>
> >>>>>>>>>>>>>> my
> >>>>
> >>>>> application, thus killing performance.
> >>>>>>>>>>>>>>>
> >>>>>>>>>>>>>>> We ran load tests and our
CPU went to 100% usage. At this
> >>>>>>>>>>>>>>> point we
> >>>>>>>>>>>>>>>
> >>>>>>>>>>>>>> measured
> >>>>>>>>>>>>>>
> >>>>>>>>>>>>>>> how much time was being
taken by each class/method. Here
> are
> >>>>>>>>>>>>>>> some
> >>>>>>>>>>>>>>> interesting figures:
> >>>>>>>>>>>>>>>
> >>>>>>>>>>>>>>> CPU usage by all Trinidad
+ myfaces classes = 80-90%
> >>>>>>>>>>>>>>> Myfaces CPU usage (without
trinidad) = 8% (which implies
> >>>>>>>>>>>>>>> trinidad is
> >>>>>>>>>>>>>>>
> >>>>>>>>>>>>>> taking
> >>>>>>>>>>>>>>
> >>>>>>>>>>>>>>> 70-80% of CPU)
> >>>>>>>>>>>>>>> Total time taken by one
method
> >>>>>>>>>>>>>>>
> (org.apache.myfaces.trinidad.bean.FacesBeanImpl.getProperty)
> >>>>>>>>>>>>>>> =
> >>>>>>>>>>>>>>> 40%
> >>>>>>>>>>>>>>>
> >>>>>>>>>>>>>>> Can anybody confirm that
they have seen this behavior?
> >>>>>>>>>>>>>>> Or if somebody can confirm
that this does not happen in
> their
> >>>>>>>>>>>>>>> performance
> >>>>>>>>>>>>>>> tests, that should help
too.
> >>>>>>>>>>>>>>>
> >>>>>>>>>>>>>>> Thanks
> >>>>>>>>>>>>>>> Ravi
> >>>>>>>>>>>>>>>
> >>>>>>>>>>>>>>>  --
> >>>>>>>>>>>>>> Matthias Wessendorf
> >>>>>>>>>>>>>>
> >>>>>>>>>>>>>> blog: http://matthiaswessendorf.wordpress.com/
> >>>>>>>>>>>>>> sessions: http://www.slideshare.net/mwessendorf
> >>>>>>>>>>>>>> twitter: http://twitter.com/mwessendorf
> >>>>>>>>>>>>>>
> >>>>>>>>>>>>>>
> >>>>>>
> >>>>>>
> >>>>>
> >>
> >>
> >>
> >
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message