| = 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=\{}] |