blob: 3e78cfc0cd5d3596024319c185354ed0c05718ef [file] [log] [blame]
<!DOCTYPE html>
<html lang="en">
<head>
<meta charset="UTF-8">
<title>EJB Request Logging</title>
<meta name="description" content="Apache TomEE">
<meta name="author" content="Apache TomEE">
<meta name="google-translate-customization" content="f36a520c08f4c9-0a04e86a9c075ce9-g265f3196f697cf8f-10">
<meta http-equiv="Pragma" content="no-cache">
<meta http-equiv="Expires" content="0">
<meta http-equiv="Cache-Control" content="no-store, no-cache, must-revalidate, max-age=0">
<!-- Le HTML5 shim, for IE6-8 support of HTML elements -->
<!--[if lt IE 9]>
<script src="http://html5shim.googlecode.com/svn/trunk/html5.js"></script>
<![endif]-->
<!-- Le styles -->
<link href="./resources/css/bootstrap.css" rel="stylesheet">
<link href="./resources/css/prettify.css" rel="stylesheet">
<!--link href="./resources/css/bootstrap-mods.css" rel="stylesheet"-->
<link href="./resources/css/main.css" rel="stylesheet">
<link href="./resources/font-awesome-4.6.3/css/font-awesome.min.css" rel="stylesheet">
<script type="text/javascript">
var t = encodeURIComponent(document.title.replace(/^\s+|\s+$/g,""));
var u = encodeURIComponent(""+document.URL);
function fbshare () {
window.open(
"http://www.facebook.com/sharer/sharer.php?u="+u,
'Share on Facebook',
'width=640,height=426');
};
function gpshare () {
window.open(
"https://plus.google.com/share?url="+u,
'Share on Google+',
'width=584,height=385');
};
function twshare () {
window.open(
"https://twitter.com/intent/tweet?url="+u+"&text="+t,
'Share on Twitter',
'width=800,height=526');
};
function pinshare () {
window.open("//www.pinterest.com/pin/create/button/?url="+u+"&media=http%3A%2F%2Ftomee.apache.org%2Fresources%2Fimages%2Ffeather-logo.png&description="+t,
'Share on Pinterest',
'width=800,height=526');
};
</script>
<!-- Le fav and touch icons -->
<link rel="shortcut icon" href="./favicon.ico">
<link rel="apple-touch-icon" href="./resources/images/apple-touch-icon.png">
<link rel="apple-touch-icon" sizes="72x72" href="./resources/images/apple-touch-icon-72x72.png">
<link rel="apple-touch-icon" sizes="114x114" href="./resources/images/apple-touch-icon-114x114.png">
<script src="./resources/js/prettify.js" type="text/javascript"></script>
<script src="./resources/js/jquery-latest.js"></script>
<script src="http://platform.twitter.com/widgets.js" type="text/javascript"></script>
<script src="./resources/js/common.js"></script>
<script src="./resources/js/prettyprint.js"></script>
<!--script src="//assets.pinterest.com/js/pinit.js" type="text/javascript" async></script//-->
<script type="text/javascript">
var _gaq = _gaq || [];
_gaq.push(['_setAccount', 'UA-2717626-1']);
_gaq.push(['_setDomainName', 'apache.org']);
_gaq.push(['_trackPageview']);
(function() {
var ga = document.createElement('script'); ga.type = 'text/javascript'; ga.async = true;
ga.src = ('https:' == document.location.protocol ? 'https://ssl' : 'http://www') + '.google-analytics.com/ga.js';
var s = document.getElementsByTagName('script')[0]; s.parentNode.insertBefore(ga, s);
})();
</script>
</head>
<body>
<div class="topbar" data-dropdown="dropdown">
<div class="fill">
<div class="container">
<a class="brand" href="./index.html">Apache TomEE</a>
<ul class="nav">
<li class="dropdown">
<a class="dropdown-toggle" data-toggle="dropdown" href="#">
Apache
<b class="caret"></b>
</a>
<ul class="dropdown-menu">
<!-- <li><a href="./misc/whoweare.html">Who we are?</a></li> -->
<!-- <li><a href="./misc/heritage.html">Heritage</a></li> -->
<li><a href="http://www.apache.org">Apache Home</a></li>
<!-- <li><a href="./misc/resources.html">Resources</a></li> -->
<li><a href="./misc/contact.html">Contact</a></li>
<li><a href="./misc/legal.html">Legal</a></li>
<li><a href="http://www.apache.org/foundation/sponsorship.html">Sponsorship</a></li>
<li><a href="http://www.apache.org/foundation/thanks.html">Thanks</a></li>
<li class="divider"/>
<li><a href="http://www.apache.org/security">Security</a></li>
</ul>
</li>
<li><a href="./index.html">Home</a></li>
<li><a href="./downloads.html">Downloads</a></li>
<li><a href="./documentation.html">Documentation</a></li>
<li><a href="./examples-trunk/index.html">Examples</a></li>
<li><a href="./support.html">Support</a></li>
<li><a href="./contribute.html">Contribute</a></li>
<li><a href="./security/index.html">Security</a></li>
</ul>
<!-- Google CSE Search Box Begins -->
<FORM class="pull-right" id="searchbox_010475492895890475512:_t4iqjrgx90" action="http://www.google.com/cse">
<INPUT type="hidden" name="cx" value="010475492895890475512:_t4iqjrgx90">
<INPUT type="hidden" name="cof" value="FORID:0">
<INPUT size="18" width="130" style="width:130px" name="q" type="text" placeholder="Search">
</FORM>
<!--<SCRIPT type="text/javascript" src="http://www.google.com/coop/cse/brand?form=searchbox_010475492895890475512:_t4iqjrgx90"></SCRIPT>-->
<!-- Google CSE Search Box Ends -->
</div>
</div>
</div>
<div class="container">
<div class="page-header">
<small><a href="./index.html">Home</a></small><br>
<h1>EJB Request Logging
<div style="float: right; position: relative; bottom: -10px; ">
<a onclick="javascript:gpshare()" class="gp-share sprite" title="Share on Google+">share [gp]</a>
<a onclick="javascript:fbshare()" class="fb-share sprite" title="Share on Facebook">share [fb]</a>
<a onclick="javascript:twshare()" class="tw-share sprite" title="Share on Twitter">share [tw]</a>
<a onclick="javascript:pinshare()" class="pin-share sprite" title="Share on Pinterest">share [pin]</a>
<a data-toggle="modal" href="#edit" class="edit-page" title="Contribute to this Page">contribute</a>
</div>
</h1>
</div>
<p>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.</p>
<h2>Client-side</h2>
<p>On the client requests/responses are logged on java.util.logging <code>FINEST</code> level in category <code>OpenEJB.client</code>. The code is similar to the following:</p>
<pre><code>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);
</code></pre>
<p>Note that the check to see if FINEST is enabled is cached for performance reasons, so it must be set at VM startup.</p>
<h2>Server-side</h2>
<p>On the server requests/responses are logged in java.util.logging <code>FINE</code> in category<code>"OpenEJB.server.remote.ejb</code>. The code for that
is similar to this:</p>
<pre><code>logger.fine("EJB REQUEST: " + req + " -- RESPONSE: " + res);
</code></pre>
<h2>Request times</h2>
<p>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:</p>
<ul>
<li><strong>Container time</strong> -- this is the raw time of invoking the bean including its
interceptors and any transaction begin/commit time. This time is effectively "business logic".</li>
<li><strong>Server time</strong> -- 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.</li>
<li><strong>Client time</strong> -- 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.</li>
</ul>
<p>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.</p>
<h2>Bean-time and JMX Statistics</h2>
<p>The above information applies purely to remote EJB calls made over a network. Calls on <code>@Remote</code> or <code>@Local</code> interfaces between two components in the same server are not logged.</p>
<p>However, <strong>all</strong> EJB invocations to business methods <em>or</em> callbacks like <code>@PostConstruct</code> are tracked for statistical analysis.
By default a floating window of 2000 samples are kept. The time tracked is purely <strong>bean time</strong> which includes
interceptors, decorators and the bean itself, but does not include other container services like transactions or security. </p>
<p>This information is available in JMX. A sample JMX ObjectName for a <code>CounterBean</code> will look like this:</p>
<pre><code>openejb.management:J2EEServer=openejb,J2EEApplication=null,EJBModule=StatsModule,StatelessSessionBean=CounterBean,j2eeType=Invocations,name=CounterBean
</code></pre>
<p>All beans have the following MBean attributes, listed here in shorthand:</p>
<ul>
<li>javax.management.MBeanAttributeInfo[description=, name=InvocationCount, type=long, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=InvocationTime, type=long, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=MonitoredMethods, type=long, read-only, descriptor={}]</li>
<li>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={}]</li>
</ul>
<p>Then for every method there will be these attributes and operations:</p>
<ul>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Count, type=long, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().GeometricMean, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Kurtosis, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Max, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Mean, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Min, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile01, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile10, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile25, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile50, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile75, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile90, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Percentile99, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().SampleSize, type=int, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Skewness, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().StandardDeviation, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Sum, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Sumsq, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanAttributeInfo[description=, name=someMethod().Variance, type=double, read-only, descriptor={}]</li>
<li>javax.management.MBeanOperationInfo[description=, name=someMethod().setSampleSize, returnType=void, signature=[javax.management.MBeanParameterInfo[description=, name=p1, type=int, descriptor={}]], impact=unknown, descriptor={}]</li>
<li>javax.management.MBeanOperationInfo[description=, name=someMethod().sortedValues, returnType=[D, signature=[], impact=unknown, descriptor={}]</li>
<li>javax.management.MBeanOperationInfo[description=, name=someMethod().values, returnType=[D, signature=[], impact=unknown, descriptor={}]</li>
</ul>
<div id="edit" class="modal hide fade in" style="display: none; ">
<div class="modal-header">
<a class="close" data-dismiss="modal">x</a>
<h3>Thank you for contributing to the documentation!</h3>
</div>
<div class="modal-body">
<h4>Any help with the documentation is greatly appreciated.</h4>
<p>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 :)</p>
<small>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.</small>
<!--[if gt IE 6]>
<h4>Internet Explorer Users</h4>
<p>If you are not an Apache committer, click the Yes link and enter a <i>anonymous</i> for the username and leave the password empty</p>
<![endif]-->
</div>
<div class="modal-footer">
Do you have an Apache ID?
<a href="javascript:void(location.href='https://cms.apache.org/redirect?uri='+escape(location.href))" class="btn">Yes</a>
<a href="javascript:void(location.href='https://anonymous:@cms.apache.org/redirect?uri='+escape(location.href))" class="btn">No</a>
</div>
</div>
<script src="./resources/js/bootstrap-modal.js"></script>
<footer>
<p>Copyright &copy; 1999-2016 The Apache Software Foundation, Licensed under the Apache License, Version 2.0.
Apache TomEE, TomEE, Apache, the Apache feather logo, and the Apache TomEE project logo are trademarks of The Apache Software Foundation.
All other marks mentioned may be trademarks or registered trademarks of their respective owners.</p>
</footer>
</div> <!-- /container -->
<!-- Javascript
================================================== -->
<!-- Placed at the end of the document so the pages load faster -->
<script src="./resources/js/bootstrap-dropdown.js"></script>
</body>
</html>