tag:blogger.com,1999:blog-68524713275552828692024-03-13T08:24:16.582-07:00From Applications to Infrastructureapp-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.comBlogger14125tag:blogger.com,1999:blog-6852471327555282869.post-48581735041256183312013-04-13T22:59:00.002-07:002013-04-13T23:05:24.386-07:00Pitfalls of Handling Large String Objects in JavaMost Java developers know to be careful about String concatenation. But some argue that it is less important nowadays with improved JVM garbage collection efficiency. That might be true for small objects, but for<strong> large String objects,</strong> which is common when dealing with <strong>web services</strong> and <strong>xmls</strong>, developers need to be even more careful with String operations in general, and not just concatenation.<br />
<br />
<h3>
OOM in Production, Why?</h3>
<br />
I recently looked into an OutOfMemory exception in production and the culprit turned out to be the following code.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEiXEdYqDlNrfFT_jQo6L_-xmU1pn6QSmn3Ukb341zDdylRREcduy98chJj2CkDv0kqUVHyoZQRqUzwKVTE4fZrxpbkwDPrsHxrIcg26bOpVc_xTge_xXr77-x3XWbzSE39ycsFKfHMBH4Y/s1600/replaceAll.gif" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" bua="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEiXEdYqDlNrfFT_jQo6L_-xmU1pn6QSmn3Ukb341zDdylRREcduy98chJj2CkDv0kqUVHyoZQRqUzwKVTE4fZrxpbkwDPrsHxrIcg26bOpVc_xTge_xXr77-x3XWbzSE39ycsFKfHMBH4Y/s1600/replaceAll.gif" /></a></div>
<br />
<a name='more'></a>The application receives a response from a web service and needs to pass the result as a String into a field to a downstream web service. The downstream web service was old, and doesn't support prefixes. So a developer writes the above code to remove prefixes and also change a field name. Not an ideal situation but Innocent enough? <br />
<br />
However, when the return xml from the first web service turns out to be pretty big, in the size of ~200k, it causes frequent OutOfMemory exceptions in production servers. 200k is pretty big for simple texts, but still, the server has 1.5G heap size, why is it OutOfMemory?<br />
<br />
<h3>
Java String Impementation is NOT Optimized for Large String</h3>
<br />
JVM hates large objects. The heap may have enough space, but it is always highly fragmented. When a large object request comes in, JVM will usually go through a series of gc cycles to move objects around to accomodate the large object. In my case, it is unfortunate that the input String is huge already, ~200k, the above code makes even more copies of it, stressing out JVM and resulting in OOM.<br />
<br />
In the above code, each parse result is a new large String, which makes it 4 additional large objects. But that is not ALL! More large objects were allocated in Java's String implementation.<br />
<br />
<ul>
<li><h4>
replaceAll is not optimized for large Strings</h4>
</li>
</ul>
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEju7fXlF3tcE4cntrEluyZYht9AW1ddaYlqEXxXiAmuz7L5S_lw13bPTDaOKMBfDJ3zN7M5NA1S1Ygph4sqeoWjzID-HPms1SwjX_8vCYtBVib7cJQWJughSdizhRTN1ybxNhAvxR9e2kM/s1600/replaceAll-matcher.gif" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" bua="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEju7fXlF3tcE4cntrEluyZYht9AW1ddaYlqEXxXiAmuz7L5S_lw13bPTDaOKMBfDJ3zN7M5NA1S1Ygph4sqeoWjzID-HPms1SwjX_8vCYtBVib7cJQWJughSdizhRTN1ybxNhAvxR9e2kM/s1600/replaceAll-matcher.gif" /></a></div>
String's replaceAll method eventually invokes replaceAll in <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">java.util.regex.Matcher</span> as listed above. Its implementation, as explained below, is not optimized for large Strings. <br />
<ul>
<li><h4>
Always specify size when StringBuffer is created for large Strings </h4>
</li>
</ul>
First of all, when replaceAll creates the StringBuffer, it uses the default constructor, which only allocates 16 bytes, perfect for small Strings.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhf3w-Fgm1RRrCb4Mh-rcZCsK96DyfnIsG-vezhqO0XFpw4wNgjKB-yu27LQMT-SOxGMWFRLHMuvjHV9g-DbU2SSgqpx_C0YhqH2WrYDN_J6Xn5jZJbYiHo3TBKFwnnpei5oSLquawm2Wo/s1600/StringBuffer-new.gif" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" bua="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhf3w-Fgm1RRrCb4Mh-rcZCsK96DyfnIsG-vezhqO0XFpw4wNgjKB-yu27LQMT-SOxGMWFRLHMuvjHV9g-DbU2SSgqpx_C0YhqH2WrYDN_J6Xn5jZJbYiHo3TBKFwnnpei5oSLquawm2Wo/s1600/StringBuffer-new.gif" /></a></div>
As more charecters are appended to it, the StringBuffer will double its size when it reaches its limit.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh233J8DyXCLe0qz5Xtxw4YbLuwH2hMb8uypg4reu7uIRxQ-CTwRioSxLZ4nIe0MyqpcuxSNXdrna6YwMnD8mawltvI-0eZa3k50AvXx9rGUBNK5KGbyp7fwtToqYxv_iU4f5ZIMwi4Lfw/s1600/StringBuffer-exapnd.gif" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" bua="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh233J8DyXCLe0qz5Xtxw4YbLuwH2hMb8uypg4reu7uIRxQ-CTwRioSxLZ4nIe0MyqpcuxSNXdrna6YwMnD8mawltvI-0eZa3k50AvXx9rGUBNK5KGbyp7fwtToqYxv_iU4f5ZIMwi4Lfw/s1600/StringBuffer-exapnd.gif" /></a></div>
This means, in our case, replaceAll will generate garbage objects in the size of 16, 32, ... 32k, 64k, 128k, 256k when it finishes its parsing. 32k, 64k, 128k objects are all very large objects from the garbage collection's point of view.<br />
<br />
<ul>
<li><h4>
For large Strings, StringBuffer.toString() is bad, use new String(StringBuffer) instead</h4>
</li>
</ul>
Secondly, when replaceAll returns, it uses StringBuffer.toString(). Following is the source code for StringBuffer.toString().<br />
<br />
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhGgXu9f2EwWbs-O60KCCyPj-Dq530YntHgeuNPeZbE4LvwJZE6L2I42cWGOwLG9FUUInKrmgUpgQofOmTWqiFWHouYsAipehlWOGLV3KCGwET0TmhMm_1fAGDcRiZP0kS4l_T8QKw6jRQ/s1600/StringBuffer-toString.gif" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" bua="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhGgXu9f2EwWbs-O60KCCyPj-Dq530YntHgeuNPeZbE4LvwJZE6L2I42cWGOwLG9FUUInKrmgUpgQofOmTWqiFWHouYsAipehlWOGLV3KCGwET0TmhMm_1fAGDcRiZP0kS4l_T8QKw6jRQ/s1600/StringBuffer-toString.gif" /></a><br />
It checks the size of wasted bytes: if it is more than 768, it uses a different String constructor to make another copy of its underlying char array to free up 'wasted' space.<br />
<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi_r0cwJE3txPW85J-f1_qNEswOR-hDsgsY7vq9dPkttkhDYdwxANogo5Jbgvkl6FbKcY4jUHe5RTkWVcaVtrLwkSh0Q34BS-avjPkBc-Op_VguyPWnhwHdWOFW7HD93sS0JFiN-1m7R3A/s1600/String-new.gif" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" bua="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi_r0cwJE3txPW85J-f1_qNEswOR-hDsgsY7vq9dPkttkhDYdwxANogo5Jbgvkl6FbKcY4jUHe5RTkWVcaVtrLwkSh0Q34BS-avjPkBc-Op_VguyPWnhwHdWOFW7HD93sS0JFiN-1m7R3A/s1600/String-new.gif" /></a></div>
For large Strings, wasting 768 bytes is nothing compred to the overhead of allocating another large object from the heap. new String(StringBuffer sb) on the other hand, simply re-uses the char arrary in the StringBuffer object.<br />
<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgOSY6hn59DCEstFO9k_jnFPjHekP330L4l5uDV_hyZ4D3-PoCsTo69MxtyKcXBGq4gK6p2GWvpEY8QsGFyLGlu3xLdUe5YbfuqYJKzFSsbI6GUgoxUcyt1oS2zsh093Cx9_1qbINVH5jM/s1600/String-StringBuffer.gif" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" bua="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgOSY6hn59DCEstFO9k_jnFPjHekP330L4l5uDV_hyZ4D3-PoCsTo69MxtyKcXBGq4gK6p2GWvpEY8QsGFyLGlu3xLdUe5YbfuqYJKzFSsbI6GUgoxUcyt1oS2zsh093Cx9_1qbINVH5jM/s1600/String-StringBuffer.gif" /></a></div>
<br />
<ul>
<li><h4>
Always be extra careful with large Strings, read Java's source code when in doubt</h4>
</li>
</ul>
Java may change its Java implementation in later versions, if you are not sure, read source code. If you cannot avoid large String objects for whatever reason, treat it with extra care. The difference between generating 2 large objects vs 20 can mean mutliple gc cycles of the expensive kind, and in our case, OutOfMemory exception. <br />
<h3>
</h3>
<h3>
Code Optimized </h3>
<br />
Eventually we decided to parse the String manually instead of using replaceAll. This allows us to transform the input String in one single pass and avoid generating additional large Java objects.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh7a2VjrVw_hOg5KCDNrVAdTGU1rTJI8ofMhU5XuvZPRhGQQTuPsCdqHdYsqpnwvuV6i4CxnZ5AmkNur_cNaiTqTDRI4t8fSwiKgAu5e-k5YaQYvUtdO43537OWg4sHMywDEhOLWujFsHU/s1600/final.gif" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" bua="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh7a2VjrVw_hOg5KCDNrVAdTGU1rTJI8ofMhU5XuvZPRhGQQTuPsCdqHdYsqpnwvuV6i4CxnZ5AmkNur_cNaiTqTDRI4t8fSwiKgAu5e-k5YaQYvUtdO43537OWg4sHMywDEhOLWujFsHU/s1600/final.gif" /></a></div>
app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com2tag:blogger.com,1999:blog-6852471327555282869.post-52803110137097885402012-10-16T21:29:00.000-07:002012-10-17T11:30:15.110-07:00Log4j Behaviour in Tomcat and WebSphereLogging is the interface between developers and system admin. Developers need to know how their logging code behave in a server envrionment. Admins need to know how to configure and turn on/off logging. This series inspects how two most common logging methods, Java Util Logging and Log4j, behave in Tomcat and WebSphere.<br />
<ul>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-java-se.html">Java Util Logging Behaviour in Java SE</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-tomcat.html">Java Util Logging Behaviour in Tomcat</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-websphere.html">Java Util Logging Behaviour in WebSphere</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/log4j-behaviour-in-tomcat-and-websphere.html">Log4j behaviour in Tomcat and WebSphere</a></li>
</ul>
<br />
<a name='more'></a>Contrary to Java Util Logging, log4j is not part of the JDK. You need to include log4j.jar in your classpath in order to use log4j logging. However, also because it is not part of the JDK, WebSphere and Tomcat don't use it for its own internal logging and it enables log4j's behaviour to be consistent across different platforms. This article inspects how log4j works.<br />
<br />
<h3>
1. Components of Log4j</h3>
<ul>
<li><h4>
The log4j jar file</h4>
</li>
</ul>
For web applications, you need to include a version of log4j jar, for example, log4j-1.2.12.jar, under WEB-INF\lib.<br />
<ul>
<li><h4>
Java Code </h4>
</li>
</ul>
<div>
</div>
<div>
</div>
<ul><ul>
<li>Create Loggers</li>
</ul>
</ul>
In the following log4j sample code, two loggers are created: the mainLogger <span style="color: #0000e6;">com.appinf <span style="color: black;">and a perfSubLogger </span><span style="color: #0000e6;">com.appinf.perf. </span></span><span style="color: black;"> This is to help us understand how log4j organizes loggers in a tree structure. </span><br />
<br />
It is almost identical to java util logging. The only difference is the type of Logger is <b><span style="color: #7f0055; font-size: x-small;"><span style="color: #7f0055; font-size: x-small;"></span></span></b><br />
<div align="left">
</div>
<span style="font-size: x-small;">org.apache.log4j.Logger <span style="font-size: small;">instead of </span><span style="font-size: x-small;">java.util.logging.Logger;</span></span><br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;"> static</span> Logger mainLogger = null<span style="color: #808030;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> Logger perfSubLogger = null<span style="color: #808030;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> <span style="color: purple;">{</span>
<span style="background-color: yellow;">mainLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf4j"</span><span style="color: #808030;">)</span></span><span style="color: purple;">;</span>
<span style="background-color: yellow;">perfSubLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf4j.perf"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span></span>
<span style="color: purple;">}</span></pre>
</blockquote>
<ul><ul>
<li>Logging</li>
</ul>
</ul>
Again, the code is almost identical to java util logging. <br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;"> final</span> long startTime = System.currentTimeMillis()<span style="color: #808030;">;</span>
<span style="background-color: yellow;">perfSubLogger.info</span>("JavaUtilLoggingSETest main Enter")<span style="color: #808030;">;</span>
<span style="background-color: yellow;">mainLogger.info</span>("JavaUtilLoggingSETest main Processing ... ")<span style="color: #808030;">;</span>
<span style="color: maroon; font-weight: bold;">final</span> long endTime = System.currentTimeMillis()<span style="color: #808030;">;</span>
<span style="background-color: yellow;">perfSubLogger.info</span>("JavaUtilLoggingSETest main Exit Total time : " + (endTime - startTime) + " ms.")<span style="color: #808030;">;</span></pre>
</blockquote>
<ul>
<li><h4>
log4j.properties</h4>
</li>
</ul>
A log4j.properties file has to be put in the classpath, usually directly under WEB-INF/classes. If not, you will see an error that states "No appenders could be found for logger (com.appinf4j.perf)" <span style="font-family: inherit; font-size: small;">and</span> "Please initialize the log4j system properly".<br />
.<br />
<br />
<span style="font-size: x-small;"><div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi9l4GbjMLVlNso0R5gMcYx8XeyyiJWD6dtdu7eHcB45yOt62J2gJT5km1Ddvq-Ti-49_xwjkMrSGKe3w9k-hNfPtPnbcAsxdTfDzys6yRqi0FepWBrGoi1IDHQAfA7QhyphenhyphenLiL1IU_q6y1w/s1600/log4j-was-noappender.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="80" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi9l4GbjMLVlNso0R5gMcYx8XeyyiJWD6dtdu7eHcB45yOt62J2gJT5km1Ddvq-Ti-49_xwjkMrSGKe3w9k-hNfPtPnbcAsxdTfDzys6yRqi0FepWBrGoi1IDHQAfA7QhyphenhyphenLiL1IU_q6y1w/s640/log4j-was-noappender.png" width="640" /></a></div>
<span style="font-size: small;">You can define a default logger (rootLogger) for the web application.</span><br /><br /><div align="left">
log4j.rootLogger=DEBUG,console<br />
log4j.appender.console=org.apache.log4j.ConsoleAppender<br />
log4j.appender.console.Target=System.out<br />
log4j.appender.console.Threshold=DEBUG<br />
log4j.appender.console.layout=org.apache.log4j.PatternLayout<br />
log4j.appender.console.layout.ConversionPattern=%d{yyyy.MM.dd-HH.mm.ss} [console] %-5p %c : %m%n</div>
</span><br />
<span style="font-size: x-small;"><div align="left">
</div>
<span style="font-size: small;">You can also configure a named logger (<span style="font-size: x-small;">log4j.logger.com.appinf4j</span>) to log to its own log file.</span><br /><br /><div align="left">
log4j.logger.com.appinf4j=DEBUG,appinfLog<br />
log4j.appender.appinfLog=org.apache.log4j.FileAppender<br />
log4j.appender.appinfLog.layout=org.apache.log4j.PatternLayout<br />
log4j.appender.appinfLog.Threshold=DEBUG<br />
log4j.appender.appinfLog.layout.ConversionPattern=%d{yyyy.MM.dd-HH.mm.ss} [appinfLog] %-5p %c : %m%n<br />
log4j.appender.appinfLog.File=logs/appinf.log</div>
</span><br />
<br />
There are several things to note here. <br />
<div>
</div>
<ul style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<li>If you are NOT using absolute path, it will use the profile home directory <strong>profiles\was70profile1 </strong>in WebSphere, or the directory where you run startup scripts for Tomcat. </li>
<li>A named logger (log4j.logger.com.appinf4j) will still log to its parent logger (the root logger in the above case, which in turn logs to the console). To disable it, you have to call <strong>setAdditivity</strong> to <strong>false</strong>.<br /><br /><pre style="background: #ffffff; color: black;">mainLogger.setAdditivity(false)<span style="color: #808030;">;</span></pre>
</li>
</ul>
<div>
</div>
<div>
</div>
<h3 align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
2. Log4j in Tomcat</h3>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<span style="background-color: yellow;">Usually, log4j jar and log4j.properties are packaged within the web app and log4j's behaviour is consistent across Tomcat and WebSphere</span>. However, there are two scenarios that Tomcat will modify default log4j behaviour.</div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<br /></div>
<ul>
<li><div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
Use Default Java Util Logging for Tomcat, but defined -Dlog4j.configuration </div>
</li>
</ul>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
if you follow recommendations by some popular <a href="http://logging.apache.org/log4j/1.2/manual.html">log4j documentation</a> on how to configure log4j with Tomcat, you may be in trouble.</div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<br /></div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
export TOMCAT_OPTS="-Dlog4j.configuration=<em>log4j-dev.properties</em>"</div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<br />
If this system level setting specificies a file name different than <strong>log4j.properties</strong>, as the case in the above example, it will interrup log4j's default behaviour. Even if you have <strong>log4j.properties </strong>under WEB-INF\classes, you may encounter errors like "No appenders could be found for logger (com.appinf4j.perf)" <span style="font-family: inherit; font-size: small;">and</span> "Please initialize the log4j system properly".</div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<br /></div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
My recommendation is to <span style="background-color: yellow;">leave log4j alone and <strong>DO NOT use -Dlog4j.configuration </strong>in Tomcat </span>unless it is well-communicated to developers.</div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<br /></div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<ul>
<li><div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
Customized Tomcat to use Log4j for System logging</div>
</li>
</ul>
</div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
Tomcat provides <a href="http://tomcat.apache.org/tomcat-6.0-doc/logging.html">documentation</a> on how to use log4j, instead of the default Java Util logging, for Tomcat internal logging. This puts log4j jar in the system directory and introduces an extra layer <span style="font-family: Courier New; font-size: x-small;">tomcat-juli-adapters.jar. </span>This will definitely affect log4j behaviour. I am not familiar with the setup and personally don't see any benefit by going through all these extra configurations. </div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<br /></div>
app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com0tag:blogger.com,1999:blog-6852471327555282869.post-51349300524250439702012-10-16T09:39:00.002-07:002012-10-17T08:01:16.708-07:00Java Util Logging Behaviour in WebSphereLogging is the interface between developers and system admin. Developers need to know how their logging code behave in a server envrionment. Admins need to know how to configure and turn on/off logging. This series inspects how two most common logging methods, Java Util Logging and Log4j, behave in Tomcat and WebSphere.<br />
<ul>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-java-se.html">Java Util Logging Behaviour in Java SE</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-tomcat.html">Java Util Logging Behaviour in Tomcat</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-websphere.html">Java Util Logging Behaviour in WebSphere</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/log4j-behaviour-in-tomcat-and-websphere.html">Log4j behaviour in Tomcat and WebSphere</a></li>
</ul>
<br />
<a name='more'></a>Java Util Logging is part of the JDK starting with version 6, which means that a web application can use it without including any additional jars in WEB-INF/lib. However, also because it is part of the JDK, WebSphere itself uses the library for internal logging. How to protect WebSphere internal logging from misconfiguration? WebSphere has implemented extra control over the Java Util Logging framework. This article inspects how Java Util Logging behaves in WebSphere.<br />
<br />
<h3>
1. Default Behaviour with Basic Logging Code</h3>
<ul>
<li><h4>
Basic Java Util Logging Code</h4>
</li>
</ul>
<br />
In the following java util logging sample code, two loggers are created: the mainLogger <span style="color: #0000e6;">com.appinf <span style="color: black;">and a perfSubLogger </span><span style="color: #0000e6;">com.appinf.perf. </span></span><span style="color: black;"> This is to help us understand how java util logging organizes loggers in a tree structure. <strong>No additional calls are made to customize these loggers</strong>. </span><br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;">public</span> <span style="color: maroon; font-weight: bold;">class</span> JavaUtilLoggingTestServlet <span style="color: maroon; font-weight: bold;">extends</span> HttpServlet <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">static</span> Logger mainLogger <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> Logger perfSubLogger <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> <span style="color: purple;">{</span>
<span style="background-color: yellow;">mainLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span></span>
<span style="background-color: yellow;">perfSubLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf.perf"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span></span>
<span style="color: purple;">}</span>
<span style="color: maroon; font-weight: bold;">protected</span> <span style="color: #bb7977;">void</span> process<span style="color: #808030;">(</span>HttpServletRequest request<span style="color: #808030;">,</span> HttpServletResponse response<span style="color: #808030;">)</span> <span style="color: maroon; font-weight: bold;">throws</span> ServletException<span style="color: #808030;">,</span> <span style="color: #bb7977; font-weight: bold;">IOException</span> <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">final</span> <span style="color: #bb7977;">long</span> startTime <span style="color: #808030;">=</span> <span style="color: #bb7977; font-weight: bold;">System</span><span style="color: #808030;">.</span>currentTimeMillis<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="background-color: yellow;">perfSubLogger<span style="color: #808030;">.</span>logp</span><span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"JavaUtilLoggingSETest"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"main"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Enter"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="background-color: yellow;">mainLogger<span style="color: #808030;">.</span>logp</span><span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"JavaUtilLoggingSETest"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"main"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Processing ... "</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">final</span> <span style="color: #bb7977;">long</span> endTime <span style="color: #808030;">=</span> <span style="color: #bb7977; font-weight: bold;">System</span><span style="color: #808030;">.</span>currentTimeMillis<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="background-color: yellow;">perfSubLogger<span style="color: #808030;">.</span>logp</span><span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"JavaUtilLoggingSETest"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"main"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Exit Total time : "</span> <span style="color: #808030;">+</span> <span style="color: #808030;">(</span>endTime <span style="color: #808030;">-</span> startTime<span style="color: #808030;">)</span> <span style="color: #808030;">+</span> <span style="color: #0000e6;">" ms."</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: #bb7977; font-weight: bold;">String</span> destination <span style="color: #808030;">=</span> <span style="color: #0000e6;">"/test.jsp"</span><span style="color: purple;">;</span>
getServletContext<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>getRequestDispatcher<span style="color: #808030;">(</span>destination<span style="color: #808030;">)</span><span style="color: #808030;">.</span>forward<span style="color: #808030;">(</span>request<span style="color: #808030;">,</span> response<span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span><span style="color: purple;">}</span></pre>
</blockquote>
<ul>
<li><h4>
How does Basic Logging Code Behave in WebSphere</h4>
</li>
</ul>
1. WebSphere Log Manager : <span style="font-family: Arial;"><span style="font-family: Times New Roman; font-size: x-small;">com.ibm.ws.bootstrap.WsLogManager</span></span><br />
<br />
In Java SE, <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">Logger<span style="color: #808030;">.</span>getLogger</span> invokes <span style="font-size: x-small;"><span style="font-family: "Courier New", Courier, monospace;">java.util.logging.LogManager, </span><span style="font-family: Times New Roman; font-size: small;">which creates all loggers within the JVM based on a .properties file. </span></span><span style="font-size: x-small;"><span style="font-family: Times New Roman; font-size: small;">WebSphere, however, uses java util logging for its own internal components, as complex and crucial as transactions, messaging etc., so it doesn't want users to have the <em>chance</em> to misconfigure the .properties file. Instead, it manages loggers using its own log manager by adding t</span></span><span style="font-size: x-small;"><span style="font-family: Times New Roman; font-size: small;">he following system property to all WebSphere jvms.</span></span><br />
<br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">-Djava.util.logging.manager=com.ibm.ws.bootstrap.WsLogManager</span><br />
<br />
2. Logging configuration is managed internally. I don't know of a .config file similiar to the one in Java SE or Tomcat.<br />
<br />
<span style="font-size: x-small;"><span style="font-size: small;">3. <span style="background-color: yellow;">By default, all loggers will log to System.out</span>.</span></span><br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEghNK_PjRYzDM1OrEAz6EWzu2x21KtheO45siVjSgGC4ebgIxeSBq_gnsMvvhRCyU3R_63C42SkEW50y_67_XFtpv3BS3ej9WjyDQ9uTa7CkSU2dURVfwk-pZXQs5Ny_72a2WlGfYfSH60/s1600/was-javautil-console.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="128" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEghNK_PjRYzDM1OrEAz6EWzu2x21KtheO45siVjSgGC4ebgIxeSBq_gnsMvvhRCyU3R_63C42SkEW50y_67_XFtpv3BS3ej9WjyDQ9uTa7CkSU2dURVfwk-pZXQs5Ny_72a2WlGfYfSH60/s640/was-javautil-console.png" width="640" /></a></div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
<span style="font-size: x-small;"><span style="font-size: small;">4. WebSphere does provide a nice interface to change the logging level through admin console.</span></span><br />
<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgVk3EHdzCn3LeFE7OswCi4ePXgIZn1pDYwdlllqFYq9FHpplPdbFiWnUFcAA8o0CaSmzhzKIQPMm4NwyTBQRpGMDpnw7Gvog2UzPgYAEShEL6Ce0aQO3fuAEhoCdNorOxSlUJJXIQfxe0/s1600/was-logging-cofigure.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgVk3EHdzCn3LeFE7OswCi4ePXgIZn1pDYwdlllqFYq9FHpplPdbFiWnUFcAA8o0CaSmzhzKIQPMm4NwyTBQRpGMDpnw7Gvog2UzPgYAEShEL6Ce0aQO3fuAEhoCdNorOxSlUJJXIQfxe0/s1600/was-logging-cofigure.png" /></a></div>
<div class="separator" style="clear: both; text-align: center;">
</div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
<br />
<h3>
<br />2. Customize : Log to application specific log files</h3>
<span style="background-color: yellow;">If the default behaviour is not what you want, and you want applications to write to their own logs, you can only do it in Java code</span>. This is documented in <a href="http://publib.boulder.ibm.com/infocenter/wsdoc400/v6r0/index.jsp?topic=/com.ibm.websphere.iseries.doc/info/ae/ae/rtrb_cbeusecustom.html">WAS Info Center</a>.<br />
<h4>
Add a FileHandler in Java Code. </h4>
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;">mainLogger.<strong><span style="background-color: white; color: #e06666;">setUseParentHandlers</span></strong>(false)<span style="color: #808030;">;</span>
if ( mainLogger.getHandlers().length == 0)<span style="color: purple;">{</span>
FileHandler fh <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">new</span> FileHandler<span style="color: #808030;">(</span><span style="color: #0000e6;">"logs"</span>
<span style="color: #808030;">+</span> <span style="color: #bb7977; font-weight: bold;">File</span><span style="color: #808030;">.</span>separator <span style="color: #808030;">+</span> <span style="color: #0000e6;">"com.appinf.log"</span><span style="color: #808030;">,</span> <span style="color: #008c00;">1024</span> <span style="color: #808030;">*</span> <span style="color: #008c00;">5000</span><span style="color: #808030;">,</span> <span style="color: #008c00;">10</span><span style="color: #808030;">,</span> <span style="color: maroon; font-weight: bold;">true</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
fh<span style="color: #808030;">.</span>setFormatter<span style="color: #808030;">(</span><span style="color: maroon; font-weight: bold;">new</span> SimpleFormatter<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
mainLogger<span style="color: #808030;">.</span>addHandler<span style="color: #808030;">(</span>fh<span style="color: #808030;">)</span><span style="color: purple;">;</span><span style="color: purple;">}</span></pre>
</blockquote>
<span style="color: #2a00ff; font-size: x-small;"><span style="color: #2a00ff; font-size: x-small;"></span></span><span style="font-size: x-small;"><div align="left">
</div>
</span>There are several things to note here.
<br />
<div>
</div>
<ul style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<li>If you are not using absolute path, it will use the profile home directory <strong>profiles\was70profile1. </strong>So the above code will log to profileHome\logs\com.appinf.log, ususally the right place to be. </li>
<li>Even though you specified a file handler, logs are still written to the parent logger, which is <strong>System.out</strong>. To disable it, you have to <strong>setUseParentHandlers</strong> to <strong>false</strong>.</li>
</ul>
<br />
<h3 align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
</h3>
app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com0tag:blogger.com,1999:blog-6852471327555282869.post-79272209456004838152012-10-15T12:21:00.000-07:002012-10-17T08:00:41.756-07:00Java Util Logging Behaviour in Tomcat Logging is the interface between developers and system admin. Developers need to know how their logging code behave in a server envrionment. Admins need to know how to configure and turn on/off logging. This series inspects how two most common logging methods, Java Util Logging and Log4j, behave in Tomcat and WebSphere.<br />
<ul>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-java-se.html">Java Util Logging Behaviour in Java SE</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-tomcat.html">Java Util Logging Behaviour in Tomcat</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-websphere.html">Java Util Logging Behaviour in WebSphere</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/log4j-behaviour-in-tomcat-and-websphere.html">Log4j behaviour in Tomcat and WebSphere</a></li>
</ul>
<br />
<a name='more'></a><br />
Java Util Logging is part of the JDK starting with version 6, which means that a web application can use it without including any additional jars in WEB-INF/lib. However, also because it is part of the JDK, Tomcat server itself uses the library for internal logging. How to make sure different web applications and the Tomcat server itself use Java Util Logging without interfering with each other? Tomcat has put in extra mechanism upon the Java Util Logging framework. This article inspects how Java Util Logging behaves in Tomcat.<br />
<br />
<h3>
1. Default Behaviour with Basic Logging Code</h3>
<ul>
<li><h4>
Basic Java Util Logging Code</h4>
</li>
</ul>
<br />
In the following java util logging sample code, two loggers are created: the mainLogger <span style="color: #0000e6;">com.appinf <span style="color: black;">and a perfSubLogger </span><span style="color: #0000e6;">com.appinf.perf. </span></span><span style="color: black;"> This is to help us understand how java util logging organizes loggers in a tree structure. <strong>No additional calls are made to customize these loggers</strong>. </span><br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;">public</span> <span style="color: maroon; font-weight: bold;">class</span> JavaUtilLoggingTestServlet <span style="color: maroon; font-weight: bold;">extends</span> HttpServlet <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">static</span> Logger mainLogger <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> Logger perfSubLogger <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> <span style="color: purple;">{</span>
<span style="background-color: yellow;">mainLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span></span>
<span style="background-color: yellow;">perfSubLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf.perf"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span></span>
<span style="color: purple;">}</span>
<span style="color: maroon; font-weight: bold;">protected</span> <span style="color: #bb7977;">void</span> process<span style="color: #808030;">(</span>HttpServletRequest request<span style="color: #808030;">,</span> HttpServletResponse response<span style="color: #808030;">)</span> <span style="color: maroon; font-weight: bold;">throws</span> ServletException<span style="color: #808030;">,</span> <span style="color: #bb7977; font-weight: bold;">IOException</span> <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">final</span> <span style="color: #bb7977;">long</span> startTime <span style="color: #808030;">=</span> <span style="color: #bb7977; font-weight: bold;">System</span><span style="color: #808030;">.</span>currentTimeMillis<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="background-color: yellow;">perfSubLogger<span style="color: #808030;">.</span>logp</span><span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"JavaUtilLoggingSETest"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"main"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Enter"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="background-color: yellow;">mainLogger<span style="color: #808030;">.</span>logp</span><span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"JavaUtilLoggingSETest"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"main"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Processing ... "</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">final</span> <span style="color: #bb7977;">long</span> endTime <span style="color: #808030;">=</span> <span style="color: #bb7977; font-weight: bold;">System</span><span style="color: #808030;">.</span>currentTimeMillis<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="background-color: yellow;">perfSubLogger<span style="color: #808030;">.</span>logp</span><span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"JavaUtilLoggingSETest"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"main"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Exit Total time : "</span> <span style="color: #808030;">+</span> <span style="color: #808030;">(</span>endTime <span style="color: #808030;">-</span> startTime<span style="color: #808030;">)</span> <span style="color: #808030;">+</span> <span style="color: #0000e6;">" ms."</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: #bb7977; font-weight: bold;">String</span> destination <span style="color: #808030;">=</span> <span style="color: #0000e6;">"/test.jsp"</span><span style="color: purple;">;</span>
getServletContext<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>getRequestDispatcher<span style="color: #808030;">(</span>destination<span style="color: #808030;">)</span><span style="color: #808030;">.</span>forward<span style="color: #808030;">(</span>request<span style="color: #808030;">,</span> response<span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span><span style="color: purple;">}</span></pre>
</blockquote>
<ul>
<li><h4>
How Does Basic Logging Code Behave in Tomcat</h4>
</li>
</ul>
1. Tomcat Log Manager : <span style="font-family: Arial; font-size: x-small;">ClassLoaderLogManager</span><br />
<br />
In Java SE, <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">Logger<span style="color: #808030;">.</span>getLogger</span> invokes <span style="font-size: x-small;"><span style="font-family: "Courier New", Courier, monospace;">java.util.logging.LogManager, </span><span style="font-family: Times New Roman; font-size: small;">which creates all loggers within the JVM based on a .properties file. In Tomcat, in order to better manage web-application level logging configurations, a new LogManger is created. Notice that the following system property is added to the command line by the tomcat startup script. (<span style="font-family: Courier New; font-size: x-small;">catalina.bat</span> or <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">catalina.sh)</span></span></span><br />
<br />
<div style="text-align: center;">
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"><span style="font-family: Arial, Helvetica, sans-serif; font-size: x-small;">-Djava.util.logging.manager=<strong>org.apache.juli.ClassLoaderLogManager</strong></span></span> </div>
<br />
<span style="font-size: x-small;"><span style="font-family: Times New Roman; font-size: small;">If </span></span><span style="font-size: x-small;"><span style="font-family: Times New Roman; font-size: small;"><span style="font-family: Courier New; font-size: x-small;">${catalina.base}/conf/logging.properties</span> exists, the startup script also adds the following command line parameter.<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"><span style="font-family: Times New Roman; font-size: small;"> </span></span></span></span><br />
<br />
<span style="font-family: Arial, Helvetica, sans-serif; font-size: x-small;">-Djava.util.logging.config.file=/software/Tomcat/apache-tomcat-7.0.25/conf/logging.properties</span><br />
<br />
<span style="font-family: inherit;">ClassLoaderLogManager reads the file if specified, otherwise it will use <span style="font-size: x-small;"><span style="font-family: Courier New;">${java.home}/lib/logging.properties.</span> </span><span style="font-size: small;">You can refer to <a href="http://tomcat.apache.org/tomcat-6.0-doc/logging.html">Tomcat Documentation</a> or <a href="http://www.javadocexamples.com/java_source/org/apache/juli/ClassLoaderLogManager.java.html">source code</a>. <span style="background-color: yellow;">If your Tomcat environment defined customized <span style="font-family: Courier New; font-size: x-small;">catalina.base</span> to support multiple instances, make sure <span style="font-family: Courier New; font-size: x-small;">${catalina.base}/conf/logging.properties</span> exists.</span> </span></span><br />
<strong><span style="font-family: Arial;"></span></strong><br />
<br />
2. Default Config File : <span style="font-family: Courier New; font-size: x-small;">${catalina.base}/conf/logging.properties</span> <br />
<br />
The <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">logging.properties</span> file shipped with Tomcat contains the following entries.<br />
<ul>
<li><span lang="EN"><span style="font-size: x-small;"><span lang="EN">.handlers = 1catalina.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler</span>handlers</span> </span></li>
</ul>
<span lang="EN">-- <em>by default, everything logs to console and a file</em></span><br />
<ul>
<li><span lang="EN"><span lang="EN"><span lang="EN" style="font-size: x-small;">1catalina.org.apache.juli.FileHandler.level = FINE<br />1catalina.org.apache.juli.FileHandler.directory = ${catalina.base}/logs<br />1catalina.org.apache.juli.FileHandler.prefix = catalina.</span></span></span></li>
</ul>
<em><span lang="EN">-- <em>that file is configured as above.</em></span></em><br />
<ul>
<li><span lang="EN"><span lang="EN"><span lang="EN"><span lang="EN" style="font-size: x-small;">org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].level = INFO<br />org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].handlers = 3manager.org.apache.juli.FileHandler<br />3manager.org.apache.juli.FileHandler.level = FINE<br />3manager.org.apache.juli.FileHandler.directory = ${catalina.base}/logs<br />3manager.org.apache.juli.FileHandler.prefix = manager</span></span></span></span></li>
</ul>
-- <em>Other name loggers are configured, but they don't affect our code.</em><br />
<br />
3. <span style="font-size: x-small;"><span style="font-size: small;">Because of 1 and 2, <span style="background-color: yellow;">under default setting, the logging statements in the sample code will write to both the <strong>console</strong> and <strong>catalina.out</strong>.</span></span></span> <br />
<br />
<ul>
<li>Catlina.out</li>
</ul>
<div>
</div>
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEj8Dx8AaJkMst-nqv9FQn4qQDjGbDKOJWMVO7bVNuvj55TacP1IxD3mR19IcQqxSb64LmrjYnYmm8m1H4gd2CrCM77c4qv9Wa_EcNYVGHdy0VMhjhdEjI-NvYsjhmaal-FTiKRrMgTFDkc/s1600/tomcat-javautil.log.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="218" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEj8Dx8AaJkMst-nqv9FQn4qQDjGbDKOJWMVO7bVNuvj55TacP1IxD3mR19IcQqxSb64LmrjYnYmm8m1H4gd2CrCM77c4qv9Wa_EcNYVGHdy0VMhjhdEjI-NvYsjhmaal-FTiKRrMgTFDkc/s640/tomcat-javautil.log.png" width="640" /></a></div>
<ul>
<li>Console</li>
</ul>
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEii6rrtWwzI9FgyOyq3rMkqgkyUu30WZxGBKwu2hOwE0jsBqV2B1U8JwtMPcexiqNyV6A8gL9QT3fQGWUTWPQqmKH-ZttaH3zQrASiliHHAs2x81fP6ZWfyS7fjHSs8RaOmnSTsb6KZf9M/s1600/tomcat-javautil.console.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="344" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEii6rrtWwzI9FgyOyq3rMkqgkyUu30WZxGBKwu2hOwE0jsBqV2B1U8JwtMPcexiqNyV6A8gL9QT3fQGWUTWPQqmKH-ZttaH3zQrASiliHHAs2x81fP6ZWfyS7fjHSs8RaOmnSTsb6KZf9M/s640/tomcat-javautil.console.png" width="640" /></a></div>
<div class="separator" style="clear: both; text-align: center;">
</div>
<br />
<h3>
<br />2. Customize : Log to application specific log file</h3>
<span style="background-color: yellow;"><span style="background-color: white;">If the default behaviour is not what you want, and</span> if you want applications to write to their own logs, there are three ways you can do it in Tomcat.</span><br />
<h4>
</h4>
<h4>
Method 1 : Modify <span style="font-family: Courier New; font-size: x-small;">${catalina.base}/conf/logging.properties</span> </h4>
Add the following entries to <span style="font-family: Courier New; font-size: x-small;">${catalina.base}/conf/logging.properties</span> .<br />
<br />
<span lang="EN" style="font-size: x-small;">handlers = 1catalina.org.apache.juli.FileHandler, 2localhost.org.apache.juli.FileHandler, 3manager.org.apache.juli.FileHandler, 4host-manager.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler,<strong><span style="color: red;">5appinf.org.apache.juli.FileHandler</span></strong></span><br />
<br />
<span lang="EN" style="font-size: x-small;">5appinf.org.apache.juli.FileHandler.level = FINE<br />5appinf.org.apache.juli.FileHandler.directory = ${catalina.base}/logs<br />5appinf.org.apache.juli.FileHandler.prefix = app-inf.</span><br />
<br />
<span lang="EN"><span style="font-size: x-small;">com.appinf.handlers = 5appinf.org.apache.juli.FileHandler<br />com.appinf.level = INFO</span></span><br />
<h4>
</h4>
<h4>
Method 2 : Add logging.properties file to a web app under WEB-INF\classes</h4>
<span style="font-size: x-small;">handlers = org.apache.juli.FileHandler</span><br />
<span style="font-size: x-small;">org.apache.juli.FileHandler.level = FINE<br />org.apache.juli.FileHandler.directory = ${catalina.base}/logs<br />org.apache.juli.FileHandler.prefix = app-inf.</span><br />
<br />
<span style="font-size: x-small;">com.appinf.level = INFO</span><br />
<span style="font-size: x-small;">com.appinf.perf.level = SEVERE</span><br />
<br />
The above lines define the web-app level root logger to log only to app-inf.*.log, and not the console, or catalinat.out<br />
<h4>
</h4>
<h4>
Method 3 : Same as Java SE, add a FileHandler in Java Code. </h4>
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;">mainLogger.<strong><span style="background-color: white; color: #e06666;">setUseParentHandlers</span></strong>(false)<span style="color: #808030;">;</span>
if ( mainLogger.getHandlers().length == 0)<span style="color: purple;">{</span>
FileHandler fh <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">new</span> FileHandler<span style="color: #808030;">(</span><span style="color: #0000e6;">"logs"</span>
<span style="color: #808030;">+</span> <span style="color: #bb7977; font-weight: bold;">File</span><span style="color: #808030;">.</span>separator <span style="color: #808030;">+</span> <span style="color: #0000e6;">"com.appinf.log"</span><span style="color: #808030;">,</span> <span style="color: #008c00;">1024</span> <span style="color: #808030;">*</span> <span style="color: #008c00;">5000</span><span style="color: #808030;">,</span> <span style="color: #008c00;">10</span><span style="color: #808030;">,</span> <span style="color: maroon; font-weight: bold;">true</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
fh<span style="color: #808030;">.</span>setFormatter<span style="color: #808030;">(</span><span style="color: maroon; font-weight: bold;">new</span> SimpleFormatter<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
mainLogger<span style="color: #808030;">.</span>addHandler<span style="color: #808030;">(</span>fh<span style="color: #808030;">)</span><span style="color: purple;">;</span><span style="color: purple;">}</span></pre>
</blockquote>
<span style="color: #2a00ff; font-size: x-small;"><span style="color: #2a00ff; font-size: x-small;"></span></span><span style="font-size: x-small;"><div align="left">
</div>
</span>There are several things to note here.
<br />
<div>
</div>
<ul style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<li>If you are not using absolute path, it will use the directory <strong>where you start tomcat</strong>. </li>
<li>Subdirectories have to exist beforehand.</li>
<li>Even though you specified a file handler, logs are still written to the parent logger. To disable it, you have to <strong>setUseParentHandlers</strong> to <strong>false</strong>.</li>
<li>You can still use <strong>Method 2</strong>. A web-app level root logger will be configured. If setUseParentHandlers<strong> </strong>to false, handlers defined in WEB-INF\classes\logging.properties will be <strong>ignored, </strong> unless you directly associate the handler with the mainLogger.</li>
<ul>
<li><span style="font-size: x-small;"><span lang="EN">com.appinf.handlers = org.apache.juli.FileHandler</span></span></li>
</ul>
</ul>
<br />
<h4 align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
Comparision of Method 1, 2 and 3</h4>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
For Developers :</div>
<ul>
<li><div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
In Method 2 and 3 described above, app team controls the configuration of the app's logging, whether it is by java code or WEB-INF\classes\<span style="font-family: Courier New; font-size: x-small;">logging.properties</span>. </div>
</li>
<li><div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
WEB-INF\classes\<span style="font-family: Courier New; font-size: x-small;">logging.properties </span>is Tomcat specific, enabled by Tomcat's <span style="font-family: Arial; font-size: x-small;">ClassLoaderLogManager.</span></div>
</li>
<li><div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
Java code is probably more universal if you may need to migrate from Tomcat to WebSphere, or vice versa. </div>
</li>
</ul>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
For System admin :</div>
<ul>
<li><div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
In all three Methods described above, you have ways to redirect where application logs or change logging levels. This may become handy in trouble-shooting.</div>
</li>
<li><div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
You may not want to take up the task of configuring logging for each web-app, however, you canmonitor catalina.out to mandate apps follow your logging policy.</div>
</li>
</ul>
app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com4tag:blogger.com,1999:blog-6852471327555282869.post-85400891272412065422012-10-15T12:03:00.001-07:002012-10-17T07:57:08.456-07:00Java Util Logging and Log4j Behaviour in Tomcat and WebSphereLogging is the interface between developers and system admin. Developers need to know how their logging code behave in a server envrionment. Admins need to know how to read logging.properties and log4j.properties, configure them and turn on/off logging. This series inspects how two most common logging methods, Java Util Logging and Log4j, behave in Tomcat and WebSphere.<br />
<ul>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-java-se.html">Java Util Logging Behaviour in Java SE</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-tomcat.html">Java Util Logging Behaviour in Tomcat</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/java-util-logging-behaviour-in-websphere.html">Java Util Logging Behaviour in WebSphere</a></li>
<li><a href="http://app-inf.blogspot.com/2012/10/log4j-behaviour-in-tomcat-and-websphere.html">Log4j behaviour in Tomcat and WebSphere</a></li>
</ul>
<br />
<a name='more'></a><h2>
</h2>
<h3>
Java Util Logging Behaviour in Java SE</h3>
<br />
<br />
Java Util Logging is part of the JDK starting with version 6, which means that you don't need any jars to use it. This article inspects how Java Util Logging behaves in a Java Standard Edition environment.<br />
<br />
<h3>
1. Default Behaviour with Basic Logging Code</h3>
<ul>
<li><h4>
Let's Start with Basic Logging Code</h4>
</li>
</ul>
In the following java util logging sample code, two loggers are created: the mainLogger <span style="color: #0000e6;">com.appinf <span style="color: black;">and a perfSubLogger </span><span style="color: #0000e6;">com.appinf.perf. </span></span><span style="color: black;"> This is to help us understand how java util logging organizes loggers in a tree structure. </span><br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;">public</span> <span style="color: maroon; font-weight: bold;">class</span> JavaUtilLoggingSETestNoHandlers <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">static</span> Logger perfSubLogger <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> Logger mainLogger <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> <span style="color: purple;">{</span>
<span style="background-color: yellow;">mainLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span></span>
<span style="background-color: yellow;">perfSubLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf.perf"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span></span>
<span style="color: purple;">}</span>
<span style="color: maroon; font-weight: bold;">public</span> <span style="color: maroon; font-weight: bold;">static</span> <span style="color: #bb7977;">void</span> main<span style="color: #808030;">(</span><span style="color: #bb7977; font-weight: bold;">String</span><span style="color: #808030;">[</span><span style="color: #808030;">]</span> args<span style="color: #808030;">)</span> <span style="color: maroon; font-weight: bold;">throws</span> <span style="color: #bb7977; font-weight: bold;">IOException</span> <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">final</span> <span style="color: #bb7977;">long</span> startTime <span style="color: #808030;">=</span> <span style="color: #bb7977; font-weight: bold;">System</span><span style="color: #808030;">.</span>currentTimeMillis<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="background-color: yellow;">perfSubLogger<span style="color: #808030;">.</span>logp</span><span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"JavaUtilLoggingSETest"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"main"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Enter"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="background-color: yellow;">mainLogger<span style="color: #808030;">.</span>logp</span><span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"JavaUtilLoggingSETest"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"main"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Processing ... "</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">final</span> <span style="color: #bb7977;">long</span> endTime <span style="color: #808030;">=</span> <span style="color: #bb7977; font-weight: bold;">System</span><span style="color: #808030;">.</span>currentTimeMillis<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="background-color: yellow;">perfSubLogger<span style="color: #808030;">.</span>logp</span><span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"JavaUtilLoggingSETest"</span><span style="color: #808030;">,</span><span style="color: #0000e6;">"main"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Exit Total time : "</span> <span style="color: #808030;">+</span> <span style="color: #808030;">(</span>endTime <span style="color: #808030;">-</span> startTime<span style="color: #808030;">)</span> <span style="color: #808030;">+</span> <span style="color: #0000e6;">" ms."</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span><span style="color: purple;">}</span></pre>
</blockquote>
<ul>
<li><h4>
How does Java Util Logging Behave in a Java Standard Environment</h4>
</li>
</ul>
<br />
1. By default, <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">Logger<span style="color: #808030;">.</span>getLogger</span> invokes <span style="font-size: x-small;"><span style="font-family: "Courier New", Courier, monospace;">java.util.logging.LogManager. </span><span style="font-family: Times New Roman; font-size: small;">The logManager reads a configuration file and creates loggers based on defined default behaviour. The configuration file can be </span></span><span style="font-size: small;">specified by -D<span style="color: #3f5fbf; font-size: x-small;"><span style="color: #3f5fbf; font-size: x-small;">java.util.logging.config.file.</span></span> If not specified, Java uses a default one shipped with the JRE, <span style="color: #2a00ff; font-size: x-small;"><span style="color: #2a00ff; font-size: x-small;">($java.home)/lib/<span style="color: #2a00ff; font-size: x-small;"><span style="color: #2a00ff; font-size: x-small;">logging.properties<span style="color: black; font-family: Courier New;">.</span></span></span></span></span></span><br />
<br />
2. The following is defined in the default <span style="color: #2a00ff; font-size: x-small;">($java.home)/lib/logging.properties.</span><br />
<ul>
<li><span lang="EN">handlers= java.util.logging.ConsoleHandler -- <em>by default, everything logs to console.</em></span></li>
<li><span lang="EN"><span lang="EN">.level= INFO <em>-- default log level.</em></span></span></li>
<li><span lang="EN"><span lang="EN"><span lang="EN">java.util.logging.FileHandler.pattern = %h/java%u.log <br />java.util.logging.FileHandler.limit = 50000<br />java.util.logging.FileHandler.count = 1<br />java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter<br /><em>-- A FileHandler is defined, but <strong>not</strong> referenced by default.</em></span></span></span></li>
</ul>
3. <span style="font-size: x-small;"><span style="font-size: small;">Because of 1 and 2, <span style="background-color: yellow;">under default setting, the logging statements in the sample code will write to the console, and nowhere else</span>.</span></span><br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh1yN1b4V0l0G_Kb19hBcKdemSBLx7l6WdjfKnBCfMT-tfQ9URPoLp9pi32yKp-jtOfY-x1BqkCkQX-dzhrUcYh_cRs_jFA8kx8ZmmJ8obQotS1LI8RHuimRhAnBDjhxjcF0pkk2tJkZG8/s1600/java-util-logging-se-default.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="86" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh1yN1b4V0l0G_Kb19hBcKdemSBLx7l6WdjfKnBCfMT-tfQ9URPoLp9pi32yKp-jtOfY-x1BqkCkQX-dzhrUcYh_cRs_jFA8kx8ZmmJ8obQotS1LI8RHuimRhAnBDjhxjcF0pkk2tJkZG8/s640/java-util-logging-se-default.png" width="640" /></a></div>
<br />
<br />
4. You can modify <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">logging.properties</span> to specify logging levels. You may want to leave the JRE logging.properties alone. Make a seperate copy before you modify it and reference it using -D<span style="color: #3f5fbf; font-size: x-small;"><span style="color: #3f5fbf; font-size: x-small;">java.util.logging.config.file.</span></span><br />
<br />
<span lang="EN"><span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">com.appinf.level = SEVERE</span><br /><span lang="EN"><span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">com.appinf.perf.level = INFO</span></span></span><br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh2j1vyPVRpaSOzlfwnGp1B3zDAdcyta9SQohZg4-RRepH2pl23h6MVCjr-J0-MtwAqotzLm0I7NkylGIpCre0hc8pU2pKB8AR9Pitb8BJHMjpUzMSYTex2-7rpRBss0xSH8ws4QIKzAQI/s1600/java-util-logging-se-default-level.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="52" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh2j1vyPVRpaSOzlfwnGp1B3zDAdcyta9SQohZg4-RRepH2pl23h6MVCjr-J0-MtwAqotzLm0I7NkylGIpCre0hc8pU2pKB8AR9Pitb8BJHMjpUzMSYTex2-7rpRBss0xSH8ws4QIKzAQI/s640/java-util-logging-se-default-level.png" width="640" /></a></div>
<br />
As you can see, statements logged by <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">com.appinf</span> is ommitted.<br />
<br />
<h3>
2. Customize : Log to application specific log files</h3>
<span style="background-color: yellow;">If you want to log to <strong>a application-specific log file </strong>in Java SE, you need to use a FileHandler</span>. <br />
<div align="left">
<br /></div>
<div align="left">
<br /></div>
<blockquote class="tr_bq">
<pre style="background: #ffffff; border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none; color: black;"><span style="color: maroon; font-weight: bold;">static</span> Logger mainLogger = null<span style="color: #808030;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> Logger perfSubLogger = null<span style="color: #808030;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> <span style="color: purple;">{</span>
mainLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
perfSubLogger <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.appinf.perf"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">try</span> <span style="color: purple;">{</span>
FileHandler fh <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">new</span> <strong>FileHandler</strong><span style="color: #808030;">(</span><span style="color: #0000e6;">"logs"</span> <span style="color: #808030;">+</span> <span style="color: #bb7977; font-weight: bold;">File</span><span style="color: #808030;">.</span>separator
<span style="color: #808030;">+</span> <span style="color: #0000e6;">"com.appinf.perf.log"</span><span style="color: #808030;">,</span> <span style="color: #008c00;">1024</span> <span style="color: #808030;">*</span> <span style="color: #008c00;">5000</span><span style="color: #808030;">,</span> <span style="color: #008c00;">10</span><span style="color: #808030;">,</span> <span style="color: maroon; font-weight: bold;">true</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
mainLogger<span style="color: #808030;">.</span>addHandler<span style="color: #808030;">(</span>fh<span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span> <span style="color: maroon; font-weight: bold;">catch</span> <span style="color: #808030;">(</span><span style="color: #bb7977; font-weight: bold;">IOException</span> e<span style="color: #808030;">)</span> <span style="color: purple;">{</span>
<span style="color: dimgrey;">// </span><span style="background: #808000; color: white;">TODO Auto-generated catch block</span>
e<span style="color: #808030;">.</span>printStackTrace<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span>
<span style="color: purple;">}</span></pre>
</blockquote>
<span style="color: #2a00ff; font-size: x-small;"><span style="color: #2a00ff; font-size: x-small;"></span></span><span style="font-size: x-small;"><div align="left">
</div>
</span><br />
<br />
<br />
<div>
There are several things to note here.</div>
<div>
</div>
<ul style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<li>If you are not using absolute path, it will use the directory where you run the command. (Under C: directly in my testing case.)</li>
<li>Subdirectories have to exist beforehand.</li>
<li><span style="background-color: yellow;">Even though you specified a file handler, logs are still written to the console. To disable it, you have to <strong>setUseParentHandlers</strong> to <strong>false</strong>.</span></li>
</ul>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<br />
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEjMuPZoVbOxkOVrr134XNo8BsOV4lLcC2X70kD1aU3w_O_PTCVEp-cjCppHs2X0xiqTlp4H3LfrFzkvWBtIQyDL0A5xN5CvFxuYUsgYszj7Q8qBguHISzGu-jXidUxL4QZsKc5Asl7AbPw/s1600/java-util-logging-se-handler-default.png" imageanchor="1" style="clear: left; cssfloat: left; float: left; margin-bottom: 1em; margin-right: 1em;"><img border="0" height="128" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEjMuPZoVbOxkOVrr134XNo8BsOV4lLcC2X70kD1aU3w_O_PTCVEp-cjCppHs2X0xiqTlp4H3LfrFzkvWBtIQyDL0A5xN5CvFxuYUsgYszj7Q8qBguHISzGu-jXidUxL4QZsKc5Asl7AbPw/s640/java-util-logging-se-handler-default.png" width="640" /></a><span lang="EN"></span> </div>
<ul>
<li>By default, logs written to files are in XML format, because as mentioned in 2, even though FileHandler is not used, it defined default formatter for file handlers to be XMLFormatter.</li>
</ul>
<span style="font-family: Arial, Helvetica, sans-serif; font-size: x-small;">java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter</span><br />
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<br /></div>
<div align="left" style="border-bottom: medium none; border-left: medium none; border-right: medium none; border-top: medium none;">
<span lang="EN" style="font-size: x-small;"><record><br /><date>2012-10-15T14:05:56</date><br /><millis>1350324356198</millis><br /><sequence>1</sequence><br /><logger>com.appinf</logger><br /><level>INFO</level><br /><class>JavaUtilLoggingSETest</class><br /><method>main</method><br /><thread>10</thread><br /><message>Processing ... </message><br /></record></span></div>
<div align="left">
<br /></div>
<div align="left">
<ul>
<li>To log only to file, not to console, and to log in simple format, add the following statements to the code in 5. </li>
</ul>
</div>
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"> fh.setFormatter(new SimpleFormatter())<span style="color: #808030;">;</span>
mainLogger.setUseParentHandlers(false)<span style="color: #808030;">;</span></pre>
</blockquote>
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi1gp8MwRHtrfQLrIEatzBV2YHAYX68vMDsDWd-iY8_hFPxjLNZ_2liaMLuuhNaGtbeJsyplqHeWnqaUpP1MvZiPff7Xxw5GT2FKkb-vZ4t03Ydmppwvh_6f_86tN4gx9yWvMOF26AbIC8/s1600/java-util-logging-se-handler-default-final.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="40" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi1gp8MwRHtrfQLrIEatzBV2YHAYX68vMDsDWd-iY8_hFPxjLNZ_2liaMLuuhNaGtbeJsyplqHeWnqaUpP1MvZiPff7Xxw5GT2FKkb-vZ4t03Ydmppwvh_6f_86tN4gx9yWvMOF26AbIC8/s640/java-util-logging-se-handler-default-final.png" width="640" /></a></div>
<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhHPQnYT6-RiFdS8TaIw8f5dkq_em59Xyg8vvnjAmvpNnIS5MCz976DSXl0hKVX5qWK8wg5S7qU8Us2poad_p7x8o7H90w_U2034YovGNaGwUqC1XxQ0gHBdgx3COFx67ryLppBG0n0ya4/s1600/java-util-logging-se-log.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="223" nea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhHPQnYT6-RiFdS8TaIw8f5dkq_em59Xyg8vvnjAmvpNnIS5MCz976DSXl0hKVX5qWK8wg5S7qU8Us2poad_p7x8o7H90w_U2034YovGNaGwUqC1XxQ0gHBdgx3COFx67ryLppBG0n0ya4/s400/java-util-logging-se-log.png" width="400" /></a></div>
<br />
<br />
<h4>
Appendix</h4>
Default getLogger implementation<br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;">private</span> <span style="color: maroon; font-weight: bold;">static</span> Logger getLoggerWithRes(String name,
String resourceBundleName, boolean hasResourceName) <span style="color: purple;">{</span>
LogManager man <span style="color: #808030;">=</span> LogManager<span style="color: #808030;">.</span>getLogManager<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
Logger l <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">synchronized</span> <span style="color: #808030;">(</span>man<span style="color: #808030;">)</span> <span style="color: purple;">{</span>
<span style="color: dimgrey;">// Try to find an existing logger with the specified name</span>
l <span style="color: #808030;">=</span> man<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span>name<span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: dimgrey;">// If no existing logger with the same name, create a new one</span>
<span style="color: maroon; font-weight: bold;">if</span> <span style="color: #808030;">(</span><span style="color: maroon; font-weight: bold;">null</span> <span style="color: #808030;">=</span><span style="color: #808030;">=</span> l<span style="color: #808030;">)</span> <span style="color: purple;">{</span>
l <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">new</span> Logger<span style="color: #808030;">(</span>name<span style="color: #808030;">,</span> resourceBundleName<span style="color: #808030;">)</span><span style="color: purple;">;</span>
man<span style="color: #808030;">.</span>addLogger<span style="color: #808030;">(</span>l<span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">return</span> l<span style="color: purple;">;</span>
<span style="color: purple;">}</span>
<span style="color: purple;">}</span>
<span style="color: maroon; font-weight: bold;">if</span> <span style="color: #808030;">(</span>hasResourceName<span style="color: #808030;">)</span> <span style="color: purple;">{</span>
updateResourceBundle<span style="color: #808030;">(</span>l<span style="color: #808030;">,</span> resourceBundleName<span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span>
<span style="color: maroon; font-weight: bold;">return</span> l<span style="color: purple;">;</span>
<span style="color: purple;">}</span></pre>
</blockquote>
app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com2tag:blogger.com,1999:blog-6852471327555282869.post-31336010605331391602012-10-09T09:21:00.000-07:002012-10-18T12:45:25.670-07:00Step-by-Step : How logging caused big performance problem for a JAX-WS web serviceThis article is about how a small piece of code can cause big performance trouble and how hard it is to figure out the root cause. <br />
<h4>
<br />What's the Number 1 Java Coding Best Practice? </h4>
There are some common known Java coding best practices: use StringBuffer for string concatenation, don't create large objects, cache expensive objects such as DateFormatter, etc.. How important are they? How much performance can you improve by following these practices? 5%, 10%, or 20%? <br />
<br />
Then, even the most dilligent developers can not claim that they follow all the best practices all the time, especially with so many 'new' frameworks and standards being adopted. Could you have missed anything?<br />
<br />
<a name='more'></a>The only way to find out is <strong>performance testing, </strong>that is the only way you can fully understand the behaviour of your code in a server environment and identify potential performance killers. <br />
<h4>
</h4>
<h4>
Test Results Indicated Performance Problem</h4>
During a recent performance testing, I identified a performance problem with a JAX-WS web service. The service is implemented similarly to the one described in <a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless.html">this tutorial</a>. The main class is both a EJB3 stateless session bean and a JAX-WS web service. It uses entity beans to retrieve data from a backend database.<br />
<br />
When the service is invoked by 20 users simultaneously, here is what we saw in the application logs.<br />
<br />
<span dir="auto"><span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">[2/29/12 8:43:35:096 EST] 0000009e Total response time for xxxx Service : 1657 ms<br />[2/29/12 8:43:35:141 EST] 00000069 Total response time for xxxx Service : 961 ms<br />[2/29/12 8:43:35:372 EST] 00000062 Total response time for xxxx Service : 1177 ms<br />[2/29/12 8:43:46:860 EST] 000000e6 Total response time for xxxx Service : 3897 ms<br />[2/29/12 8:43:46:964 EST] 000000e9 Total response time for xxxx Service : 3868 ms<br />[2/29/12 8:43:47:803 EST] 00000060 Total response time for xxxx Service : 4502 ms<br />[2/29/12 8:43:47:960 EST] 000004d3 Total response time for xxxx Service : 4673 ms<br />[2/29/12 8:43:48:066 EST] 000000a2 Total response time for xxxx Service : 5064 ms<br />[2/29/12 8:43:48:250 EST] 00000062 Total response time for xxxx Service : 5047 ms<br />[2/29/12 8:43:48:265 EST] 00000089 Total response time for xxxx Service : 5064 ms<br />[2/29/12 8:43:48:335 EST] 00000069 Total response time for xxxx Service : 5203 ms<br />[2/29/12 8:43:48:346 EST] 000000e1 Total response time for xxxx Service : 5215 ms<br />[2/29/12 8:43:48:352 EST] 000000e7 Total response time for xxxx Service : 5135 ms</span></span><br />
<br />
If invoked by single user, the total response time is always ~500ms. Apparently, there is some sort of contention going on. It took me a <strong>long </strong>time to figure out the real culprit. But knowing that there is a problem is <strong>2/3 of the success,</strong> because most of the times you don't even know you have a problem.<br />
<ul>
<li>We have so many services implemented similarly that are in production, have never been performance tested, and all have the same piece of troubling code.</li>
<li>This service was not the real target of the performance testing as well. It is just one of many downstream services being called by a batch job. Actually, no one was looking at the log of this web service until very later on. </li>
</ul>
<h4>
Application or Infrastructure?</h4>
In a Java EE environment, a problem like this can be caused by either infrastructure or application. A lot of trouble shooting can go nowhere if trapped between the app team and the infrastructure team. I was a developer, but now work on the infrastructure side. Whenever a problem like this happens, we always get requests to increase the <strong>web container thread pool </strong>size. Well, in this case, since the logging is done by the app, the container has already passed the control to the app, the time spent is all within the application code.<br />
<br />
<h4>
Initial Code Review</h4>
I requested source code and here is what I reviewed. (Simplified for generalization purpose.)<br />
<ul>
<li>The main method:</li>
</ul>
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;">try <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">final</span> <span style="color: #bb7977;">long</span> startTime <span style="color: #808030;">=</span> <span style="color: #bb7977; font-weight: bold;">System</span><span style="color: #808030;">.</span>currentTimeMillis<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
TestProcessing<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>logp<span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"HelloWorldBean"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"hello"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Enter"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
callDAO<span style="color: #808030;">(</span>arg<span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">final</span> <span style="color: #bb7977;">long</span> endTime <span style="color: #808030;">=</span> <span style="color: #bb7977; font-weight: bold;">System</span><span style="color: #808030;">.</span>currentTimeMillis<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
TestProcessing<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>logp<span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"HelloWorldBean"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"hello"</span><span style="color: #808030;">,</span>
<span style="color: #0000e6;">"Exit, Total Time : "</span> <span style="color: #808030;">+</span> <span style="color: #808030;">(</span>endTime <span style="color: #808030;">-</span> startTime<span style="color: #808030;">)</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span> catch (Exception e) <span style="color: purple;">{</span>
<span style="color: dimgrey;">// </span><span style="background: #808000; color: white;">TODO Auto-generated catch block</span>
e<span style="color: #808030;">.</span>printStackTrace<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
context<span style="color: #808030;">.</span>setRollbackOnly<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span></pre>
</blockquote>
<ul>
<li>The <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">callDAO</span> method. </li>
</ul>
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;">public</span> String callDAO(GetOSRPolicyRqType arg) <span style="color: maroon; font-weight: bold;">throws</span> InterruptedException <span style="color: purple;">{</span>
TestProcessing<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>logp<span style="color: #808030;">(</span>
Level<span style="color: #808030;">.</span>FINE<span style="color: #808030;">,</span>
<span style="color: #0000e6;">"HelloWorldBean"</span><span style="color: #808030;">,</span>
<span style="color: #0000e6;">"hello"</span><span style="color: #808030;">,</span>
<span style="color: maroon; font-weight: bold;">new</span> <span style="color: #bb7977; font-weight: bold;">StringBuffer</span><span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>append<span style="color: #808030;">(</span><span style="color: #0000e6;">"request "</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>append<span style="color: #808030;">(</span>arg<span style="color: #808030;">)</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>toString<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: #bb7977; font-weight: bold;">String</span> id <span style="color: #808030;">=</span> arg<span style="color: #808030;">.</span>getIdentifier<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
TestProcessingDAO<span style="color: #808030;">.</span>getBackendDataByID<span style="color: #808030;">(id</span><span style="color: #808030;">)</span><span style="color: purple;">;</span> <span style="color: dimgrey;">// EJB3 Entity Bean Processing</span>
<span style="color: maroon; font-weight: bold;">return</span> <span style="color: #0000e6;">"abc"</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span></pre>
</blockquote>
<ul>
<li>The getLogger method</li>
</ul>
<br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;">static</span> <span style="color: maroon; font-weight: bold;">public</span> Logger getLogger()<span style="color: purple;">{</span>
Logger log <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span><span style="color: purple;">;</span>
log <span style="color: #808030;">=</span> Logger<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #0000e6;">"test"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
log <span style="color: #808030;">=</span> TestHandler<span style="color: #808030;">.</span>addFileHandler<span style="color: #808030;">(</span>log<span style="color: #808030;">,</span> <span style="color: #0000e6;">"test"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">return</span> log<span style="color: purple;">;</span>
<span style="color: purple;">}</span></pre>
<br /></blockquote>
<ul>
<li>The addFileHandler method</li>
</ul>
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;"> public</span> <span style="color: maroon; font-weight: bold;">static</span> Logger addFileHandler(Logger logger, String name) <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">try</span> <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">if</span> <span style="color: #808030;">(</span>logger <span style="color: #808030;">!</span><span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span> <span style="color: #808030;">&</span><span style="color: #808030;">&</span> logger<span style="color: #808030;">.</span>getHandlers<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>length <span style="color: #808030;">=</span><span style="color: #808030;">=</span> <span style="color: #008c00;">0</span><span style="color: #808030;">)</span> <span style="color: purple;">{</span>
FileHandler handler <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">new</span> FileHandler<span style="color: #808030;">(</span><span style="color: #0000e6;">"logs"</span> <span style="color: #808030;">+</span> <span style="color: #bb7977; font-weight: bold;">File</span><span style="color: #808030;">.</span>separator
<span style="color: #808030;">+</span> name <span style="color: #808030;">+</span> <span style="color: #0000e6;">".log"</span><span style="color: #808030;">,</span> <span style="color: #008c00;">1024</span> <span style="color: #808030;">*</span> <span style="color: #008c00;">5000</span><span style="color: #808030;">,</span> <span style="color: #008c00;">10</span><span style="color: #808030;">,</span> <span style="color: maroon; font-weight: bold;">true</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
handler<span style="color: #808030;">.</span>setFormatter<span style="color: #808030;">(</span><span style="color: maroon; font-weight: bold;">new</span> SimpleFormatter<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
logger<span style="color: #808030;">.</span>addHandler<span style="color: #808030;">(</span>handler<span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span>
<span style="color: purple;">}</span> <span style="color: maroon; font-weight: bold;">catch</span> <span style="color: #808030;">(</span><span style="color: #bb7977; font-weight: bold;">Exception</span> e<span style="color: #808030;">)</span> <span style="color: purple;">{</span>
e<span style="color: #808030;">.</span>printStackTrace<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span>
<span style="color: maroon; font-weight: bold;">return</span> logger<span style="color: purple;">;</span>
<span style="color: purple;">}</span></pre>
<div style="background: #ffffff; color: black;">
<br /></div>
<h4>
Identify Possible Culprits</h4>
<ol>
<li>The main work of this web service is callDAO. It invokes an EJB3 entity bean, which in turn invokes database operations. Can database query be the bottleneck?</li>
<li>Logger is not cached. TestProcessing<span style="color: #808030;">.</span>getLogger() is called each time. Does it cause synchronization issue when invoked by multiple threads?</li>
<li>Logging too much. All logs are written to the same file, can file IO be the bottleneck?</li>
</ol>
<h4>
Changes Logging - Problem Resolved</h4>
<br />
The developers made the following two changes.<br />
<ul>
<li>The getLogger method now returns a static copy of the logger instance. </li>
<li>Following common known best practice, added <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">isLoggable</span> check before logging.</li>
</ul>
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;">if (log.isLoggable(Level.FINE))<span style="color: purple;">{</span>
<span style="color: purple;">}</span></pre>
</blockquote>
Tada, performance problem resolved. All requests took ~500ms now; no more spikes to <span style="font-family: Courier New; font-size: x-small;">5203 ms <span style="font-family: Times New Roman; font-size: small;">under load. Logging too much is commonly blamed for bad performance and it is a known best-practice to tune down logging in production. This seems to be another case. Project moved on. Went live. End of story. Until...</span></span><br />
<br />
<h4>
But Logging is not the the Real Culprit</h4>
<br />
Months later, to document the root-cause of this incident, I decided to reproduce this problem using my <a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless.html">TestHarness</a> framework. I invoked <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">java.util.logging.Logger</span> 20 times per thread non-cached, logged 20 messages at a time, used <a href="http://jmeter.apache.org/">JMeter</a> to initiated 20, then 40 threads at a time, I cannot reproduce this problem. The overhead is minimal. <br />
<br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"> for ( int i = 0<span style="color: #808030;">;</span> i < 20<span style="color: #808030;">;</span> i++ )<span style="color: purple;">{</span>
TestProcessing<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>logp<span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"HelloWorldBean"</span><span style="color: #808030;">,</span>
<span style="color: #0000e6;">"hello"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Enter"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span>
<span style="color: dimgrey;">//callDAO(arg);</span>
Thread.sleep(1000)<span style="color: #808030;">;</span>
<span style="color: maroon; font-weight: bold;">final</span> long endTime = System.currentTimeMillis()<span style="color: #808030;">;</span>
TestProcessing.getLogger().logp(Level.INFO, "HelloWorldBean",
"hello", "Exit, Total Time : " + (endTime - startTime))<span style="color: #808030;">;</span></pre>
</blockquote>
I used <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">Thread.sleep(1000)<span style="font-family: Times New Roman; font-size: small;">to simulate the business method, and the result shows the overhead of logging to be < 30ms.</span></span><br />
<br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">[10:30:10:594] 0000003d Exit, Total Time : 1030<br />[10:30:10:656] 0000007c Exit, Total Time : 1014<br />[10:30:10:734] 00000043 Exit, Total Time : 1014<br />[10:30:10:781] 00000055 Exit, Total Time : 1030<br />[10:30:10:843] 0000004b Exit, Total Time : 1014<br />[10:30:10:859] 00000036 Exit, Total Time : 1030<br />[10:30:10:906] 0000004f Exit, Total Time : 1030<br />[10:30:10:999] 00000049 Exit, Total Time : 1014<br />[10:30:10:999] 00000057 Exit, Total Time : 1014<br />[10:30:11:108] 0000003f Exit, Total Time : 1029</span><br />
<br />
<h4>
The Real Culprit</h4>
<br />
Eventually, I went back to the source code repository and saw a piece of code that was not sent over the first time.<br />
<br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"> if (log.isLoggable(Level.FINE))<span style="color: purple;">{</span>
TestProcessing<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>logp<span style="color: #808030;">(</span>
Level<span style="color: #808030;">.</span>FINE<span style="color: #808030;">,</span>
<span style="color: #0000e6;">"HelloWorldBean"</span><span style="color: #808030;">,</span>
<span style="color: #0000e6;">"hello"</span><span style="color: #808030;">,</span>
<span style="color: maroon; font-weight: bold;">new</span> <span style="color: #bb7977; font-weight: bold;">StringBuffer</span><span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>append<span style="color: #808030;">(</span><span style="color: #0000e6;">"request "</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>append<span style="color: #808030;">(</span>xmlToString<span style="color: #808030;">(</span>arg<span style="color: #808030;">,</span><span style="color: #0000e6;">"com.helloworld.dataobjects"</span><span style="color: #808030;">)</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>toString<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span></pre>
</blockquote>
Apparently, <span style="font-family: "Courier New", Courier, monospace;"><span style="font-size: x-small;">.append<span style="color: #808030;">(</span>arg<span style="color: #808030;">) </span></span></span>doesn't print out the incoming JAXB requests in xml, so a utility method <span style="font-size: x-small;"><span style="font-family: Courier New;">xmlToString<span style="color: #808030;">(</span>arg<span style="color: #808030;">,</span><span style="color: #0000e6;">"com.helloworld.dataobjects"</span><span style="color: #808030;">)</span></span></span>was intoduced.<br />
<br />
<ul>
<li>Here is the <span style="font-family: Courier New; font-size: x-small;">xmlToString m</span>ethod.</li>
</ul>
<br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;">private</span> <span style="color: maroon; font-weight: bold;">static</span> String xmlToString(Object xmlObj, String cntxt) <span style="color: purple;">{</span>
<span style="color: #bb7977; font-weight: bold;">String</span> result <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">null</span><span style="color: purple;">;</span>
<span style="color: maroon; font-weight: bold;">try</span> <span style="color: purple;">{</span>
JAXBContext ctx <span style="color: #808030;">=</span> JAXBContext<span style="color: #808030;">.</span>newInstance<span style="color: #808030;">(</span>cntxt<span style="color: #808030;">)</span><span style="color: purple;">;</span>
Marshaller m <span style="color: #808030;">=</span> ctx<span style="color: #808030;">.</span>createMarshaller<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: #bb7977; font-weight: bold;">StringWriter</span> sw <span style="color: #808030;">=</span> <span style="color: maroon; font-weight: bold;">new</span> <span style="color: #bb7977; font-weight: bold;">StringWriter</span><span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
m<span style="color: #808030;">.</span>setProperty<span style="color: #808030;">(</span>Marshaller<span style="color: #808030;">.</span>JAXB_FORMATTED_OUTPUT<span style="color: #808030;">,</span> <span style="color: maroon; font-weight: bold;">true</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
m<span style="color: #808030;">.</span>marshal<span style="color: #808030;">(</span>xmlObj<span style="color: #808030;">,</span> sw<span style="color: #808030;">)</span><span style="color: purple;">;</span>
result <span style="color: #808030;">=</span> sw<span style="color: #808030;">.</span>toString<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span> <span style="color: maroon; font-weight: bold;">catch</span> <span style="color: #808030;">(</span><span style="color: #bb7977; font-weight: bold;">Exception</span> e<span style="color: #808030;">)</span> <span style="color: purple;">{</span>
TestProcessing<span style="color: #808030;">.</span>getLogger<span style="color: #808030;">(</span><span style="color: #808030;">)</span><span style="color: #808030;">.</span>logp<span style="color: #808030;">(</span>Level<span style="color: #808030;">.</span>INFO<span style="color: #808030;">,</span> <span style="color: #0000e6;">"TestProcessing"</span><span style="color: #808030;">,</span>
<span style="color: #0000e6;">"process"</span><span style="color: #808030;">,</span> <span style="color: #0000e6;">"Exception"</span> <span style="color: #808030;">+</span> e<span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span>
<span style="color: maroon; font-weight: bold;">return</span> result<span style="color: purple;">;</span>
<span style="color: purple;">}</span></pre>
<br /></blockquote>
<br />
It uses the JAXB marshaller to convert JAXB requests to xml. I performance tested the above code using my <a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless.html">TestHarness</a> and <a href="http://jmeter.apache.org/">JMeter</a>. Again, use <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">Thread.sleep(1000)</span>to simulate the business method, Here is the result.<br />
<br />
Invoked by 1 user, the overhead is ~400ms, which is tremendous.<br />
<br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">[10:55:15:855] 00000026 hello Exit, Total Time : 1420</span><br />
<br />
Invoked by 20 users concurrently, it got worse.<br />
<br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">[10:55:28:788] 0000003f hello Exit, Total Time : 2559<br />[10:55:29:100] 0000004c hello Exit, Total Time : 2527<br />[10:55:29:100] 00000055 hello Exit, Total Time : 2746<br />[10:55:29:100] 0000003b hello Exit, Total Time : 2824<br />[10:55:29:318] 0000004b hello Exit, Total Time : 2933<br />[10:55:30:254] 00000053 hello Exit, Total Time : 3432<br />[10:55:30:332] 0000003e hello Exit, Total Time : 3229<br />[10:55:30:473] 00000046 hello Exit, Total Time : 3276<br />[10:55:31:518] 0000007a hello Exit, Total Time : 4243<br />[10:55:31:752] 00000034 hello Exit, Total Time : 4524<br />[10:55:32:329] 000000ab hello Exit, Total Time : 4618<br />[10:55:32:469] 00000043 hello Exit, Total Time : 4758<br />[10:55:32:532] 00000050 hello Exit, Total Time : 4774<br />[10:55:32:563] 0000003c hello Exit, Total Time : 4789<br />[10:55:32:672] 00000048 hello Exit, Total Time : 6177<br />[10:55:32:672] 0000004a hello Exit, Total Time : 4961<br />[10:55:32:688] 00000054 hello Exit, Total Time : 4977<br />[10:55:32:766] 000000ac hello Exit, Total Time : 5086<br />[10:55:32:859] 0000004e hello Exit, Total Time : 6380<br />[10:55:32:875] 00000027 hello Exit, Total Time : 5179</span><br />
So what exactly is wrong with the <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">xmlToString</span> method? I generated thread dumps, (use <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">kill -3 pid</span> in Linux and follow <a href="http://www-01.ibm.com/support/docview.wss?uid=swg21177139">this instruction</a> in Windows,) and the thread dumps attached at the end of this article point to <br />
<br />
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-size: x-small;"><blockquote class="tr_bq">
<span style="font-family: "Courier New", Courier, monospace;"><span style="color: red; font-size: x-small;"><strong>JAXBContext ctx = JAXBContext.newInstance(cntxt);</strong></span></span></blockquote>
</span></span><span style="color: purple; font-family: Courier New; font-size: x-small;"></span>
<br />
This is the problem code. <strong><span style="color: red;">JAXBContext.newInstance </span></strong>turns out to be very expensive as it reloads all JAXB objects generated from the wsdl schema, especially when you have a big schema, a common case if you use industry or enterprise standard. (In my case, JAXB generated ~200 classes from the schema.)<br />
<br />
What happens when I cached the <span style="color: red;"><strong>JAXBContext </strong></span><span style="color: black;">instance by using a static variable? </span><br />
<br />
<blockquote class="tr_bq">
<pre style="background: #ffffff; color: black;"><span style="color: maroon; font-weight: bold;">private</span> <span style="color: maroon; font-weight: bold;">static</span> JAXBContext ctx<span style="color: #808030;">;</span>
<span style="color: maroon; font-weight: bold;">static</span> <span style="color: purple;">{</span>
<span style="color: maroon; font-weight: bold;">try</span> <span style="color: purple;">{</span>
ctx <span style="color: #808030;">=</span> JAXBContext
<span style="color: #808030;">.</span>newInstance<span style="color: #808030;">(</span><span style="color: #0000e6;">"com.hello.dataobjects"</span><span style="color: #808030;">)</span><span style="color: purple;">;</span>
<span style="color: purple;">}</span> <span style="color: maroon; font-weight: bold;">catch</span> <span style="color: #808030;">(</span><span style="color: #bb7977; font-weight: bold;">Exception</span> e<span style="color: #808030;">)</span> <span style="color: purple;">{</span>
<span style="color: purple;">}</span>
<span style="color: purple;">}</span></pre>
</blockquote>
<br />
<span style="color: black;">Here is the result when invoked by 20 concurrent users. The actual marshalling, logging JAXB ojbects as xml, only adds <span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">~14ms </span>overhead.</span><br />
<br />
<div style="font-family: Calibri; margin: 0in;">
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">[11:17:12:445] 0000004c hello Exit, Total Time : 1014<br />[11:17:12:492] 00000049 hello Exit, Total Time : 1014<br />[11:17:12:554] 00000053 hello Exit, Total Time : 1030<br />[11:17:12:616] 000000ae hello Exit, Total Time : 1029<br />[11:17:12:679] 00000034 hello Exit, Total Time : 1014<br />[11:17:12:694] 00000027 hello Exit, Total Time : 1014<br />[11:17:12:741] 00000078 hello Exit, Total Time : 1014<br />[11:17:12:788] 00000028 hello Exit, Total Time : 1014</span></div>
<br />
<span style="color: black;">The performance of JAXBContext.newInstance is a known issue. There is a great discussion <a href="http://stackoverflow.com/questions/6043956/how-do-i-improve-performance-of-application-that-uses-the-jaxbcontext-newinstanc">here</a>, which points out that JAXB 2.2 Specification recommends reusing a JAXBContext instance, that JAXBContext is thread safe while Marshaller is not. </span><br />
<br />
<h4>
Takeaways</h4>
<ol>
<li><strong><span style="color: red;">JAXBContext.newInstance </span></strong>is very expensive. It should be cached. Add it to your knowledge of java coding best practices.</li>
<li><strong><span style="color: red;">Log, Log, Log</span></strong>. Although logging is an easy target for blame, it is not the problem. Without logging, we may not even notice this problem. The actual logging, when done right, adds minimal overhead.</li>
<li><strong><span style="color: red;">log.isLoggable</span></strong> is a very useful guard when the logging is <em>unintentionally</em> expensive. It prevented the bad version of <em>xmlToString </em>from being called in the first place. Its use is limited because developers do want to log the requests in xml format for troubleshooting, but at lease it provides a switch to turn it off. </li>
<li>Performace test your code. With so many new java frameworks being adopted, performance testing is the only way to find out traps. <a href="http://junit.org/">Junit</a> is overrated. <a href="http://jmeter.apache.org/"><strong><span style="color: red;">JMeter</span></strong></a> is under-rated.</li>
<li>It is worth it to <strong><span style="color: red;">get to the bottom</span></strong> of it. We didn't, and the bad version of <em>xmlToString </em>is being called in production in tens of other web services. </li>
</ol>
<br />
<h4>
Appendix : The Thread Dump</h4>
<br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">3XMTHREADINFO "WebContainer : 17" TID:0x4D5D4E00, j9thread_t:0x4A5DD738, state:CW, prio=5<br />3XMTHREADINFO1 (native thread ID:0x13BC, native priority:0x5, native policy:UNKNOWN)<br />4XESTACKTRACE at java/util/zip/Inflater.inflateBytes(Native Method)<br />4XESTACKTRACE at java/util/zip/Inflater.inflate(Inflater.java:234(Compiled Code))<br />4XESTACKTRACE at java/util/zip/InflaterInputStream.read(InflaterInputStream.java:141(Compiled Code))<br />4XESTACKTRACE at java/util/zip/InflaterInputStream.read(InflaterInputStream.java:116(Compiled Code))<br />4XESTACKTRACE at java/io/FilterInputStream.read(FilterInputStream.java:77(Compiled Code))<br />4XESTACKTRACE at java/io/DataInputStream.readUnsignedShort(DataInputStream.java:332(Compiled Code))<br />4XESTACKTRACE at java/io/DataInputStream.readUTF(DataInputStream.java:586(Compiled Code))<br />4XESTACKTRACE at java/io/DataInputStream.readUTF(DataInputStream.java:558(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/bytecode/ClassTailor.tailor(ClassTailor.java:90(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/reflect/opt/AccessorInjector.tailor(AccessorInjector.java:95(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/reflect/opt/AccessorInjector.prepare(AccessorInjector.java:68(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/reflect/opt/OptimizedAccessorFactory.get(OptimizedAccessorFactory.java:140(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/reflect/Accessor$FieldReflection.optimize(Accessor.java:225(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/SingleElementNodeProperty.<init>(SingleElementNodeProperty.java:64(Compiled Code))<br />4XESTACKTRACE at sun/reflect/GeneratedConstructorAccessor4.newInstance(Bytecode PC:36(Compiled Code))<br />4XESTACKTRACE at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))<br />4XESTACKTRACE at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/ArrayElementProperty.<init>(ArrayElementProperty.java:84(Compiled Code))<br />4XESTACKTRACE at sun/reflect/GeneratedConstructorAccessor5.newInstance(Bytecode PC:36(Compiled Code))<br />4XESTACKTRACE at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))<br />4XESTACKTRACE at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/ArrayElementProperty.<init>(ArrayElementProperty.java:84(Compiled Code))<br />4XESTACKTRACE at sun/reflect/GeneratedConstructorAccessor5.newInstance(Bytecode PC:36(Compiled Code))<br />4XESTACKTRACE at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))<br />4XESTACKTRACE at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/SingleElementNodeProperty.<init>(SingleElementNodeProperty.java:75(Compiled Code))<br />4XESTACKTRACE at sun/reflect/GeneratedConstructorAccessor4.newInstance(Bytecode PC:36(Compiled Code))<br />4XESTACKTRACE at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))<br />4XESTACKTRACE at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/ArrayElementProperty.<init>(ArrayElementProperty.java:84(Compiled Code))<br />4XESTACKTRACE at sun/reflect/GeneratedConstructorAccessor5.newInstance(Bytecode PC:36(Compiled Code))<br />4XESTACKTRACE at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))<br />4XESTACKTRACE at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/ArrayElementProperty.<init>(ArrayElementProperty.java:84(Compiled Code))<br />4XESTACKTRACE at sun/reflect/GeneratedConstructorAccessor5.newInstance(Bytecode PC:36(Compiled Code))<br />4XESTACKTRACE at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))<br />4XESTACKTRACE at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.<init>(JAXBContextImpl.java:311(Compiled Code))<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/ContextFactory.createContext(ContextFactory.java:115)<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/ContextFactory.createContext(ContextFactory.java:93)<br />4XESTACKTRACE at com/sun/xml/internal/bind/v2/ContextFactory.createContext(ContextFactory.java:164)<br />4XESTACKTRACE at sun/reflect/GeneratedMethodAccessor39.invoke(Bytecode PC:40)<br />4XESTACKTRACE at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))<br />4XESTACKTRACE at java/lang/reflect/Method.invoke(Method.java:599(Compiled Code))<br />4XESTACKTRACE at com/ibm/xml/xlxp2/jaxb/JAXBContextImpl.createFallbackContext(JAXBContextImpl.java:230)<br />4XESTACKTRACE at com/ibm/xml/xlxp2/jaxb/JAXBContextImpl.<init>(JAXBContextImpl.java:107)<br />4XESTACKTRACE at com/ibm/xml/xlxp2/jaxb/JAXBContextFactory.createContext(JAXBContextFactory.java:37)<br />4XESTACKTRACE at sun/reflect/NativeMethodAccessorImpl.invoke0(Native Method)<br />4XESTACKTRACE at sun/reflect/NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:45(Compiled Code))<br />4XESTACKTRACE at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))<br />4XESTACKTRACE at java/lang/reflect/Method.invoke(Method.java:599(Compiled Code))<br />4XESTACKTRACE at javax/xml/bind/ContextFinder.newInstance(ContextFinder.java:144)<br />4XESTACKTRACE at javax/xml/bind/ContextFinder.find(ContextFinder.java:297(Compiled Code))<br />4XESTACKTRACE at javax/xml/bind/JAXBContext.newInstance(JAXBContext.java:383(Compiled Code))<br />4XESTACKTRACE at javax/xml/bind/JAXBContext.newInstance(JAXBContext.java:348(Compiled Code))<br /><strong><span style="color: red;">4XESTACKTRACE at javax/xml/bind/JAXBContext.newInstance(JAXBContext.java:255(Compiled Code))<br />4XESTACKTRACE at com/test/ejb/HelloWorldBean.xmlToString(HelloWorldBean.java:67(Compiled Code))<br />4XESTACKTRACE at com/test/ejb/HelloWorldBean.hello</span></strong>(HelloWorldBean.java:38(Compiled Code))<br />4XESTACKTRACE at sun/reflect/GeneratedMethodAccessor43.invoke(Bytecode PC:40)<br />4XESTACKTRACE at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))</span>app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com6tag:blogger.com,1999:blog-6852471327555282869.post-30592399502255988712012-09-29T00:02:00.001-07:002012-10-04T11:38:09.093-07:00Tutorial : Building EJB3 Stateless Session Bean and JAX-WS web service In One Class Using RAD 7.5 - Developing JAX-WS Client<div class="separator" style="clear: both; text-align: left;">
This series is about building an empty shell application that contains an EJB3 stateless session bean, a JAX-WS web service, and a web application that acts as the EJB and web service clients. I personally built it for performance testing purpose; so I can plug-in "in-doubt" java code to oberve how they handle concurrency in a server environment. But this will serve as a tutorial for those who are interested.</div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless.html">Part 1</a> : Project Setup</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_28.html">Part 2</a> : EJB3 and JAX-WS Implementation</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_1704.html">Part 3</a> : Develop EJB3 client</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_29.html">Part 4</a> : Develop JAX-WS client</div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<a name='more'></a><div class="separator" style="clear: both; text-align: left;">
<br /></div>
<h4>
Generate JAX-WS client code</h4>
From Java EE perspective, expand Services from the EJB/JAX-WS project TestHarness. Right click the service, select Generate -> Client.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEie_sQ6hZ_lgzIWKxPObIPTz6S-OhecqG0nfkqCQjegVVGbwCNmWwvOVMFMWt9o2GFTrnJvm4MwLVFB-60jdrCHTjKcMwOSF8V9pQSiMnCzo7ZMUwzAW070IyS5O2LrRyanTR3iWTiCOIs/s1600/ejb-client-jax-create.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="143" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEie_sQ6hZ_lgzIWKxPObIPTz6S-OhecqG0nfkqCQjegVVGbwCNmWwvOVMFMWt9o2GFTrnJvm4MwLVFB-60jdrCHTjKcMwOSF8V9pQSiMnCzo7ZMUwzAW070IyS5O2LrRyanTR3iWTiCOIs/s400/ejb-client-jax-create.png" width="400" /></a></div>
<br />
Accept Default, Click Next.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEiuInhlmXD8raKtQ_d8F95M5KGLP9rTf6GHaPH6jLWU55fwRVtEiPut7DV8Ti6_p9lbT4cNRX026r3aKeFRWjzCbWLfMPyS0G-HIa0wyOdo1GU2hyphenhyphenUlWH17oOnR6tmFf9ccffJAIBfcVVg/s1600/ejb-client-jax-create-proxy.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEiuInhlmXD8raKtQ_d8F95M5KGLP9rTf6GHaPH6jLWU55fwRVtEiPut7DV8Ti6_p9lbT4cNRX026r3aKeFRWjzCbWLfMPyS0G-HIa0wyOdo1GU2hyphenhyphenUlWH17oOnR6tmFf9ccffJAIBfcVVg/s1600/ejb-client-jax-create-proxy.png" /></a></div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
Make sure the output folder is the Client web project. If not, you will have to copy generated classes over. </div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEiZIC2926WPs65OZpIflnlet2-fJKh6F_g3gPIWYvQxW0-cEn1QTc_dYY-IdL-LXYTyPp9xnWgYbRnkCTBCQrYqrW_auoZGhm7mgA2kfuU5H5Qw4_l0BPgQ6vNsazKBC3nOxOzXDRiYht8/s1600/ejb-client-jax-create-src.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEiZIC2926WPs65OZpIflnlet2-fJKh6F_g3gPIWYvQxW0-cEn1QTc_dYY-IdL-LXYTyPp9xnWgYbRnkCTBCQrYqrW_auoZGhm7mgA2kfuU5H5Qw4_l0BPgQ6vNsazKBC3nOxOzXDRiYht8/s1600/ejb-client-jax-create-src.png" /></a></div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
Review what is generated. Under src are generated client classes and under WEB-INF/wsdl are generated wsdl files.</div>
<div class="separator" style="clear: both; text-align: left;">
</div>
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEifSPcqjlYGV7NcElHOT_X4oNuRe6BQQJTV8MR1dTs-PBQQgc0wI4WhlAPsCXWlAaun6tiu9dStyShLIWgt0A5cXSoYcMH7iOiUFqsOlKCX6WFmoAI58Vjzh4T4RwO9bMwxJsxxSSxfH68/s1600/ejb-client-jax-create-generated.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEifSPcqjlYGV7NcElHOT_X4oNuRe6BQQJTV8MR1dTs-PBQQgc0wI4WhlAPsCXWlAaun6tiu9dStyShLIWgt0A5cXSoYcMH7iOiUFqsOlKCX6WFmoAI58Vjzh4T4RwO9bMwxJsxxSSxfH68/s1600/ejb-client-jax-create-generated.png" /></a></div>
<div align="left">
</div>
<h4>
Develop Jax-WS client servlet</h4>
Create a servlet called <span style="font-size: x-small;">TestJAXWSClientServlet.</span><br />
<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgeaYdOlhIg3M4FddYeB6AZix0G3LA0PgyKaAuqcXf5HKKKNbld6JXJKeMZRwUjUAdRhRqqr8-ov6zvatHE6XBfwTLgdVhzeqeVJeDy4uApTanYJwxKpMaT_g7D0VtW6uCmSj7vtppOBi0/s1600/ejb-client-jax-src.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgeaYdOlhIg3M4FddYeB6AZix0G3LA0PgyKaAuqcXf5HKKKNbld6JXJKeMZRwUjUAdRhRqqr8-ov6zvatHE6XBfwTLgdVhzeqeVJeDy4uApTanYJwxKpMaT_g7D0VtW6uCmSj7vtppOBi0/s1600/ejb-client-jax-src.png" /></a></div>
<br />
<h4>
Change Jax-WS web service endpoint</h4>
Open the wsdl file generated under WEB-INF/wsdl. <br />
<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEjnPiZ6mIsUUXvA6H4LT9thB-hfJsclB6sF8N4LYJ6g50Clhw28WRyFmuF1IBarNynIiFw4ifh-SzitgMDzAdn4xEATBBu4Z8LayZr5mvGnGTOfivibaHnWIRdKvt0f6ZwahjEa9TtyPKs/s1600/ejb-wsdl.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEjnPiZ6mIsUUXvA6H4LT9thB-hfJsclB6sF8N4LYJ6g50Clhw28WRyFmuF1IBarNynIiFw4ifh-SzitgMDzAdn4xEATBBu4Z8LayZr5mvGnGTOfivibaHnWIRdKvt0f6ZwahjEa9TtyPKs/s1600/ejb-wsdl.png" /></a></div>
Replace "<span style="color: #2a00ff; font-size: x-small;"><span style="color: #2a00ff; font-size: x-small;"><em>REPLACE_WITH_ACTUAL_URL" </em><span style="color: black; font-size: small;"> with the actual url, in my case, <a href="http://localhost:9081/TestHarness_HTTPRouter/TestHarnessService">http://localhost:9081/<span style="font-size: xx-small;">TestHarness_HTTPRouter/TestHarnessService</span></a> </span></span></span><br />
<span style="color: #2a00ff; font-size: x-small;"><span style="color: #2a00ff; font-size: x-small;"><span style="color: black; font-size: small;"><span style="font-size: xx-small;"><h4>
Test</h4>
</span></span></span></span>Now we are done. Deploy the application to WebSphere Application Server and test it.
<br />
<br />
<a href="http://localhost:9081/TestHarnessWeb/TestJAXWSClientServlet">http://localhost:9081/TestHarnessWeb/TestJAXWSClientServlet</a><br />
<a href="http://localhost:9081/TestHarnessWeb/TestEJBClientServlet">http://localhost:9081/TestHarnessWeb/TestEJBClientServlet</a><br />
<br />app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com0tag:blogger.com,1999:blog-6852471327555282869.post-8336414907742768502012-09-28T23:31:00.000-07:002012-10-04T11:22:38.503-07:00Tutorial : Building EJB3 Stateless Session Bean and JAX-WS web service In One Class Using RAD 7.5 - Developing EJB3 Client<div class="separator" style="clear: both; text-align: left;">
This series is about building an empty shell application that contains an EJB3 stateless session bean, a JAX-WS web service, and a web application that acts as the EJB and web service clients. I personally built it for performance testing purpose; so I can plug-in "in-doubt" java code to oberve how they handle concurrency in a server environment. But this will serve as a tutorial for those who are interested.</div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless.html">Part 1</a> : Project Setup</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_28.html">Part 2</a> : EJB3 and JAX-WS Implementation</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_1704.html">Part 3</a> : Develop EJB3 client</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_29.html">Part 4</a> : Develop JAX-WS client</div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<h4 class="separator" style="clear: both; text-align: left;">
Client Web Project Setup</h4>
<div class="separator" style="clear: both; text-align: left;">
I will create a web project to host servlets that will call the EJB3 Stateless Session Bean and the JAX-WS web service. </div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
From Java EE perspective, Click New -> Dynamic Web Project.</div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEj2cwMS5TutC2WLmkDRAm6FdRfYgWriXBcfoUOb2HN3ymS6tToPe3vrpGfxEzK7ITWAKPS0gXWBcwXSG-mxkppU8PE805srutNdv4rDrwtDrMaAF3Kr9PUnH0Uz7ZSnfHufUcjOsVJoTWk/s1600/ejb-client.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEj2cwMS5TutC2WLmkDRAm6FdRfYgWriXBcfoUOb2HN3ymS6tToPe3vrpGfxEzK7ITWAKPS0gXWBcwXSG-mxkppU8PE805srutNdv4rDrwtDrMaAF3Kr9PUnH0Uz7ZSnfHufUcjOsVJoTWk/s1600/ejb-client.png" /></a></div>
<a name='more'></a><br />
Enter Project Name, ClickFinish.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEjaqt2rik0V_DQ7VPMg-zJqWtSBIcW6VohWmWKjN8gTYlw0qPFzZohGcuXBa1zoNeLCYZac8-S7IP4svTzn5jmROINXedncYyITJZPVkL_MmeVltZFwfErDQDF7nZZwtQN38K3FXQfjxvI/s1600/ejb-client-project.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEjaqt2rik0V_DQ7VPMg-zJqWtSBIcW6VohWmWKjN8gTYlw0qPFzZohGcuXBa1zoNeLCYZac8-S7IP4svTzn5jmROINXedncYyITJZPVkL_MmeVltZFwfErDQDF7nZZwtQN38K3FXQfjxvI/s1600/ejb-client-project.png" /></a></div>
<br />
Once the Project is created, Right Click the project name and Select Properties. Select Java EE Module Dependencies, check TestHarness,jar. This will allow the web project to see interfaces defined in the EJB module.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEiCdGAGndSP0RPe7-C2terLc8jVZHqkBLFVdpyc-8R_RVibadaenwFwWhmhtPsLg4GvyzHkGr3vfXmulExIRI-nfacQQxeUiS6XR16Wf5MzU3yG9f8Uw14R0UP2zJNUNhNkJZzH2R1VheI/s1600/ejb-client-dependency.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEiCdGAGndSP0RPe7-C2terLc8jVZHqkBLFVdpyc-8R_RVibadaenwFwWhmhtPsLg4GvyzHkGr3vfXmulExIRI-nfacQQxeUiS6XR16Wf5MzU3yG9f8Uw14R0UP2zJNUNhNkJZzH2R1VheI/s1600/ejb-client-dependency.png" /></a></div>
<br />
<br />
<h4>
Create an EJB3 Client</h4>
Create a servlet called <span style="font-size: x-small;">TestEJBClientServlet.</span><br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh1kbSFIKvp4Nn9wSMbEHBcl4jv2qz61Qz6YzHiyz9JlZIsy5UsJG93LHe4NhxeGYNHWK_nwTYuMZMHv7rPy_uZa5LjtuH2mQRPEsgUDfmhnp8shYMswBpaMmn3MzV2pwdn3VAipN1iklQ/s1600/ejb-client-ejb.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEh1kbSFIKvp4Nn9wSMbEHBcl4jv2qz61Qz6YzHiyz9JlZIsy5UsJG93LHe4NhxeGYNHWK_nwTYuMZMHv7rPy_uZa5LjtuH2mQRPEsgUDfmhnp8shYMswBpaMmn3MzV2pwdn3VAipN1iklQ/s1600/ejb-client-ejb.png" /></a></div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
<span style="font-size: x-small;">That's it. The declaration of TestHarnessRemote will be smart enough to use the default JNDI name for the EJB to find a reference to it.</span><br />
<br />
<span style="font-size: x-small;">Next, we will create a JAX-WS client.</span>app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com1tag:blogger.com,1999:blog-6852471327555282869.post-42423438868519653342012-09-28T22:50:00.000-07:002012-10-04T11:22:15.265-07:00Tutorial : Building EJB3 Stateless Session Bean and JAX-WS web service In One Class Using RAD 7.5 - Implementation<div class="separator" style="clear: both; text-align: left;">
This series is about building an empty shell application that contains an EJB3 stateless session bean, a JAX-WS web service, and a web application that acts as the EJB and web service clients. I personally built it for performance testing purpose; so I can plug-in "in-doubt" java code to oberve how they handle concurrency in a server environment. But this will serve as a tutorial for those who are interested.</div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless.html">Part 1</a> : Project Setup</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_28.html">Part 2</a> : EJB3 and JAX-WS Implementation</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_1704.html">Part 3</a> : Develop EJB3 client</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_29.html">Part 4</a> : Develop JAX-WS client</div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<h4>
Implement the Interface. </h4>
Before we make changes to it, here is the generated class.<br />
<br />
<b><span style="color: #7f0055; font-size: x-small;"><span style="color: #7f0055; font-size: x-small;"><div align="left">
package </div>
</span></span></b><span style="font-size: x-small;">com.appinf;</span><b><span style="color: #7f0055; font-size: x-small;"><span style="color: #7f0055; font-size: x-small;"></span></span></b>
<br />
<br />
<div align="left">
import <span style="font-size: x-small;">javax.ejb.Remote;</span></div>
<div align="left">
</div>
<span style="color: #646464; font-size: x-small;"><span style="color: #646464; font-size: x-small;"><div align="left">
@Remote</div>
</span></span><b><span style="color: #7f0055; font-size: x-small;"><span style="color: #7f0055; font-size: x-small;"><div align="left">
public</div>
</span></span></b><b><span style="color: #7f0055; font-size: x-small;"><span style="color: #7f0055; font-size: x-small;"> interface</span></span></b><span style="font-size: x-small;"> TestHarnessRemote {</span>
<br />
<div align="left">
</div>
<div align="left">
}</div>
<div align="left">
<br />
<a name='more'></a><br />
</div>
After the changes:<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi899vk1n9dopcjOHlnfE2D-g302mY4oDSHKo_Fq7NCBa5NX2NskYbm6Xh9JxnqupOi7iWke19ifcwcNY7pb7lEp34dbdibs6UeamGrT4ZvVSyZmFtoeTPe7dX5Fj7RBQtrvcsAndnTtfw/s1600/ejb-interface-impl.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi899vk1n9dopcjOHlnfE2D-g302mY4oDSHKo_Fq7NCBa5NX2NskYbm6Xh9JxnqupOi7iWke19ifcwcNY7pb7lEp34dbdibs6UeamGrT4ZvVSyZmFtoeTPe7dX5Fj7RBQtrvcsAndnTtfw/s1600/ejb-interface-impl.png" /></a></div>
<div align="left">
<strong></strong></div>
<br />
<div align="left">
Here we added a method called runTest, and added WebService annotations.</div>
<h4>
Implement the Bean class.</h4>
<br />
<div align="left">
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEg_FxAZ-MVMPSpJDKfzAJoRprC2XOJfUyGdp0WPYiYeIj0xyMZwqG1-0uLlUujw9EFa5pFeTrzBSkQvTLCCyNckuE6MrHLAyADsg3qfqPeHdwtFHArdigWw0pYQZ5T_OR9UuJIF625tP_s/s1600/ejb-bean-impl.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEg_FxAZ-MVMPSpJDKfzAJoRprC2XOJfUyGdp0WPYiYeIj0xyMZwqG1-0uLlUujw9EFa5pFeTrzBSkQvTLCCyNckuE6MrHLAyADsg3qfqPeHdwtFHArdigWw0pYQZ5T_OR9UuJIF625tP_s/s1600/ejb-bean-impl.png" /></a></div>
</div>
<br />
<br />
The most important thing here is to specify <span style="font-size: x-small;">endpointInterface </span><span style="font-size: small;">in the WebService annotation. Without it, the class will compile and run, but fail when being called because the web service client needs an Interface instead of an actual class to call the web service. </span><br />
<br />
Also, pay attention to the warning next to the WebService annotation. It reads "<em>This EJB Web Service does not have a router module. Invocation of this web service would fail</em><strong>.</strong>" This is because a web service needs a web module to process the web service http requests. For that, we need to generate a router module.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgC1hn0wPMe4UXVUAFzP8spj0_n9eBNB1inrZpD7LCNyVnM3gNgsqexSrNJqmuK4_SCfefU75vOvtSVKsU4H2ZCs_nPia574_Zjnm7Fc9zpGQcAvYm1FUNN2xJOuPfgwxqd36da3iDQwPI/s1600/ejb-warning.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgC1hn0wPMe4UXVUAFzP8spj0_n9eBNB1inrZpD7LCNyVnM3gNgsqexSrNJqmuK4_SCfefU75vOvtSVKsU4H2ZCs_nPia574_Zjnm7Fc9zpGQcAvYm1FUNN2xJOuPfgwxqd36da3iDQwPI/s1600/ejb-warning.png" /></a></div>
<br />
<br />
<h4>
Generate a router Module</h4>
In Java EE perspective, right click the Service. Click "Create Router Modules (EndpointEnabler).<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhM2JQ-e1fOOmubkWyP4ui09TZejptsDJi75Esa_CrnVvPUVQ6JHjMq8n73ME2HINeCjz1dC9v4DEnGbQiR-TMSIP641XxVVCnKNulcShutxzYQ4pRVn4-8z1YkM22dqSVDjxLzOFCeHIM/s1600/ejb-generate-router.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhM2JQ-e1fOOmubkWyP4ui09TZejptsDJi75Esa_CrnVvPUVQ6JHjMq8n73ME2HINeCjz1dC9v4DEnGbQiR-TMSIP641XxVVCnKNulcShutxzYQ4pRVn4-8z1YkM22dqSVDjxLzOFCeHIM/s1600/ejb-generate-router.png" /></a></div>
Accept Default. Click Finish.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi6WjCiR4BWolPmtIkW0VDblxZuur1SKW3r8va7kK4qI43HTWo8BC-LsdadBI5SEDBqqG8hzezOXB2qOkG_Ggr2-sOIPLbuIABDKbmnGU0FPEvwcdX1KNHz4urvZon_6X-5ge0w-4GcWUI/s1600/ejb-generate-router-project.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi6WjCiR4BWolPmtIkW0VDblxZuur1SKW3r8va7kK4qI43HTWo8BC-LsdadBI5SEDBqqG8hzezOXB2qOkG_Ggr2-sOIPLbuIABDKbmnGU0FPEvwcdX1KNHz4urvZon_6X-5ge0w-4GcWUI/s1600/ejb-generate-router-project.png" /></a></div>
<br />
A web project Called TestHarness_HTTPRouter is created. Open the web.xml, the url mapping <span style="font-size: x-small;"></span><br />
/TestHarnessService <br />
appended by the default context root <span style="font-size: x-small;">TestHarness_HTTPRouter </span>will be the url to call this web service.<span style="font-size: x-small;"></span><br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgDwiGziqX-J86eCMyHQawGKmqS6eBK7xfzY7ENumdlR5h0V3oX3Pxbo70pwbN6iG8qzKC9PYaaBNNiSUf4mOWRIYL31XK9jOmr58U8r0VHXbdDYMnZmLMeDIVuYtU3ROw5ZuujL3IcK_o/s1600/ejb-generate-router-url.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgDwiGziqX-J86eCMyHQawGKmqS6eBK7xfzY7ENumdlR5h0V3oX3Pxbo70pwbN6iG8qzKC9PYaaBNNiSUf4mOWRIYL31XK9jOmr58U8r0VHXbdDYMnZmLMeDIVuYtU3ROw5ZuujL3IcK_o/s1600/ejb-generate-router-url.png" /></a></div>
<br />
Next, we are going to develop clients to test the EJB3 Stateless Session Bean and the JAX-WS web-service.<br />
<br />
<br />app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com1tag:blogger.com,1999:blog-6852471327555282869.post-73302566931777446372012-09-28T21:28:00.002-07:002012-10-04T11:36:49.125-07:00Tutorial : Building EJB3 Stateless Session Bean and JAX-WS web service In One Class Using RAD 7.5 - Project Setup<div class="separator" style="clear: both; text-align: left;">
This series is about building an empty shell application that contains an EJB3 stateless session bean, a JAX-WS web service, and a web application that acts as the EJB and web service clients. I personally built it for performance testing purpose; so I can plug-in "in-doubt" java code to oberve how they handle concurrency in a server environment. But this will serve as a tutorial for those who are interested.</div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless.html">Part 1</a> : Project Setup</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_28.html">Part 2</a> : EJB3 and JAX-WS Implementation</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_1704.html">Part 3</a> : Develop EJB3 client</div>
<div class="separator" style="clear: both; text-align: left;">
<a href="http://app-inf.blogspot.com/2012/09/tutorial-building-ejb3-stateless_29.html">Part 4</a> : Develop JAX-WS client</div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<br />
<a name='more'></a><br />
<h2 class="separator" style="clear: both; text-align: left;">
Tutorial : Building EJB3 Stateless Session Bean and JAX-WS web service In One Class Using RAD 7.5 - Project Setup</h2>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
<br /></div>
<div class="separator" style="clear: both; text-align: left;">
1. From Java EE perspective, create a new EJB project.</div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEjcXaJuvYoPtulRFJgwoOZVjZXScaw5ANj7GtMHScNs2OovwIUKcrlqj8eGoRbA85ged2dBZJblsaNUcUn6M28-6pl1iCuvaRFeQ7nksvXhegX7oJyzuP0Ne-f_1XYDIZxciIzXXG_UF4I/s1600/newEJB.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="222" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEjcXaJuvYoPtulRFJgwoOZVjZXScaw5ANj7GtMHScNs2OovwIUKcrlqj8eGoRbA85ged2dBZJblsaNUcUn6M28-6pl1iCuvaRFeQ7nksvXhegX7oJyzuP0Ne-f_1XYDIZxciIzXXG_UF4I/s320/newEJB.png" width="320" /></a></div>
<br />
2.Enter Project Name.Click Next.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhY-rkVewu1Ifa35xkMSW-gXOkDPXnLccU2N8D7Xh_c9GeOM-A5phDz7SuSsIbG3qZc9932dLKOpOf40Nldy0mdTWhPjSCxPSpcDEQe1MOKV_Me10CsjhWe5wBOBjV6wDRXg6uJz8FamRE/s1600/newEJB2.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="320" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhY-rkVewu1Ifa35xkMSW-gXOkDPXnLccU2N8D7Xh_c9GeOM-A5phDz7SuSsIbG3qZc9932dLKOpOf40Nldy0mdTWhPjSCxPSpcDEQe1MOKV_Me10CsjhWe5wBOBjV6wDRXg6uJz8FamRE/s320/newEJB2.png" width="270" /></a></div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
3. In my case I unchecked the Create EJB Client option, because I don't want the remote interface classes to be generated in a seperate Client Project. Click Finish.<br />
<div class="separator" style="clear: both; text-align: center;">
</div>
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhh8yeYq2w_73nWwnOpE8IjG4kSKoQthJy2XKFwdWOv5cgxDXAiGgw6mSaOqgP7JgTS1n-KFThy6fzMCCu9LzQPBdLA1FHVhV0NlDAdNTGgoKkqJjZN0s-VcQhqgLPYjQy2GmFLjSBT6Cc/s1600/newEJB-noclient.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="320" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEhh8yeYq2w_73nWwnOpE8IjG4kSKoQthJy2XKFwdWOv5cgxDXAiGgw6mSaOqgP7JgTS1n-KFThy6fzMCCu9LzQPBdLA1FHVhV0NlDAdNTGgoKkqJjZN0s-VcQhqgLPYjQy2GmFLjSBT6Cc/s320/newEJB-noclient.png" width="270" /></a></div>
<br />
4. Create a new Bean. New -> Session Bean.<br />
<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi_PqeXnYhVhMU7xWTLUL2df_alyNyniulHplusFh7F2pCrucQTkA4AVqO1dqJ0-Oo5jxJn8UIrM5E4tl5ADGapecdptmPEa1RAhXeYoI5z1K2r0gMuQdkRnmSJUm2WeNkmsSLaNcXAw24/s1600/newBean.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="244" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEi_PqeXnYhVhMU7xWTLUL2df_alyNyniulHplusFh7F2pCrucQTkA4AVqO1dqJ0-Oo5jxJn8UIrM5E4tl5ADGapecdptmPEa1RAhXeYoI5z1K2r0gMuQdkRnmSJUm2WeNkmsSLaNcXAw24/s320/newBean.png" width="320" /></a></div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
5. Enter Bean name and package name. Click Finish.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEipT4WkBhyphenhyphen275tRUxuzdRt6iCCKxu7LFe7OboLDwiMIan8suSsSDWj17_8cpztGJ3uhyphenhyphenmo7xTY9ZexkpwsVEl2KugxWZiXzQlIw9otte4DzwjMAG5VsjsC7GS-ncpdVDY7f65sv6KP1OYI/s1600/newBean2.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" height="296" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEipT4WkBhyphenhyphen275tRUxuzdRt6iCCKxu7LFe7OboLDwiMIan8suSsSDWj17_8cpztGJ3uhyphenhyphenmo7xTY9ZexkpwsVEl2KugxWZiXzQlIw9otte4DzwjMAG5VsjsC7GS-ncpdVDY7f65sv6KP1OYI/s320/newBean2.png" width="320" /></a></div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
<div class="separator" style="clear: both; text-align: center;">
<br /></div>
5. All right, here is what is generated. Next, we will add contents to the generated TestHarness and TestHarnessRemote classes.<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgkl4gIphqvlFeBj2TkQK230BrM2IXFtCL_JKkSHvqOysUkmjgDwSjAk1qkaCg2U9pLbpvnv_D8ZKqxclVq_ZNcaUhX-rXrinjTQAQeA4tsz9-_2avYUL9G3SsH-g4kUFZwNQM4PbNMExY/s1600/ejb-content.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" kea="true" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgkl4gIphqvlFeBj2TkQK230BrM2IXFtCL_JKkSHvqOysUkmjgDwSjAk1qkaCg2U9pLbpvnv_D8ZKqxclVq_ZNcaUhX-rXrinjTQAQeA4tsz9-_2avYUL9G3SsH-g4kUFZwNQM4PbNMExY/s1600/ejb-content.png" /></a></div>
<br />app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com0tag:blogger.com,1999:blog-6852471327555282869.post-46658886089704847242012-09-21T09:23:00.003-07:002012-10-04T11:39:21.892-07:00Keep Connections Alive : Browser - Load Balancer - Web Server - mod jk - Tomcat : Part 4<div class="post-title entry-title" itemprop="name">
This series is about how connections are kept alive between different components along the route.</div>
<div class="post-title entry-title" itemprop="name">
Browser - Load Balancer - Web Server - mod jk - Tomcat </div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk.html">Part 1</a> : Browser - Load Balancer.</div>
<div class="post-title entry-title" itemprop="name">
<a href="http://app-inf.blogspot.com/2012/09/conitnued-browser-load-balancer-web.html">Part 2</a> : Load Balancer - Apache HTTP Server</div>
<div class="post-title entry-title" itemprop="name">
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_21.html">Part 3</a> : Apache HTTP Server - Mod jk</div>
<div class="post-title entry-title" itemprop="name">
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_5682.html">Part 4</a> : Mod jk - Tomcat</div>
<div class="post-title entry-title" itemprop="name">
<a name='more'></a><br /></div>
<h3 class="post-title entry-title" itemprop="name">
Mod jk - Tomcat Servers </h3>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<h4 class="post-title entry-title" itemprop="name">
What might break the connection between mod_jk and tomcat servers during the processing of a request?</h4>
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"><span style="font-family: Times New Roman; font-size: small;"><div class="post-title entry-title" itemprop="name">
When mod_jk receives a request from the Apache web server, it will re-use or make a new connection to the Tomcat Servers. Many <a href="http://tomcat.apache.org/connectors-doc/reference/workers.html">configuration parameters</a> control how mod_jk manage and maintain the connection pool, or how a connection is acquired or probed before sending requests through it, but majorly, <em>once a request is accpeted and being processed by the Tomcat servers, </em>two parameters control the behaviour of the connection.</div>
<ul>
<li><div class="post-title entry-title" itemprop="name">
socket_timeout</div>
</li>
</ul>
<div class="post-title entry-title" itemprop="name">
Socket timeout in seconds used for the communication channel between JK and remote host. If the remote host does not respond inside the timeout specified, JK will generate an error, and retry again. If set to zero (default) JK will wait for an infinite amount of time on all socket operations. </div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
The source code for mod_jk, can be downloaded <a href="http://tomcat.apache.org/download-connectors.cgi">here</a>, shows that it uses this value to set receive timeout and send timeout. (jk_connect.c)</div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
<span lang="EN"></span></div>
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-size: x-small;">struct timeval tv;</span></span><br /><span style="font-family: "Courier New", Courier, monospace;"><span style="font-size: x-small;">tv.tv_sec = timeout;</span></span><br /><span style="font-family: "Courier New", Courier, monospace;"><span style="font-size: x-small;">tv.tv_usec = 0;</span></span><br /><span style="font-family: "Courier New", Courier, monospace;"><span style="font-size: x-small;">setsockopt(sd, SOL_SOCKET, SO_RCVTIMEO,</span></span><span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">(const void *) &tv, sizeof(tv));</span><br /><span style="font-family: "Courier New", Courier, monospace;"><span style="font-size: x-small;">setsockopt(sd, SOL_SOCKET, SO_SNDTIMEO,</span></span><span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">(const void *) &tv, sizeof(tv));</span></span></span>
<br />
<ul>
<li><div class="post-title entry-title" itemprop="name">
socket_keepalive</div>
</li>
</ul>
<span lang="EN">Mod_jk makes the following call if keepalive is set to true. <br /><br /><span lang="EN"><span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">if (keepalive) {</span></span><span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"> set = 1;</span></span><span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"> if (setsockopt(sd, SOL_SOCKET, SO_KEEPALIVE, (SET_TYPE)&set,</span><br />
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-size: x-small;">sizeof(set))) {</span></span><br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">...}}</span><br />
<span lang="EN"><br />However, as discussed in <a href="http://app-inf.blogspot.com/2012/09/conitnued-browser-load-balancer-web.html">part 2</a>, Linux's keepalive routines by default will not kick in until after two hours (7200 secs), controlled by the <span style="font-family: Courier New; font-size: xx-small;"><strong>tcp_keepalive_time </strong><span style="font-family: Times New Roman; font-size: x-small;">parameter.</span></span><br /><h4 class="post-title entry-title" itemprop="name">
The Answer</h4>
<div class="post-title entry-title" itemprop="name">
Remember, there is ususally not a load balancer, who likes to drop connections with its idle timeout setting, between mod_jk and tomcat servers. If there is no firewall in between, with socket_timeout defaulted to 0, the connection between mod_jk and tomcat will <em>never </em>get broken. <em>If it takes a hour for a servlet to return, the connection will be open for a hour, </em>even if the client times out a long time before. </div>
</span><br />
<ul>
<li><div class="post-title entry-title" itemprop="name">
How about setting socket_timeout to non-zero?<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"><span style="font-family: Times New Roman; font-size: small;"></span></span></div>
</li>
</ul>
<div class="post-title entry-title" itemprop="name">
If socket_timeout is set to a non-zero value, mod_jk will timeout on the connection. However, the tomcat server will still have a thread processing this request for however long it takes. In addition, if the mod_jk <em><a href="http://tomcat.apache.org/tomcat-5.5-doc/config/ajp.html">retires</a></em> parameter is defaulted to 2, mod_jk will resend the request to Tomcat. <em>If a request is known to take a long time, due to slow database query, or cpu processing, it really doesn't make sense for the mod_jk to timeout and retry.</em> Moreover, once mod_jk retries and times out again, it will mark the tomcat server as down, and if using a lb worker, mod_jk will retry on other tomcat servers in the lb, until every one fails. So my opinion is, don't specify the socket_timeout unless u know retry helps. </div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com1tag:blogger.com,1999:blog-6852471327555282869.post-72723201195168343372012-09-21T08:45:00.002-07:002012-10-04T11:24:12.250-07:00Keep Connections Alive : Browser - Load Balancer - Web Server - mod jk - Tomcat : Part 3<br />
This series is about how connections are kept alive between different components along the route.<br />
Browser - Load Balancer - Web Server - mod jk - Tomcat<br />
<br />
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk.html">Part 1</a> : Browser - Load Balancer.<br />
<a href="http://app-inf.blogspot.com/2012/09/conitnued-browser-load-balancer-web.html">Part 2</a> : Load Balancer - Apache HTTP Server<br />
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_21.html">Part 3</a> : Apache HTTP Server - Mod jk<br />
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_5682.html">Part 4</a> : Mod jk - Tomcat<br />
<br />
<h3>
Apache Web Server - Mod jk</h3>
<br />
<h4 class="post-title entry-title" itemprop="name">
Does mod_jk changes how Apache web server handles its connection with the clients?</h4>
<div class="post-title entry-title" itemprop="name">
Mod jk is a module that runs within the Apache web server. Apache web server will manage the connections between itself and the clients, usually web browsers or a load balancer, and pass the request to a chain of modules.</div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
Using the example described in an <a href="http://threebit.net/tutorials/apache2_modules/tut1/tutorial1.html">Apache module tutorial</a>, a module will register a hook with the web server and the web server will pass a <span style="font-family: Courier New; font-size: x-small;">request_rec</span> to the module.<br />
<a name='more'></a></div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">//register the hook</span></div>
<div class="post-title entry-title" itemprop="name">
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">static void mod_tut1_register_hooks (apr_pool_t *p)<br />{<br /> ap_hook_handler(mod_tut1_method_handler, NULL, NULL, APR_HOOK_LAST);<br />}</span></div>
<div class="post-title entry-title" itemprop="name">
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">//The hook takes a parameter as <strong>request_rec</strong> </span></div>
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">static int mod_tut1_method_handler (request_rec *r)<br />{<br /> fprintf(stderr,"apache2_mod_tut1: A request was made.\n");</span><br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"> fflush(stderr);</span><br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"> return DECLINED;<br />}</span><br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"><span style="font-family: Times New Roman; font-size: small;"><h4 class="post-title entry-title" itemprop="name">
The Answer </h4>
For the purpose of this article, the point is mod jk doesn't have the chance to meddle with the socket between web server and clients, for example, by setting additional keep-alive parameters.</span></span>
<br />
<h4>
More Things to Consider</h4>
The connection between mod_jk and Tomcat Servers is discussed in <a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_5682.html">part 4</a> of this topic.<br />
<br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;"><span style="font-family: Times New Roman; font-size: small;"><span lang="EN"></span></span></span>app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com0tag:blogger.com,1999:blog-6852471327555282869.post-87806460638509858212012-09-21T06:58:00.001-07:002012-10-04T11:24:23.994-07:00Keep Connections Alive : Browser - Load Balancer - Web Server - mod jk - Tomcat : Part 2<h3 class="post-title entry-title" itemprop="name">
</h3>
<div class="post-title entry-title" itemprop="name">
This series is about how connections are kept alive between different components along the route.</div>
<div class="post-title entry-title" itemprop="name">
Browser - Load Balancer - Web Server - mod jk - Tomcat </div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk.html">Part 1</a> : Browser - Load Balancer.</div>
<div class="post-title entry-title" itemprop="name">
<a href="http://app-inf.blogspot.com/2012/09/conitnued-browser-load-balancer-web.html">Part 2</a> : Load Balancer - Apache HTTP Server</div>
<div class="post-title entry-title" itemprop="name">
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_21.html">Part 3</a> : Apache HTTP Server - Mod jk</div>
<div class="post-title entry-title" itemprop="name">
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_5682.html">Part 4</a> : Mod jk - Tomcat</div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<h3 class="post-title entry-title" itemprop="name">
Load Balancer -> Apache Web Server</h3>
<br />
<h4 class="post-title entry-title" itemprop="name">
How is the connection between web server and load balancer maintained? </h4>
<div class="post-title entry-title" itemprop="name">
There is usually a seperate load balancer TCP profile for the connection between load balancer and the web servers. As described <a href="http://support.f5.com/kb/en-us/products/big-ip_ltm/manuals/product/ltm_configuration_guide_10_1/ltm_protocol_profiles.html#1211081">here</a>, the default "Idle Timeout" is 5 minutes and default "Keep Alive Interval" is 30 minutes.</div>
<div class="post-title entry-title" itemprop="name">
<br />
When a request comes in for a page that takes a long time to render, a connection is established between the load balancer and the web server and can be observed by the netstat command. </div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">> netstat -an | grep :81 |grep EST</span></div>
<div class="post-title entry-title" itemprop="name">
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">tcp 0 0 ::ffff:111.111.111.11:81 ::ffff:111.111.111.12:55789 ESTABLISHED </span></div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
After 5 minutes, netstat will show that the connection is gone, dropped by the load balancer even if the request is still being processed by downstream servers. So doesn't Apache web server send keep alive signals to the load balancer to maintain the connection, just as <a href="http://serverfault.com/questions/275409/keep-alive-and-timeout-behaviours-between-different-browsers-on-windows">Google Chrome</a> does? The answer is no.</div>
<div class="post-title entry-title" itemprop="name">
<a name='more'></a><br /></div>
<div class="post-title entry-title" itemprop="name">
Here is the <a href="http://svn.apache.org/viewvc/httpd/httpd/branches/2.4.x/server/listen.c?view=markup">source code</a> for Apache web server when it makes a connection. It makes the following call to setup Keep Alive sockets.</div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-size: x-small;">stat = apr_socket_opt_set(s, APR_SO_KEEPALIVE, one);</span> </span></div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
However, according to the linux documentation, <a href="http://www.tldp.org/HOWTO/TCP-Keepalive-HOWTO/usingkeepalive.html">here</a> and <a href="http://www.tldp.org/HOWTO/html_single/TCP-Keepalive-HOWTO/">here</a>, using default values, linux's keepalive routines will wait for two hours (7200 secs) before sending the first keepalive probe, and then resend it every 75 seconds.</div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<div class="post-title entry-title" itemprop="name">
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">cat /proc/sys/net/ipv4/tcp_keepalive_time -- > 7200<br />cat /proc/sys/net/ipv4/tcp_keepalive_intvl -- > 75<br />cat /proc/sys/net/ipv4/tcp_keepalive_probes -- > 9</span></div>
<div class="post-title entry-title" itemprop="name">
<br />
These OS-level settings can be overwritten by programs, but Apache web server doesn't make specific calls to change them. This means that it will not send keep-alive signals to the load balancer during its ususally short life. </div>
<div class="post-title entry-title" itemprop="name">
<br /></div>
<h4 class="post-title entry-title" itemprop="name">
The Answer </h4>
<div class="post-title entry-title" itemprop="name">
So, if you need the connection between LB and web server to be maintained longer than default value 5 minutes, you need to do either of the following:</div>
<ul>
<li><div class="post-title entry-title" itemprop="name">
Change the "<strong>Keep Alive Interval</strong>" setting on the load balancer TCP profile from 30 minutes (1800 secs) to 60 second.</div>
</li>
<li><div class="post-title entry-title" itemprop="name">
Change the <span style="font-family: Courier New; font-size: x-small;"><strong>tcp_keepalive_time </strong><span style="font-family: Times New Roman; font-size: small;">parameter on Linux that hosts Apache from two hours (7200 secs) to less than "<strong>Idle Timeout</strong>", which is 5 minutes. </span></span></div>
</li>
<li><div class="post-title entry-title" itemprop="name">
Change the "<strong>Idle Timeout</strong>" setting on the load balancer TCP profile from 5 minutes to longer</div>
</li>
</ul>
We used the first option, keeping the "keep alive interval" setting of the F5 server-side tcp profile in sync with the client-side tcp profile.<br />
<h4>
More Things to Consider</h4>
The connection between mod_jk and Tomcat Servers is discussed in <a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_5682.html">part 4</a> of this topic.app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com0tag:blogger.com,1999:blog-6852471327555282869.post-9244560919199765832012-09-19T09:05:00.001-07:002012-10-04T11:39:35.674-07:00Keep Connections Alive : Browser - Load Balancer - Web Server - mod jk - Tomcat : Part 1<h3>
</h3>
This series is about how connections are kept alive between different components along the route.<br />
Browser - Load Balancer - Web Server - mod jk - Tomcat<br />
<br />
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk.html">Part 1</a> : Browser - Load Balancer.<br />
<a href="http://app-inf.blogspot.com/2012/09/conitnued-browser-load-balancer-web.html">Part 2</a> : Load Balancer - Apache HTTP Server<br />
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_21.html">Part 3</a> : Apache HTTP Server - Mod jk<br />
<a href="http://app-inf.blogspot.com/2012/09/browser-load-balancer-web-server-mod-jk_5682.html">Part 4</a> : Mod jk - Tomcat<br />
<h3>
<a name='more'></a></h3>
<h3>
Browser -> Load Balancer</h3>
<br />
<h4>
How is the connection between web browser and load balancer maintained?</h4>
<span style="font-family: inherit;">I created a test.jsp that does nothing but sleep for 6 minutes. </span><br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">Thread.sleep(6 * 60 * 1000);//sleep for 1000 ms</span><span style="font-family: "Courier New", Courier, monospace;"></span><br />
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-family: Times New Roman;">I deployed it to the tomcat server and access it from IE. I got the "<span style="font-family: inherit; font-size: small;">Internet Explorer cannot display the webpage</span>" error after 5 minutes. </span></span><br />
<br />
<br />
<div class="separator" style="clear: both; text-align: center;">
<a href="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgEowoDcs4Tp-_D-8IUJK3l5DWK_IWd_wXHXp7JPr42pwfCR32AHDxNQikHEaDjoypgz6pC2pj9fXNZbKlpkz9ehtHbQZn6GxGoK239sQLphY4Zz_m3gpl8jI8AWf5UJqsoeyiihZxmqiM/s1600/InternetError.png" imageanchor="1" style="margin-left: 1em; margin-right: 1em;"><img border="0" hea="true" height="153" src="https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgEowoDcs4Tp-_D-8IUJK3l5DWK_IWd_wXHXp7JPr42pwfCR32AHDxNQikHEaDjoypgz6pC2pj9fXNZbKlpkz9ehtHbQZn6GxGoK239sQLphY4Zz_m3gpl8jI8AWf5UJqsoeyiihZxmqiM/s320/InternetError.png" width="320" /></a></div>
<br />
<h4>
Troubleshooting</h4>
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-family: Times New Roman;">This is such a difficult error to troubleshoot, because on the server side, everything is ok. </span></span><br />
<br />
<br />
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-family: Times New Roman;">From mod_jk.log, I got the following entry 1 minute after IE times out.</span></span><br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">[Wed Sep 19 10:31:11 2012] 360.003697 APP-INF 200 /Test/test.jsp</span><br />
<br />
<span style="font-family: Courier New; font-size: x-small;"><span style="font-family: inherit; font-size: small;"><span style="font-family: "Courier New", Courier, monospace;"><span style="font-family: Times New Roman;">From Apache web server access.log, I got the following entries. It does show that the test.jsp page was served 6 minutes late comparing with surrounding log entries, but the status code is 200, which means ok.</span></span></span><span style="font-family: Times New Roman;"></span> </span><br />
<br />
<span style="font-family: "Courier New", Courier, monospace; font-size: x-small;">[19/Sep/2012:10:30:59 -0400] "POST /blah"<br />[19/Sep/2012:10:25:11 -0400] "GET /Test/test.jsp HTTP/1.1" 200 207 <br />[19/Sep/2012:10:31:30 -0400] "POST /blah"</span><br />
<br />
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-family: Times New Roman;">Interestingly, when I hit the url from Google Chrome, everything is fine. After 6 minutes, the page got displayed. So what's the difference between IE and Google Chrome? It turns out that Google Chrome keeps sending keep-alive signals to the server that keeps the connection alive, and IE doesn't.</span></span><br />
<br />
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-family: Times New Roman;"><a href="http://serverfault.com/questions/275409/keep-alive-and-timeout-behaviours-between-different-browsers-on-windows">http://serverfault.com/questions/275409/keep-alive-and-timeout-behaviours-between-different-browsers-on-windows</a></span></span><br />
<br />
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-family: Times New Roman;">So, it was the connection between IE and Load Balancer that was dropped, by the load blancer. According to F5 load balancer manual, there is an "Idle Timeout" setting to the TCP Profile that "specifies the number of seconds that a connection is idle before the connection is eligible for deletion". The default is 5 minutes. </span></span><br />
<br />
<a href="http://support.f5.com/kb/en-us/products/big-ip_ltm/manuals/product/ltm_configuration_guide_10_1/ltm_protocol_profiles.html#1211081">http://support.f5.com/kb/en-us/products/big-ip_ltm/manuals/product/ltm_configuration_guide_10_1/ltm_protocol_profiles.html#1211081</a><br />
<h4>
</h4>
<h4>
The Fix</h4>
According to the F5 documentation, we changed the "<strong>Keep Alive Interval</strong>" setting on the load balancer TCP profile from 30 minutes (1800 secs) to 60 second. <br />
<br />
<a href="http://support.f5.com/kb/en-us/solutions/public/8000/000/sol8049.html">http://support.f5.com/kb/en-us/solutions/public/8000/000/sol8049.html</a><br />
<br />
<span style="font-family: "Courier New", Courier, monospace;"><span style="font-family: Times New Roman;">After the change, IE is able to display the page after 6 minutes, instead of getting the notorious "<span style="font-family: inherit; font-size: small;">Internet Explorer cannot display the webpage</span>" error. One can argue that normal pages don't take 6 minutes to display, but I have seen enough applications take that long either by design or under weird situations. Besides, by principal, load balancer should not time out the connection with client while keeping the connection with the backend open. </span></span><br />
<br />
<h4>
More Things to Consider</h4>
This takes care of the connection between web browser and load balancer. How about the connection between load balancer and web server? It is discussed in <a href="http://app-inf.blogspot.com/2012/09/conitnued-browser-load-balancer-web.html">part 2</a> of this topic.<br />
<br />app-infhttp://www.blogger.com/profile/09223162075640761112noreply@blogger.com0