= EJB Request Logging
:index-group: EJB
:jbake-date: 2018-12-05
:jbake-type: page
:jbake-status: published

NOTE: 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:

[source,java]
----
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:

[source,java]
----
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:

[source,properties]
----
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=\{}]