You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tapestry.apache.org by Patrick Casey <pa...@adelphia.net> on 2005/11/19 19:33:55 UTC

A Bit of Profiling Goodness

 

            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!".


Re: A Bit of Profiling Goodness

Posted by Massimo Lusetti <ml...@gmail.com>.
On 11/22/05, Patrick Casey <pa...@adelphia.net> wrote:

>         When it goes GA I'll probably run some tests on it, but I'm actually
> working on a project which is supposed to come out around new years so I
> need to stay on released code.

Well, I think you should start with 4 even if it's named beta right
now, plus that you could switch to release when it will be available
(not so far), looking at 4.0 as the unstable and untrusted branch is a
wrong assumption right now. We even may see RC pretty soon.
Read the archive and look at source changes to trust yourself.
I've not considered stupid "political" reasons.

>         My suspicion (speculation alert) is that the numbers for ognl will
> be similar though; You still need to do more or less the same number of sets
> and gets to render a page, regardless of what version of Tapestry you have
> in the back.

Has Howard states: "We should be seeing a lot less
use of OGNL and reflection already in 4.0 than in 3.0."

Ciao
--
Massimo

---------------------------------------------------------------------
To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tapestry-user-help@jakarta.apache.org


RE: A Bit of Profiling Goodness

Posted by Patrick Casey <pa...@adelphia.net>.
	When it goes GA I'll probably run some tests on it, but I'm actually
working on a project which is supposed to come out around new years so I
need to stay on released code.

	My suspicion (speculation alert) is that the numbers for ognl will
be similar though; You still need to do more or less the same number of sets
and gets to render a page, regardless of what version of Tapestry you have
in the back.

	--- Pat

> -----Original Message-----
> From: Massimo Lusetti [mailto:mlusetti@gmail.com]
> Sent: Tuesday, November 22, 2005 3:20 AM
> To: Tapestry users
> Subject: Re: A Bit of Profiling Goodness
> 
> On 11/22/05, Patrick Casey <pa...@adelphia.net> wrote:
> 
> >         Ack, sorry I didn't include that. Tapestry 3.0.3.
> 
> I would really like to see this kind of test with 4.0
> 
> --
> Massimo
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: tapestry-user-help@jakarta.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tapestry-user-help@jakarta.apache.org


Re: A Bit of Profiling Goodness

Posted by Massimo Lusetti <ml...@gmail.com>.
On 11/22/05, Patrick Casey <pa...@adelphia.net> wrote:

>         Ack, sorry I didn't include that. Tapestry 3.0.3.

I would really like to see this kind of test with 4.0

--
Massimo

---------------------------------------------------------------------
To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tapestry-user-help@jakarta.apache.org


RE: A Bit of Profiling Goodness

Posted by Patrick Casey <pa...@adelphia.net>.
	Ack, sorry I didn't include that. Tapestry 3.0.3.

	--- Pat

> -----Original Message-----
> From: Howard Lewis Ship [mailto:hlship@gmail.com]
> Sent: Monday, November 21, 2005 7:51 PM
> To: Tapestry users
> Subject: Re: A Bit of Profiling Goodness
> 
> And again ... was this Tapestry 3 or Tapestry 4?
> 
> On 11/21/05, Patrick Casey <pa...@adelphia.net> wrote:
> >
> >         A couple of things:
> >
> >         Compiled expressions make a huge difference; I have a bit of egg
> on
> > my face in this regard. 100000 runs of the same compiled ognl expression
> run
> > significantly faster than the beanutils (100 or so ms). Unfortunately,
> that
> > still doesn't help to explain where the time is being burned in
> production.
> >
> >         I definitely am not disabling the cache, but just to be
> > double-secret sure I ran the profiler again and stuck a breakpoint in
> the
> > expression initializer. The expressions get initialized on first page
> render
> > and we never stop there again, so we're definitely yanking subsequent
> page
> > renders out of the pool. Additionally, I've been profiling renders 2..6
> > typically so as not to pollute the profile with the page creation (I'm
> more
> > interested in runtime performance).
> >
> >         I can't seem to find the source code for ognl on open symphony,
> > otherwise I could dive right in and see what is going on here, but what
> I
> > can say is this:
> >
> >         To render the page 5 times, Tapestry calls
> >
> >         Ognl.getValue(<parsed expression>, <context>, <root>) 955 times.
> >         These 955 evaluations take a total of 493 ms.
> >
> >         It also calls
> >         Ognl.setValue(<parsed expression>, <context>, <root>) 1,070
> times
> >         These 1,070 evaluations take a total of 540 ms
> >
> >         So we're looking at about 0.5 ms/OGNL call on my setup.
> >
> >         Total time (CPU) to render the page (5X), from the time we hit
> the
> > Servlet's doGet method is 2,006 ms, meaning we're spending just over
> half of
> > the total page render time inside of OGNL. Prior to my ognl dot pruning,
> it
> > was more like 3.5 seconds for 5 renders, of which 2.4 second of it was
> spent
> > inside of OGNL.
> >
> >         It's not a Tapestry bug that I can see e.g. you're absolutely
> right
> > in that you are compiling the expressions, but even with the compiled
> > expressions that's still where the time is being burned.
> >
> >         So all my profiling is telling me the OGNL is the point of
> attack to
> > improve tapestry performance. Unfortunately, your pointing out that
> you're
> > *already* compiling the expressions, and my sandbox testing to the
> effect
> > that compiled ognl expressions, at least compared to the obvious
> > alternatives, are actually pretty fast, has me scratching my head.
> >
> >         Because, *if* OGNL isn't inherently slow and, instead, we're
> running
> > up against the unalterable wall of the java reflection API, *then* you
> > byte-code enhancement approach may be the only solution. After my first
> > round of sandbox testing though, I'd begun to let myself hope there
> might be
> > a silver bullet out there. Now, I'm quite a bit less confident.
> >
> >         --- Pat
> >
> > > -----Original Message-----
> > > From: Howard Lewis Ship [mailto:hlship@gmail.com]
> > > Sent: Monday, November 21, 2005 3:19 PM
> > > To: Tapestry users
> > > Subject: Re: A Bit of Profiling Goodness
> > >
> > > Wondering if you could also try OGNL using compiled expressions?  That
> > > may be the problem.  Tapestry compiles the expressions with OGNL
> > > before using them (and caches the compiled expressions).
> > >
> > > Also (please forgive me) on your live app, was caching disabled?  With
> > > caching disabled, the OGNL cache will be cleared at the end of each
> > > request, forcing it to re-introspect as well.
> > >
> > <snip>
> >
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
> > For additional commands, e-mail: tapestry-user-help@jakarta.apache.org
> >
> >
> 
> 
> --
> 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: tapestry-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: tapestry-user-help@jakarta.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tapestry-user-help@jakarta.apache.org


