Both client-side and server-side request logging is supported and includes various invocation times aimed at helping to identify where time
is going in a request.
Client-side
On the client requests/responses are logged on java.util.logging FINEST level in category OpenEJB.client. The code is similar to the following:
final long time = System.nanoTime() - start;
final String message = String.format("Invocation %sns - %s - Request(%s) - Response(%s)", time, conn.getURI(), req, res);
logger.log(Level.FINEST, message);
Note that the check to see if FINEST is enabled is cached for performance reasons, so it must be set at VM startup.
Server-side
On the server requests/responses are logged in java.util.logging FINE in category"OpenEJB.server.remote.ejb. The code for that
is similar to this:
Three times are tracked per request and logged in the above statements as part of the formatting of the EJB Response. They're best understood in reverse:
Container time -- this is the raw time of invoking the bean including its
interceptors and any transaction begin/commit time. This time is effectively "business logic".
Server time -- this timer starts the (nano)second the request is seen by the server and
the (nano)second the response is actually written. The serverTime minus the containerTime will
effectively show you how long serialization and deserialization is taking pre request.
Client time -- entire begin to end including attempting to contact the server and fully reading the response. The clientTime minus the serverTime will show network latency for the most part.
The container time and server time are written in the EJB response and visible to the client. The client will log all three times, the server will log the first two. All log statements are on a single line.
Bean-time and JMX Statistics
The above information applies purely to remote EJB calls made over a network. Calls on @Remote or @Local interfaces between two components in the same server are not logged.
However, all EJB invocations to business methods or callbacks like @PostConstruct are tracked for statistical analysis.
By default a floating window of 2000 samples are kept. The time tracked is purely bean time which includes
interceptors, decorators and the bean itself, but does not include other container services like transactions or security.
This information is available in JMX. A sample JMX ObjectName for a CounterBean will look like this:
Any help with the documentation is greatly appreciated.
All edits are reviewed before going live, so feel free to do much more than fix typos or links. If you see a page that could benefit from an entire rewrite, we'd be thrilled to review it. Don't be surprised if we like it so much we ask you for help with other pages :)
NOTICE: unless indicated otherwise on the pages in question, all editable content available from apache.org is presumed to be licensed under the Apache License (AL) version 2.0 and hence all submissions to apache.org treated as formal Contributions under the license terms.