Jakob,
I did install VisualVM but it is not capturing org.apache.* classes or
com.mycompany.* classes. I did not find a setting on how to enable capturing
data for all the classes I want. Can you tell me where to specity the
packages for which I want to capture CPU usage?
Vinay
On Mon, Jan 11, 2010 at 4:05 PM, Ravi Kapoor <ravikapoor...@gmail.com>wrote:
> Jakob,
>
> The beans are not big. Also these tests have been performed under a single
> user to measure the CPU timing. So I doubt locking/synchronization is an
> issue.
>
> I would think that if there is synchronization, then the threads could be
> waiting for long time, but lack of synchronization can only lead to corrupt
> data not to higher CPU. Can you explain little bit how lack of
> synchronization can add to CPU?
>
> I have never used VisualVM, I can try it sometime this week. I am assuming
> it will work with Websphere 6.1
>
> Regards
> Ravi
>
>
> On Mon, Jan 11, 2010 at 3:03 PM, Jan-Kees van Andel <
> jankeesvanan...@gmail.com> wrote:
>
>> Hi Ravi,
>>
>> Just a stupid question. Are your beans extremely big? Since FacesBean
>> doesn't do much locking/synchronizing (none if I'm correctly), the
>> only reason I can imagine it to eat CPU cycles is because of its
>> size...
>>
>> Also, is it possible for you to do a profiling run using VisualVM?
>> I've been profiling Trinidad with VisualVM myself and maybe we can
>> compare numbers... Using the same tool might make it easier to
>> compare...
>>
>> /JK
>>
>>
>> 2010/1/11 Ravi Kapoor <ravikapoor...@gmail.com>:
>> > I am thinking if that was the case, I would see high CPU in
>> > java.util.HashMap instead of org.apache.faces.*
>> >
>> > If you disagree, please explain and I can try using HashTable to store
>> data
>> > and get fresh numbers.
>> >
>> >
>> > On Mon, Jan 11, 2010 at 10:00 AM, Jakob Korherr <
>> jakob.korh...@gmail.com>wrote:
>> >
>> >> 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 <ravikapoor...@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 <ravikapoor...@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 <
>> ravikapoor...@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 <
>> >> > >>> jankeesvanan...@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 <ravikapoor...@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 <
>> ravikapoor...@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 <ravikapoor...@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 <ravikapoor...@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
>> >> > >>>>>>>>>>> <jankeesvanan...@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 <ravikapoor...@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
>> >> > >>>>>>>>>>>>> <mat...@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
>> >> > >>>>>>>>>>>>>> <ravikapoor...@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
>> >> > >>>>>>>>>>>>>>
>> >> > >>>>>>>>>>>>>>
>> >> > >>>>>>
>> >> > >>>>>>
>> >> > >>>>>
>> >> > >>
>> >> > >>
>> >> > >>
>> >> > >
>> >> >
>> >>
>> >
>>
>
>