Re: A Bit of Profiling Goodness

Posted by Howard Lewis Ship <hl...@gmail.com>.
And again ... was this Tapestry 3 or Tapestry 4?

On 11/21/05, Patrick Casey <pa...@adelphia.net> wrote:
>
>         A couple of things:
>
>         Compiled expressions make a huge difference; I have a bit of egg on
> my face in this regard. 100000 runs of the same compiled ognl expression run
> significantly faster than the beanutils (100 or so ms). Unfortunately, that
> still doesn't help to explain where the time is being burned in production.
>
>         I definitely am not disabling the cache, but just to be
> double-secret sure I ran the profiler again and stuck a breakpoint in the
> expression initializer. The expressions get initialized on first page render
> and we never stop there again, so we're definitely yanking subsequent page
> renders out of the pool. Additionally, I've been profiling renders 2..6
> typically so as not to pollute the profile with the page creation (I'm more
> interested in runtime performance).
>
>         I can't seem to find the source code for ognl on open symphony,
> otherwise I could dive right in and see what is going on here, but what I
> can say is this:
>
>         To render the page 5 times, Tapestry calls
>
>         Ognl.getValue(<parsed expression>, <context>, <root>) 955 times.
>         These 955 evaluations take a total of 493 ms.
>
>         It also calls
>         Ognl.setValue(<parsed expression>, <context>, <root>) 1,070 times
>         These 1,070 evaluations take a total of 540 ms
>
>         So we're looking at about 0.5 ms/OGNL call on my setup.
>
>         Total time (CPU) to render the page (5X), from the time we hit the
> Servlet's doGet method is 2,006 ms, meaning we're spending just over half of
> the total page render time inside of OGNL. Prior to my ognl dot pruning, it
> was more like 3.5 seconds for 5 renders, of which 2.4 second of it was spent
> inside of OGNL.
>
>         It's not a Tapestry bug that I can see e.g. you're absolutely right
> in that you are compiling the expressions, but even with the compiled
> expressions that's still where the time is being burned.
>
>         So all my profiling is telling me the OGNL is the point of attack to
> improve tapestry performance. Unfortunately, your pointing out that you're
> *already* compiling the expressions, and my sandbox testing to the effect
> that compiled ognl expressions, at least compared to the obvious
> alternatives, are actually pretty fast, has me scratching my head.
>
>         Because, *if* OGNL isn't inherently slow and, instead, we're running
> up against the unalterable wall of the java reflection API, *then* you
> byte-code enhancement approach may be the only solution. After my first
> round of sandbox testing though, I'd begun to let myself hope there might be
> a silver bullet out there. Now, I'm quite a bit less confident.
>
>         --- Pat
>
> > -----Original Message-----
> > From: Howard Lewis Ship [mailto:hlship@gmail.com]
> > Sent: Monday, November 21, 2005 3:19 PM
> > To: Tapestry users
> > Subject: Re: A Bit of Profiling Goodness
> >
> > Wondering if you could also try OGNL using compiled expressions?  That
> > may be the problem.  Tapestry compiles the expressions with OGNL
> > before using them (and caches the compiled expressions).
> >
> > Also (please forgive me) on your live app, was caching disabled?  With
> > caching disabled, the OGNL cache will be cleared at the end of each
> > request, forcing it to re-introspect as well.
> >
> <snip>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: tapestry-user-help@jakarta.apache.org
>
>


