I can send you the actual profiling log if you wat (as an html
tree). Even after extensive efforts on my part to reduce the amount of OGNL
being called (statement pruning, writing and using my switch ... case
component instead of @conditional or @contrib:Choose), ognl is still
accounting for about 50% of all the cpu cycles on this particular page
render.
This is a page backed by a (fairly well cached) hibernate data tree
with about 50 persistent objects behind it as well so, while these renders
are satisfying out of L2 cache, we're still talking about a real, live page
with real live data from a fairly typial persistence framework behind it.
Likewise, even on my other pages, with less complex rendering rules,
I'm still seeing a huge chunk of my render time going down the OGNL rathole.
My operating theory is that OGNL is doing something foolish with
introspection, like not caching the results of
Object.getClass().getMethods() so it's doing a full introspection for every
set/get. Without downloading the OGNL source though, I can't be sure what's
going on, but the performance I'm seeing with OGNL is pretty grim.
For completeness sake, I also ran the same exact introspection test
three times:
10,000 simple gets using some old home brew introspection code
10,000 simple gets using the Apache BeanUtils library
10,000 simple gets using the OGNL library
HomeBrew Time: 250 ms
Beanutil Time: 190 ms (drat, apache beat me)
OGNL Time: 18,136 ms (no, I did *not* drop two decimal points
Yes, that's right, OGNL is roughly 100 times slower than beanutils
at a simple property get.
Here's the test code (which, unfortunately, requires some of my
utilities, but you can see this isn't a cooked example:
User u = new User();
u.setFirstName("Pat");
u.setManager(u);
Clock c = new Clock();
Wrapper w = new Wrapper(u);
for (int x = 0; x < 100000; x++) {
w.getFieldAsString("firstName");
}
Log.debug("Total time using wrapper= " + c);
c = new Clock();
for (int x = 0; x < 100000; x++) {
PropertyUtils.getSimpleProperty(u, "firstName");
}
Log.debug("Total beanutil time = " + c);
c = new Clock();
for (int x = 0; x < 100000; x++) {
Ognl.getValue("firstName",u);
}
Log.debug("Total ognl time = " + c);
Its just plain dog slow :(.
--- Pat
> -----Original Message-----
> From: Howard Lewis Ship [mailto:[EMAIL PROTECTED]
> Sent: Monday, November 21, 2005 1:06 PM
> To: Tapestry users
> Subject: Re: A Bit of Profiling Goodness
>
> Still, numbers like "46%" are hard to take out of context.
>
> Really, the question is: "How much time is spent in OGNL and is it
> affecting performance/scalability?"
>
> Not sure how to qualify this. Seems to me that smarter transaction
> management, better queries, and good caching will always be better
> investments than getting rid of OGNL. I'm very happy with the
> tapestry-prop library for providing another option.
>
> Were these tests on Tapestry 3 or 4? We should be seeing a lot less
> use of OGNL and reflection already in 4.0 than in 3.0. For example,
> in 3.0, Tapestry used reflection to move values from IBinding
> instances to component parameter properties. Ouch! In 4.0, Tapestry
> writes Java code (via Javassist) to do the same thing, and to better
> optimizes when and if properties are read.
>
> On 11/19/05, Patrick Casey <[EMAIL PROTECTED]> wrote:
> >
> >
> > Last week's discussion on whether or not OGNL was a dead
> project
> > inspired me to actually dig up a profiler and spend a bit of time
> profiling
> > one of my tapestry 3.0.3 apps under tomcat. I was curious to see where
> my
> > CPU time was going when I ran the thing as it wasn't quite as "snappy"
> as
> > I'd hoped.
> >
> >
> >
> > To my surprise (as I assumed such calls so infrequent as
> > efficiency doesn't matter), OGNL does, indeed, appear to be something of
> a
> > significant performance boat anchor.
> >
> >
> >
> > In my App:
> >
> >
> >
> > 35% of all CPU time spent on just two ognl functions:
> > ognl.Ognl.getValue() ongl.Ognl.setValue()
> >
> > 45.7% of all CPU time was spent on one or another ognl
> function
> >
> >
> >
> > And that's a database with heavy database access through
> > Hibernate although without a whole lot of complex server-side
> application
> > logic; it's mostly DB & presentation.
> >
> >
> >
> > I don't know how this meshes up with Howard's own internal
> > profiling that he references on his Blog post, but for my app, in my
> > environment, I'd say OGNL is definitely a major culprit.
> >
> >
> >
> > --- Pat
> >
> >
> >
> > PS As always, your mileage may vary with any profiling.
> > Different apps in different environments will burn CPU on different
> things,
> > so I wouldn't necessarily try to use this as evidence for a global
> argument
> > that "ognl is the suxor always and everywhere!".
> >
> >
> >
>
>
> --
> Howard M. Lewis Ship
> Independent J2EE / Open-Source Java Consultant
> Creator, Jakarta Tapestry
> Creator, Jakarta HiveMind
>
> Professional Tapestry training, mentoring, support
> and project work. http://howardlewisship.com
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [EMAIL PROTECTED]
> For additional commands, e-mail: [EMAIL PROTECTED]
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
