Step-by-Step : How logging caused big performance problem for a JAX-WS web service

This 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.

What's the Number 1 Java Coding Best Practice?

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%?

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?

The only way to find out is performance testing, that is the only way you can fully understand the behaviour of your code in a server environment and identify potential performance killers.

 

Test Results Indicated Performance Problem

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 this tutorial. 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.

When the service is invoked by 20 users simultaneously, here is what we saw in the application logs.

[2/29/12 8:43:35:096 EST] 0000009e Total response time for xxxx Service : 1657 ms
[2/29/12 8:43:35:141 EST] 00000069 Total response time for xxxx Service : 961 ms
[2/29/12 8:43:35:372 EST] 00000062 Total response time for xxxx Service : 1177 ms
[2/29/12 8:43:46:860 EST] 000000e6 Total response time for xxxx Service : 3897 ms
[2/29/12 8:43:46:964 EST] 000000e9 Total response time for xxxx Service : 3868 ms
[2/29/12 8:43:47:803 EST] 00000060 Total response time for xxxx Service : 4502 ms
[2/29/12 8:43:47:960 EST] 000004d3 Total response time for xxxx Service : 4673 ms
[2/29/12 8:43:48:066 EST] 000000a2 Total response time for xxxx Service : 5064 ms
[2/29/12 8:43:48:250 EST] 00000062 Total response time for xxxx Service : 5047 ms
[2/29/12 8:43:48:265 EST] 00000089 Total response time for xxxx Service : 5064 ms
[2/29/12 8:43:48:335 EST] 00000069 Total response time for xxxx Service : 5203 ms
[2/29/12 8:43:48:346 EST] 000000e1 Total response time for xxxx Service : 5215 ms
[2/29/12 8:43:48:352 EST] 000000e7 Total response time for xxxx Service : 5135 ms

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 long time to figure out the real culprit. But knowing that there is a problem is 2/3 of the success, because most of the times you don't even know you have a problem.

• 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.
• 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. 

Application or Infrastructure?

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 web container thread pool 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.

Initial Code Review

I requested source code and here is what I reviewed. (Simplified for generalization purpose.)

• The main method:

try {
      final long startTime = System.currentTimeMillis();
      TestProcessing.getLogger().logp(Level.INFO, "HelloWorldBean", "hello", "Enter");
      callDAO(arg);
      final long endTime = System.currentTimeMillis();
      TestProcessing.getLogger().logp(Level.INFO, "HelloWorldBean", "hello",
                    "Exit, Total Time : " + (endTime - startTime));
    } catch (Exception e) {
            // TODO Auto-generated catch block
        e.printStackTrace();
        context.setRollbackOnly();
    }

• The callDAO method.

public String callDAO(GetOSRPolicyRqType arg) throws InterruptedException {
        TestProcessing.getLogger().logp(
                Level.FINE,
                "HelloWorldBean",
                "hello",
                new StringBuffer().append("request ").append(arg)).toString());

        String id = arg.getIdentifier();
        TestProcessingDAO.getBackendDataByID(id); // EJB3 Entity Bean Processing
        return "abc";
    }

• The getLogger method

static public Logger getLogger(){
        Logger log = null;
        log = Logger.getLogger("test");
        log = TestHandler.addFileHandler(log, "test");
        return log;        
    }

• The addFileHandler method

     public static Logger addFileHandler(Logger logger, String name) {
        try {
            if (logger != null && logger.getHandlers().length == 0) {
                FileHandler handler = new FileHandler("logs" + File.separator
                        + name + ".log", 1024 * 5000, 10, true);
                handler.setFormatter(new SimpleFormatter());
                logger.addHandler(handler);
            }
        } catch (Exception e) {
            e.printStackTrace();
        }
        return logger;
    }

Identify Possible Culprits

1. 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?
2. Logger is not cached. TestProcessing.getLogger() is called each time. Does it cause synchronization issue when invoked by multiple threads?
3. Logging too much. All logs are written to the same file, can file IO be the bottleneck?

Changes Logging  - Problem Resolved

The developers made the following two changes.

• The getLogger method now returns a static copy of the logger instance. 
• Following common known best practice, added isLoggable check before logging.

if (log.isLoggable(Level.FINE)){
            
        }

Tada, performance problem resolved. All requests took ~500ms now; no more spikes to 5203 ms 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...

