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 <[email protected]>: > 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 > <[email protected]>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 <[email protected]> >> >> > 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 <[email protected]> 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 <[email protected] >> > >> > >> 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 < >> > >>> [email protected]> 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 <[email protected]>: >> > >>>> >> > >>>>> 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 <[email protected]> >> > >>>>>> 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 <[email protected]> >> > 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 <[email protected]>: >> > >>>>>>>>>> >> > >>>>>>>>>>> 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 >> > >>>>>>>>>>> <[email protected]> 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 <[email protected]>: >> > >>>>>>>>>>>> >> > >>>>>>>>>>>>> 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 >> > >>>>>>>>>>>>> <[email protected]>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 >> > >>>>>>>>>>>>>> <[email protected] >> > >>>>>>>>>>>>>> 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 >> > >>>>>>>>>>>>>> >> > >>>>>>>>>>>>>> >> > >>>>>> >> > >>>>>> >> > >>>>> >> > >> >> > >> >> > >> >> > > >> > >> >
