Mailing-List: contact users-help@myfaces.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "MyFaces Discussion" <users@myfaces.apache.org>
Received-SPF: pass (nike.apache.org: domain of sethfromaustria@gmail.com
 designates 209.85.218.211 as permitted sender)
DomainKey-Signature: a=rsa-sha1; c=nofws;
        d=gmail.com; s=gamma;
        h=mime-version:sender:in-reply-to:references:date
         :x-google-sender-auth:message-id:subject:from:to:content-type;
        b=DBVdBx5Fp3hKeqFu+PRdk1wwjyW+LBGqjo3yzMf+rzck792wcqtuMd0zB5Q7Hodmkm
         wbGnE9MyRumgVfx7rBl/dIJHWtR9BdftpULjPBv+Poou0+t6gCrHZADVCb2nK15xPskm
         qtO06Hs9T2RfHKd9NPDA5fp+kq2QrfUXSJ1qI=
MIME-Version: 1.0
Sender: sethfromaustria@gmail.com
In-Reply-To: <38f8e9891001110653j50cf8ec3sa30c75f4223449eb@mail.gmail.com>
References: <38f8e9891001071425u1cea73daufa30abba02a8c313@mail.gmail.com>
	 <-7377398441753107140@unknownmsgid> <4B494FF5.4000706@gmail.com>
	 <71235db41001100221n69d82b4kb44014a1baf3fb77@mail.gmail.com>
	 <4B4A0EA2.9010904@gmail.com>
	 <237ac0b1001100954j4936018csc873ce05955dae10@mail.gmail.com>
	 <38f8e9891001102145r264b170dt7a879c83a37e3503@mail.gmail.com>
	 <71235db41001110038m2d6b5747j4a245aa57227a677@mail.gmail.com>
	 <4B4B276D.1020508@gmail.com>
	 <38f8e9891001110653j50cf8ec3sa30c75f4223449eb@mail.gmail.com>
Date: Mon, 11 Jan 2010 16:00:40 +0100
Message-ID: <fd49e8161001110700j6c0fe600yf14873f8541986f3@mail.gmail.com>
Subject: Re: [Trinidad] Trinidad consuming 80-90% CPU
From: Jakob Korherr <jakob.korherr@gmail.com>
To: MyFaces Discussion <users@myfaces.apache.org>
Content-Type: multipart/alternative; boundary=0016364c7151fb5300047ce4cc4e

--0016364c7151fb5300047ce4cc4e
Content-Type: text/plain; charset=UTF-8

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
> >>>>>>>>>>>>>>
> >>>>>>>>>>>>>>
> >>>>>>
> >>>>>>
> >>>>>
> >>
> >>
> >>
> >
>

--0016364c7151fb5300047ce4cc4e--