But Logging is not the the Real Culprit

Months later, to document the root-cause of this incident, I decided to reproduce this problem using my TestHarness framework. I invoked java.util.logging.Logger 20 times per thread non-cached, logged 20 messages at a time, used JMeter to initiated 20, then 40 threads at a time, I cannot reproduce this problem. The overhead is minimal.

            for ( int i = 0; i < 20; i++ ){
            TestProcessing.getLogger().logp(Level.INFO, "HelloWorldBean",
                    "hello", "Enter");
            }
            //callDAO(arg);
            Thread.sleep(1000);
            final long endTime = System.currentTimeMillis();
            TestProcessing.getLogger().logp(Level.INFO, "HelloWorldBean",
                    "hello", "Exit, Total Time : " + (endTime - startTime));

I used Thread.sleep(1000)to simulate the business method, and the result shows the overhead of logging to be < 30ms.

[10:30:10:594] 0000003d Exit, Total Time : 1030
[10:30:10:656] 0000007c Exit, Total Time : 1014
[10:30:10:734] 00000043 Exit, Total Time : 1014
[10:30:10:781] 00000055 Exit, Total Time : 1030
[10:30:10:843] 0000004b Exit, Total Time : 1014
[10:30:10:859] 00000036 Exit, Total Time : 1030
[10:30:10:906] 0000004f Exit, Total Time : 1030
[10:30:10:999] 00000049 Exit, Total Time : 1014
[10:30:10:999] 00000057 Exit, Total Time : 1014
[10:30:11:108] 0000003f Exit, Total Time : 1029

The Real Culprit

Eventually, I went back to the source code repository and saw a piece of code that was not sent over the first time.

       if (log.isLoggable(Level.FINE)){
             
            TestProcessing.getLogger().logp(
                    Level.FINE,
                    "HelloWorldBean",
                    "hello",
                    new StringBuffer().append("request ").append(xmlToString(arg,"com.helloworld.dataobjects")).toString());
        }

Apparently,  .append(arg) doesn't print out the incoming JAXB requests in xml, so a utility method xmlToString(arg,"com.helloworld.dataobjects")was intoduced.

• Here is the xmlToString method.

private static String xmlToString(Object xmlObj, String cntxt) {
        String result = null;
        try {
            JAXBContext ctx = JAXBContext.newInstance(cntxt);
            Marshaller m = ctx.createMarshaller();
            StringWriter sw = new StringWriter();
            m.setProperty(Marshaller.JAXB_FORMATTED_OUTPUT, true);
            m.marshal(xmlObj, sw);
            result = sw.toString();
        } catch (Exception e) {
            TestProcessing.getLogger().logp(Level.INFO, "TestProcessing",
                    "process", "Exception" + e);
        }
        return result;
    }

It uses the JAXB marshaller to convert JAXB requests to xml. I performance tested the above code using my TestHarness and JMeter. Again, use Thread.sleep(1000)to simulate the business method, Here is the result.

Invoked by 1 user, the overhead is ~400ms, which is tremendous.

[10:55:15:855] 00000026 hello Exit, Total Time : 1420

Invoked by 20 users concurrently, it got worse.

[10:55:28:788] 0000003f hello Exit, Total Time : 2559
[10:55:29:100] 0000004c hello Exit, Total Time : 2527
[10:55:29:100] 00000055 hello Exit, Total Time : 2746
[10:55:29:100] 0000003b hello Exit, Total Time : 2824
[10:55:29:318] 0000004b hello Exit, Total Time : 2933
[10:55:30:254] 00000053 hello Exit, Total Time : 3432
[10:55:30:332] 0000003e hello Exit, Total Time : 3229
[10:55:30:473] 00000046 hello Exit, Total Time : 3276
[10:55:31:518] 0000007a hello Exit, Total Time : 4243
[10:55:31:752] 00000034 hello Exit, Total Time : 4524
[10:55:32:329] 000000ab hello Exit, Total Time : 4618
[10:55:32:469] 00000043 hello Exit, Total Time : 4758
[10:55:32:532] 00000050 hello Exit, Total Time : 4774
[10:55:32:563] 0000003c hello Exit, Total Time : 4789
[10:55:32:672] 00000048 hello Exit, Total Time : 6177
[10:55:32:672] 0000004a hello Exit, Total Time : 4961
[10:55:32:688] 00000054 hello Exit, Total Time : 4977
[10:55:32:766] 000000ac hello Exit, Total Time : 5086
[10:55:32:859] 0000004e hello Exit, Total Time : 6380
[10:55:32:875] 00000027 hello Exit, Total Time : 5179
So what exactly is wrong with the xmlToString  method? I generated thread dumps, (use kill -3 pid in Linux and follow this instruction in Windows,)  and the thread dumps attached at the end of this article point to