--
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: tapestry-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tapestry-user-help@jakarta.apache.org


RE: A Bit of Profiling Goodness

Posted by Patrick Casey <pa...@adelphia.net>.
	A couple of things:

	Compiled expressions make a huge difference; I have a bit of egg on
my face in this regard. 100000 runs of the same compiled ognl expression run
significantly faster than the beanutils (100 or so ms). Unfortunately, that
still doesn't help to explain where the time is being burned in production. 

	I definitely am not disabling the cache, but just to be
double-secret sure I ran the profiler again and stuck a breakpoint in the
expression initializer. The expressions get initialized on first page render
and we never stop there again, so we're definitely yanking subsequent page
renders out of the pool. Additionally, I've been profiling renders 2..6
typically so as not to pollute the profile with the page creation (I'm more
interested in runtime performance).

	I can't seem to find the source code for ognl on open symphony,
otherwise I could dive right in and see what is going on here, but what I
can say is this:

	To render the page 5 times, Tapestry calls 

	Ognl.getValue(<parsed expression>, <context>, <root>) 955 times.
	These 955 evaluations take a total of 493 ms.

	It also calls
	Ognl.setValue(<parsed expression>, <context>, <root>) 1,070 times
	These 1,070 evaluations take a total of 540 ms

	So we're looking at about 0.5 ms/OGNL call on my setup.
	
	Total time (CPU) to render the page (5X), from the time we hit the
Servlet's doGet method is 2,006 ms, meaning we're spending just over half of
the total page render time inside of OGNL. Prior to my ognl dot pruning, it
was more like 3.5 seconds for 5 renders, of which 2.4 second of it was spent
inside of OGNL.

	It's not a Tapestry bug that I can see e.g. you're absolutely right
in that you are compiling the expressions, but even with the compiled
expressions that's still where the time is being burned. 

	So all my profiling is telling me the OGNL is the point of attack to
improve tapestry performance. Unfortunately, your pointing out that you're
*already* compiling the expressions, and my sandbox testing to the effect
that compiled ognl expressions, at least compared to the obvious
alternatives, are actually pretty fast, has me scratching my head.

	Because, *if* OGNL isn't inherently slow and, instead, we're running
up against the unalterable wall of the java reflection API, *then* you
byte-code enhancement approach may be the only solution. After my first
round of sandbox testing though, I'd begun to let myself hope there might be
a silver bullet out there. Now, I'm quite a bit less confident.

	--- Pat
	
> -----Original Message-----
> From: Howard Lewis Ship [mailto:hlship@gmail.com]
> Sent: Monday, November 21, 2005 3:19 PM
> To: Tapestry users
> Subject: Re: A Bit of Profiling Goodness
> 
> Wondering if you could also try OGNL using compiled expressions?  That
> may be the problem.  Tapestry compiles the expressions with OGNL
> before using them (and caches the compiled expressions).
> 
> Also (please forgive me) on your live app, was caching disabled?  With
> caching disabled, the OGNL cache will be cleared at the end of each
> request, forcing it to re-introspect as well.
> 
<snip>



---------------------------------------------------------------------
To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tapestry-user-help@jakarta.apache.org


Re: A Bit of Profiling Goodness

Posted by Howard Lewis Ship <hl...@gmail.com>.
Wondering if you could also try OGNL using compiled expressions?  That
may be the problem.  Tapestry compiles the expressions with OGNL
before using them (and caches the compiled expressions).

Also (please forgive me) on your live app, was caching disabled?  With
caching disabled, the OGNL cache will be cleared at the end of each
request, forcing it to re-introspect as well.

On 11/21/05, Patrick Casey <pa...@adelphia.net> wrote:
>
>         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:hlship@gmail.com]
> > 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 <pa...@adelphia.net> 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: tapestry-user-unsubscribe@jakarta.apache.org
> > For additional commands, e-mail: tapestry-user-help@jakarta.apache.org
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: tapestry-user-help@jakarta.apache.org
>
>


--
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: tapestry-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tapestry-user-help@jakarta.apache.org


RE: A Bit of Profiling Goodness

Posted by Patrick Casey <pa...@adelphia.net>.
	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:hlship@gmail.com]
> 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 <pa...@adelphia.net> 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: tapestry-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: tapestry-user-help@jakarta.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: tapestry-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tapestry-user-help@jakarta.apache.org


Re: A Bit of Profiling Goodness

Posted by Howard Lewis Ship <hl...@gmail.com>.
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 <pa...@adelphia.net> 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: tapestry-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tapestry-user-help@jakarta.apache.org