Preloader image

EJB Request Logging

Licensed to the Apache Software Foundation (ASF) under one or more contributor license agreements. See the NOTICE file distributed with this work for additional information regarding copyright ownership. The ASF licenses this file to you under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. You may obtain a copy of the License at . http://www.apache.org/licenses/LICENSE-2.0 . Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License.

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:

logger.fine("EJB REQUEST: " + req + " -- RESPONSE: " + res);

Request times

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:

openejb.management:J2EEServer=openejb,J2EEApplication=null,EJBModule=StatsModule,StatelessSessionBean=CounterBean,j2eeType=Invocations,name=CounterBean

All beans have the following MBean attributes, listed here in shorthand:

  • javax.management.MBeanAttributeInfo[description=, name=InvocationCount, type=long, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=InvocationTime, type=long, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=MonitoredMethods, type=long, read-only, descriptor=\{}]

  • javax.management.MBeanOperationInfo[description=, name=FilterAttributes, returnType=void, signature=[javax.management.MBeanParameterInfo[description="", name=excludeRegex, type=java.lang.String, descriptor=\{}], javax.management.MBeanParameterInfo[description="", name=includeRegex, type=java.lang.String, descriptor=\{}]], impact=unknown, descriptor=\{}]

Then for every method there will be these attributes and operations:

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Count, type=long, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().GeometricMean, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Kurtosis, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Max, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Mean, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Min, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile01, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile10, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile25, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile50, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile75, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile90, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile99, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().SampleSize, type=int, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Skewness, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().StandardDeviation, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Sum, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Sumsq, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanAttributeInfo[description=, name=someMethod().Variance, type=double, read-only, descriptor=\{}]

  • javax.management.MBeanOperationInfo[description=, name=someMethod().setSampleSize, returnType=void, signature=[javax.management.MBeanParameterInfo[description=, name=p1, type=int, descriptor=\{}]], impact=unknown, descriptor=\{}]

  • javax.management.MBeanOperationInfo[description=, name=someMethod().sortedValues, returnType=[D, signature=[], impact=unknown, descriptor=\{}]

  • javax.management.MBeanOperationInfo[description=, name=someMethod().values, returnType=[D, signature=[], impact=unknown, descriptor=\{}]