logging database access time
logging database access time
- Subject: logging database access time
- From: Kasper Frederiksen <email@hidden>
- Date: Tue, 17 Apr 2012 16:43:18 +0200
Hi All,
So I am looking for bottlenecks to explain slow response times in a Web Objects server application and I have come up with the following plan for monitoring database access. I am not sure this is the best way to do it, please let me know what you think.
I extend WOApplication and in the constructor I set a new delegate to the EODatabaseContext and add an observer to NSNotificationCenter:
---
MyDelegateAndObserver myDelegateAndObserver = ...
EODatabaseContext.setDefaultDelegate(myDelegateAndObserver);
NSNotificationCenter.defaultCenter().addObserver(
myDelegateAndObserver,
new NSSelector("hookIntoChannel", new Class[] {NSNotification.class}),
EODatabaseContext.DatabaseChannelNeededNotification,
null);
---
In the class MyDelegateAndObserver I defined "hookIntoChannel" from above and the methods to capture notifications:
---
public void hookIntoChannel(NSNotification not){
final EODatabaseContext dbctxt = (EODatabaseContext)not.object();
final EODatabaseChannel channel = new EODatabaseChannel(dbctxt);
if(channel != null){
channel.adaptorChannel().setDelegate(this);
dbctxt.registerChannel(channel);
}
}
public boolean adaptorChannelShouldEvaluateExpression(EOAdaptorChannel channel, EOSQLExpression _expression_){
/* thread safe logging: start of database round trip */
return true;
}
public void adaptorChannelDidEvaluateExpression(EOAdaptorChannel channel, EOSQLExpression _expression_){
/* thread safe logging: end of database round trip iif _expression_ is UPDATE or INSERT */
}
public NSArray databaseContextDidFetchObjects(EODatabaseContext dbCtxt, NSArray results, EOFetchSpecification fetchSpec, EOEditingContext ec){
/* threadsafe logging: end of database round trip for SELECT */
return null;
}
---
I store the above logging in a java.lang.ThreadLocal and once the WO request is about to return (listen for WOApplication.ApplicationDidDispatchRequestNotification) I can sum up the number of database accesses and the total time spent waiting for database IO.
Two thing worry me about this approach:
1) I am overwriting the DatabaseContext default delegate with a custom delegate that will always answer adaptorChannelShouldEvaluateExpression=true
2) What kind of overhead am I looking at here ... I suppose I will find out, but does this look like the kind of code you would include in a production environment application?
I appreciate your input
-Kasper Frederiksen
ps.
I could not find this in the documentation so this is based on empirical evidence :). This is the life cycle of a database access as seen from the notifications sent to DatabaseContext and AdaptorChannel. I have noted where I have chosen to consider the closest points to the start/end of the database IO for the purpose of logging time spent.
For a SQL SELECT
===
1) databaseContextShouldFetchObjects:
2) databaseContextShouldSelectObjects:
3) adaptorChannelShouldSelectAttributes:
4) adaptorChannelShouldEvaluateExpression: start of database access
5) adaptorChannelDidEvaluateExpression:
6) adaptorChannelDidSelectAttributes:
7) adaptorChannelWillFetchRow:
8) adaptorChannelDidFetchRow: 7 and 8 may be repeated a number of times
7) adaptorChannelWillFetchRow:
9) adaptorChannelDidFinishFetching:
10) databaseContextDidFetchObjects: end of database access
For a SQL UPDATE or INSERT
===
1) adaptorChannelWillPerformOperations:
4) adaptorChannelShouldEvaluateExpression: start of database access
5) adaptorChannelDidEvaluateExpression: end of database access
6) adaptorChannelDidPerformOperations:
_______________________________________________
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