JAXBContext ctx = JAXBContext.newInstance(cntxt);

 
This is the problem code. JAXBContext.newInstance 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.)

What happens when I cached the JAXBContext instance by using a static variable? 

private static JAXBContext ctx;
    static {
        try {
            ctx = JAXBContext
                    .newInstance("com.hello.dataobjects");
        } catch (Exception e) {

        }
    }

Here is the result when invoked by 20 concurrent users. The actual marshalling, logging JAXB ojbects as xml, only adds ~14ms overhead.

[11:17:12:445] 0000004c hello Exit, Total Time : 1014
[11:17:12:492] 00000049 hello Exit, Total Time : 1014
[11:17:12:554] 00000053 hello Exit, Total Time : 1030
[11:17:12:616] 000000ae hello Exit, Total Time : 1029
[11:17:12:679] 00000034 hello Exit, Total Time : 1014
[11:17:12:694] 00000027 hello Exit, Total Time : 1014
[11:17:12:741] 00000078 hello Exit, Total Time : 1014
[11:17:12:788] 00000028 hello Exit, Total Time : 1014

The performance of JAXBContext.newInstance is a known issue. There is a great discussion here, which points out that JAXB 2.2 Specification recommends reusing a JAXBContext instance, that JAXBContext is thread safe while Marshaller is not. 

Takeaways

1. JAXBContext.newInstance is very expensive. It should be cached. Add it to your knowledge of java coding best practices.
2. Log, Log, Log. 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.
3. log.isLoggable is a very useful guard when the logging is unintentionally expensive. It prevented the bad version of xmlToString 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.     
4. Performace test your code. With so many new java frameworks being adopted, performance testing is the only way to find out traps. Junit is overrated. JMeter is under-rated.
5. It is worth it to get to the bottom of it. We didn't, and the bad version of xmlToString is being called in production in tens of other web services. 

Appendix : The Thread Dump

3XMTHREADINFO      "WebContainer : 17" TID:0x4D5D4E00, j9thread_t:0x4A5DD738, state:CW, prio=5
3XMTHREADINFO1            (native thread ID:0x13BC, native priority:0x5, native policy:UNKNOWN)
4XESTACKTRACE          at java/util/zip/Inflater.inflateBytes(Native Method)
4XESTACKTRACE          at java/util/zip/Inflater.inflate(Inflater.java:234(Compiled Code))
4XESTACKTRACE          at java/util/zip/InflaterInputStream.read(InflaterInputStream.java:141(Compiled Code))
4XESTACKTRACE          at java/util/zip/InflaterInputStream.read(InflaterInputStream.java:116(Compiled Code))
4XESTACKTRACE          at java/io/FilterInputStream.read(FilterInputStream.java:77(Compiled Code))
4XESTACKTRACE          at java/io/DataInputStream.readUnsignedShort(DataInputStream.java:332(Compiled Code))
4XESTACKTRACE          at java/io/DataInputStream.readUTF(DataInputStream.java:586(Compiled Code))
4XESTACKTRACE          at java/io/DataInputStream.readUTF(DataInputStream.java:558(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/bytecode/ClassTailor.tailor(ClassTailor.java:90(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/reflect/opt/AccessorInjector.tailor(AccessorInjector.java:95(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/reflect/opt/AccessorInjector.prepare(AccessorInjector.java:68(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/reflect/opt/OptimizedAccessorFactory.get(OptimizedAccessorFactory.java:140(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/reflect/Accessor$FieldReflection.optimize(Accessor.java:225(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/SingleElementNodeProperty.<init>(SingleElementNodeProperty.java:64(Compiled Code))
4XESTACKTRACE          at sun/reflect/GeneratedConstructorAccessor4.newInstance(Bytecode PC:36(Compiled Code))
4XESTACKTRACE          at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))
4XESTACKTRACE          at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/ArrayElementProperty.<init>(ArrayElementProperty.java:84(Compiled Code))
4XESTACKTRACE          at sun/reflect/GeneratedConstructorAccessor5.newInstance(Bytecode PC:36(Compiled Code))
4XESTACKTRACE          at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))
4XESTACKTRACE          at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/ArrayElementProperty.<init>(ArrayElementProperty.java:84(Compiled Code))
4XESTACKTRACE          at sun/reflect/GeneratedConstructorAccessor5.newInstance(Bytecode PC:36(Compiled Code))
4XESTACKTRACE          at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))
4XESTACKTRACE          at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/SingleElementNodeProperty.<init>(SingleElementNodeProperty.java:75(Compiled Code))
4XESTACKTRACE          at sun/reflect/GeneratedConstructorAccessor4.newInstance(Bytecode PC:36(Compiled Code))
4XESTACKTRACE          at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))
4XESTACKTRACE          at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/ArrayElementProperty.<init>(ArrayElementProperty.java:84(Compiled Code))
4XESTACKTRACE          at sun/reflect/GeneratedConstructorAccessor5.newInstance(Bytecode PC:36(Compiled Code))
4XESTACKTRACE          at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))
4XESTACKTRACE          at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:496(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/ArrayElementProperty.<init>(ArrayElementProperty.java:84(Compiled Code))
4XESTACKTRACE          at sun/reflect/GeneratedConstructorAccessor5.newInstance(Bytecode PC:36(Compiled Code))
4XESTACKTRACE          at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39(Compiled Code))
4XESTACKTRACE          at java/lang/reflect/Constructor.newInstance(Constructor.java:515(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/property/PropertyFactory.create(PropertyFactory.java:100(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:147(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.getOrCreate(JAXBContextImpl.java:477(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/runtime/JAXBContextImpl.<init>(JAXBContextImpl.java:311(Compiled Code))
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/ContextFactory.createContext(ContextFactory.java:115)
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/ContextFactory.createContext(ContextFactory.java:93)
4XESTACKTRACE          at com/sun/xml/internal/bind/v2/ContextFactory.createContext(ContextFactory.java:164)
4XESTACKTRACE          at sun/reflect/GeneratedMethodAccessor39.invoke(Bytecode PC:40)
4XESTACKTRACE          at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))
4XESTACKTRACE          at java/lang/reflect/Method.invoke(Method.java:599(Compiled Code))
4XESTACKTRACE          at com/ibm/xml/xlxp2/jaxb/JAXBContextImpl.createFallbackContext(JAXBContextImpl.java:230)
4XESTACKTRACE          at com/ibm/xml/xlxp2/jaxb/JAXBContextImpl.<init>(JAXBContextImpl.java:107)
4XESTACKTRACE          at com/ibm/xml/xlxp2/jaxb/JAXBContextFactory.createContext(JAXBContextFactory.java:37)
4XESTACKTRACE          at sun/reflect/NativeMethodAccessorImpl.invoke0(Native Method)
4XESTACKTRACE          at sun/reflect/NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:45(Compiled Code))
4XESTACKTRACE          at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))
4XESTACKTRACE          at java/lang/reflect/Method.invoke(Method.java:599(Compiled Code))
4XESTACKTRACE          at javax/xml/bind/ContextFinder.newInstance(ContextFinder.java:144)
4XESTACKTRACE          at javax/xml/bind/ContextFinder.find(ContextFinder.java:297(Compiled Code))
4XESTACKTRACE          at javax/xml/bind/JAXBContext.newInstance(JAXBContext.java:383(Compiled Code))
4XESTACKTRACE          at javax/xml/bind/JAXBContext.newInstance(JAXBContext.java:348(Compiled Code))
4XESTACKTRACE          at javax/xml/bind/JAXBContext.newInstance(JAXBContext.java:255(Compiled Code))
4XESTACKTRACE          at com/test/ejb/HelloWorldBean.xmlToString(HelloWorldBean.java:67(Compiled Code))
4XESTACKTRACE          at com/test/ejb/HelloWorldBean.hello(HelloWorldBean.java:38(Compiled Code))
4XESTACKTRACE          at sun/reflect/GeneratedMethodAccessor43.invoke(Bytecode PC:40)
4XESTACKTRACE          at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))