Op Framework

The Op Framework

The Op Framework is a lightweight, command-pattern Java framework for web application servers providing additional functionality around JDBC access. The namesake of the framework is the "Op" base class that encapsulates inputs and outputs to some piece of business logic. Database access is streamlined in Ops to provide easy access to stored procedures and parameterized queries. Logging of access is built-in.

Tracking in the Op Framework identifies the end user responsible for the Http Request, and the developers responsible for the code servicing the request. All database calls are timed and logged with their parameters. Requests are timed and logged along with the resources they used over the course of their lifetime. With tracking, here is a sampling of you can track:

For each request:

The end-user responsible for the request
The module of your application responsible for servicing the request
Number of connections used
Number of database calls made
Number of database rows returned across all calls
Total time spent in the database
Total time spent waiting for connections from connection pools

For each database call:

Time spent executing the request and retrieving the output
The parameterized text of the call
The value-populated text of the call
The number of rows returned
The class that made the call

The issues that these statements helped us to address:

We could see most database requests but couldn't tell what work was done during a single request. It turned out that a lot of queries were duplicated or could otherwise be simplified.
Logging was inconsistent:

Our DBA needed parameters to look into Oracle CBO issues, and sometimes parameters were not logged.
We didn't know how many rows individual queries were returning. Some were returning a lot and hogging network IO.
We couldn't load our log files into a database for analysis or bug investigations.

Database calls made to common code were being logged in the wrong place. It was difficult to see that one part of the application was misusing another part of the application written by another team.
Some requests were asking for so many connections from the connection pool, we didn't know how much time overall the request spent waiting for those connections.

Tracing works with tracking and extends it, allowing developers to include messages to be returned in HTML output.

Here is an example of tracing output returned to the HTML for a single request:

	START TRACE: 8675309-11-200701211328 at 2007-01-21 13:28:35,057
	~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
	2007-21-01 13:28:35,057  example                         8675309-11-200701211328 adding trace appender to org.example
	2007-21-01 13:28:35,057  wgen                            8675309-11-200701211328 adding trace appender to net.wgen
	2007-21-01 13:28:35,057  TraceLogger                     8675309-11-200701211328 Evaluated loggers in 0 ms
	2007-21-01 13:28:35,057  TraceTrigger                    8675309-11-200701211328 Trace initialized Sun Jan 21 13:28:35 EST 2007
	2007-21-01 13:28:35,073  OpManagerBean                   8675309-11-200701211328 EJB Executing Op: org.example.finance.ProjectTimesheetsOp
	2007-21-01 13:28:35,073  FinanceModule                   CX-TIME ]-[ 0 ms ]-[ DataSource: java:/OPFINANCEDS ]-[ null ]-[ 8675309-11-200701211328 ]-[
	2007-21-01 13:28:35,104  ProjectTimesheetsOp             DB-TIME ]-[ 31 ms ]-[ (rs1 1 records) (rs2 64 records) (total 65 records) ]-[ _traceKey=8675309-11-200701211328, _opModule=FINANCE, _opOwner=ProjectTimesheetsOp, _text={call sp_project_time( 1)} ]-[ 8675309-11-200701211328 ]-[
	2007-21-01 13:28:35,104  ProjectTimesheetsOp             OP-TIME ]-[ 31 ms ]-[ work=null ]-[ ProjectTimesheetsOp@16de641[_projectSid=1,_rootOp=,_defaultDataSourceName=java:/OPFINANCEDS] ]-[ 8675309-11-200701211328 ]-[
	2007-21-01 13:28:35,104  OpManagerBean                   EJB-TIME ]-[ 31 ms ]-[ org.example.finance.ProjectTimesheetsOp ]-[ null ]-[ 8675309-11-200701211328 ]-[
	2007-21-01 13:28:35,104  ProjectTimesheetAction          8675309-11-200701211328 returned from Op, adding data to request
	2007-21-01 13:28:35,104  TraceTrigger                    8675309-11-200701211328 RequestExecutionInfo{_totalRowsRetrieved=65, _totalConnectionsUsed=1, _totalDatabaseCallsMade=1, _totalTime=62, _totalTimeInDatabase=31, _error=false, _errMsg='null'}
	~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
	END TRACE: 8675309-11-200701211328 at 2007-01-21 13:28:35,104

The issues that this tracing functionality helped us to address:

Developers, made aware of some problem in production had to ssh to the webserver and tail application logs. This captures the log statements and returns them to the end-user.
Good tracing statements help our QA and Help Desk contribute more to identifying issues, and capturing a scenario as it's happening to forward to development for resolution.