Re: WO and Memory Management
Re: WO and Memory Management
- Subject: Re: WO and Memory Management
- From: Chuck Hill <email@hidden>
- Date: Fri, 14 Jul 2006 10:55:09 -0700
Hi Owen,
Comments in-line below.
On Jul 13, 2006, at 10:11 PM, Owen McKerrow wrote:
Hi All,
We are setting up an application of ours on a clients server,
they did some stress testing to see if they needed a bigger box
and discovered something strange.
Their comments ....
The webobjects versions have been stress tested further, we
are getting ok
results but far worse then I was hoping. RIS Public faired
worse the RIS
with it starting to get error with only 5 simultaneous users
making simple
request 5 seconds apart (running with 2 instances each with -
mx512M.
That is odd. Are you dispatching requests concurrently?
No, getting them to retest with it on.
That should make a considerable difference, unless the app is
doing a lot of EOF activity.
A major point of interest is that garbage collection does not
appear to be
active for these instances.
Check for I/O and DB usage. How long does the average request
take to process?
From the stats page :
Transactions 691
Active Session 0
Average transactions 5.031
Averegae idle 131.627
Five seconds on average is, IMHO, way too long.
Mine 2 :)
Either all of your actions are a little slow or some are very
slow. Sight unseen, my money is on the latter. Usually this is
the result of DB access,
either queries that are slow to evaluate due to missing indexes
DOH ! **Hits self in the head** Thats one thing I need to do when
there DBA gets back from holidays :) We moved the DB from OpenBase
to Oracle and we haven't been back an applied indexing yet : )
That would cause problems. :-)
or lots of single row queries due to a lack of batch faulting and
pre-fetching in the application.
I have fiddled with it today. At the beginning of the day it looked
like (Note this a request for a page that loads a displaygroup to
display every publication I have in the DB and the stats before are
for the first time it is accessed for the app ) :
09:45:42,150 DEBUG [WorkerThread0] (PublicationsList:48 <init>) -
Publication Constructor
09:45:43,188 DEBUG [WorkerThread0] (PublicationsList:149
updatePublicationListing) - Update Pubs
09:45:45,001 DEBUG [WorkerThread0] (PublicationsList:208
updatePublicationListing) - End Update Pubs.762 total Pubs
09:45:48,257 OFF [WorkerThread0] (Log.NSLogOut:1546 appendln) -
Now asleep
After my tweaks ( the biggest time saver here was changing to use
EOSharedEditingContext, as its a read only ap ) :
13:32:53,295 DEBUG [WorkerThread0] (PublicationsList:48 <init>) -
Publication Constructor
13:32:54,174 DEBUG [WorkerThread0] (PublicationsList:143
updatePublicationListing) - Update Pubs for Faculty of Education
13:32:54,920 DEBUG [WorkerThread0] (PublicationsList:196
updatePublicationListing) - End Update Pubs.762 total Pubs
13:32:58,467 OFF [WorkerThread0] (Log.NSLogOut:1546 appendln) -
Now asleep
So between the constructor ( line 1 ) and the time the Pubs have
been loaded (line 3) went from 2.8 seconds to 1.6 ( and will
hopefully get faster once I index **Hits self in the head again**)
But the biggest time is between the end of the
updatePublicationsList() and sleep(). I need to do some further
testing to see if Im grabbing more objects from the DB ( as you
said "lots of single row queries.") or its because of the actual
page itself. The site has a quotation style engine in it which
basically on the fly changes the way in which a publication is
displayed. This is what suspect is chewing up time. The other
reason I think this may be the case is the time between line 3 and
line 4 doesn't change when I come back to the page i.e. the EO's
should be in memory, but the time to "render" the page seems to be
the same.
I think you have reached the correct conclusion there.
Are you a Project Wonder user?
Nope, always wonder, never plunged. It may be my pet project while
Im at WWDC this year.
That sounds like another T-Shirt idea for Mike Schrag: Have you
WONDERed? or Always WONDER!
Any volunteer tutors ? :)
There is a class in there that will log out all queries that take
longer than X seconds to return. That is a good way of finding
slow queries. If not, I can dig out a similar class. I thought
it was in Practical WebObjects, but I can't find it now.
If you remember where it is I would love a copy.
A more official release to follow, but for now http://
www.gvcsitemaker.com/chill/files/sqlloggingadaptorchanneldelegate.java
The case gets munged, so you will need to rename it as
SQLLoggingAdaptorChannelDelegate.java
For lots of single queries, the best way I have found is to just
turn on SQL logging and look at what is spit out. If you see
reams of queries one after the other, each returning a single row,
that is your problem.
I will also suggest that you add this to Application or modify
what is there:
/**
* Overidden to log RR loop and gather statistics.
*/
public WOResponse dispatchRequest(WORequest request) {
NSLog.out.appendln("=========== New Request: " +
request.uri());
NSLog.out.appendln("Headers: " + request.headers());
long startTime = System.currentTimeMillis();
WOResponse response = super.dispatchRequest(request);
long endTime = System.currentTimeMillis();
NSLog.out.appendln("Elapsed Time," + (endTime -
startTime) / 1000.0 + "," + request.uri());
NSLog.out.appendln("=========== End Request: " +
request.uri());
return response;
}
That will show you the time for each request. You can turn this
into a CSV file for Excel by grepping the log
grep Elapsed AppLog.log > elapsed.csv
That lets you sort by elapsed time to find the max and min and to
graph against time.
Thanks ! That will be very handy !
I can attest to that.
We ran the tests yesterday and the started to
consume over 500M per instance (2 instance running for RIS and
RISPublic).
This morning after no activity all night the process are still
using the
full memory set. To me this is a bit of a concern, can you
guys check your
side to see if it the same there, or if there is some
configuration options
that can be put in place to improve this?
The strange thing here is that the instances don't seem to be
releasing memory. Is this normal ? Is there a setting I need to
tweak somewhere in JavaMonitor ?
This is normal for the JVM on OS X. Once the JVM has allocated
memory, it does not return it to the OS until it terminates.
You can have the instances restart more often to return this
memory to the OS. 500M seems like a lot, but that depends on
what the app is doing.
Sorry forgot to mention its on a Solaris Machine running Vs 9. WO
5.2.4 ( witha 5.3 build if it makes any difference ).
IIRC, Solaris is the same in this respect. But the last time I
deployed on Solaris was with Java 1.2 so it has been a few
years. :-)
Does you app deal with a large amount of data that might explain
this memory footprint?
Yeah it does use alot of data. But as I said above I have now
switched to a shared editing context and that seems to have helped
alot ( at least on my dev machine ), ram seems to sit there at
around 75 Meg.
If it does turn out that WO doesn't release its hold on said memory
I guess a staged scheduled restart across a couple of instance is a
guaranteed fix :)
It is not WO, but that will fix it. It is really only useful if the
app only periodically uses a lot of memory. If it does that usually,
this will be a waste of time as the memory will go right back up.
Chuck
--
Coming sometime... - an introduction to web applications using
WebObjects and Xcode http://www.global-village.net/wointro
Practical WebObjects - for developers who want to increase their
overall knowledge of WebObjects or who are trying to solve specific
problems. http://www.global-village.net/products/practical_webobjects
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Webobjects-dev mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden