Thursday, August 22, 2013

Log4j fillInStackTrace() show shorter info in stacktrace

private static Logger logger = Logger.getLogger(...);

try {
   ...
}
catch( Exception e ) {
   logger.error("blah blah blah", e);  // (1)

   logger.error("blah blah blah", e.fillInStackTrace());  // (2)
}
The above code got my attention as I was wonder whether (2) is more cheaper than (1)? According to the expect, there are difference between the 2. (1) will show the original position of a stack frame where the error came from whereas (2) will pop up the old stack frame by filling in the current stack frame, thus the original stack frame were gone. In addition to that, (1) is more cheaper than (2) due to fillInStackTrace() is a synchronize function, thus this will eat up some resource when filling a log.

Below is the test result when I'm using logger.error("...", e), I have this stack trace shown
ERROR 2013-08-21 09:48:18,728 [AddUserAction:129] - An error has occurred in submitUser() 
org.hibernate.HibernateException: Hibernate Exception lor
 at org.huahsin.dao.impl.UserDaoImpl.saveUser(UserDaoImpl.java:35)
 at org.huahsin.bo.impl.AdminBoImpl.addUser(AdminBoImpl.java:275)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:597)
 at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
 at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
 at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
 at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
 at $Proxy19.addUser(Unknown Source)
 at org.huahsin.AddUserAction.submitUser(AddUserAction.java:120)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:597)
 at org.apache.el.parser.AstValue.invoke(AstValue.java:266)
 at org.apache.el.MethodExpressionImpl.invoke(MethodExpressionImpl.java:278)
 at org.apache.jasper.el.JspMethodExpression.invoke(JspMethodExpression.java:70)
 at javax.faces.component._MethodExpressionToMethodBinding.invoke(_MethodExpressionToMethodBinding.java:88)
 at org.apache.myfaces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:100)
 at javax.faces.component.UICommand.broadcast(UICommand.java:120)
 at javax.faces.component.UIViewRoot._broadcastAll(UIViewRoot.java:937)
 at javax.faces.component.UIViewRoot.broadcastEvents(UIViewRoot.java:271)
 at javax.faces.component.UIViewRoot._process(UIViewRoot.java:1249)
 at javax.faces.component.UIViewRoot.processApplication(UIViewRoot.java:675)
 at org.apache.myfaces.lifecycle.InvokeApplicationExecutor.execute(InvokeApplicationExecutor.java:34)
 at org.apache.myfaces.lifecycle.LifecycleImpl.executePhase(LifecycleImpl.java:171)
 at org.apache.myfaces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118)
 at javax.faces.webapp.FacesServlet.service(FacesServlet.java:189)
 at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1221)
 at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:757)
 at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:440)
 at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:125)
 at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:92)
 at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:97)
 at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:192)
 at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
 at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:144)
 at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:192)
 at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
 at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:939)
 at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1036)
 at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:81)
 at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:930)
 at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$1.run(DynamicVirtualHost.java:253)
 at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:457)
 at com.ibm.ws.threading.internal.Worker.executeWork(Worker.java:398)
 at com.ibm.ws.threading.internal.Worker.run(Worker.java:380)
 at java.lang.Thread.run(Thread.java:662)

Next is the test result when I'm using logger.error("...", e.fillInStackTrace()), I have this stack trace shown
ERROR 2013-08-21 09:50:46,987 [AddUserAction:129] - An error has occurred in submitUser() 
org.hibernate.HibernateException: Hibernate Exception lor
 at org.huahsin.AddUserAction.submitUser(AddUserAction.java:129)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:597)
 at org.apache.el.parser.AstValue.invoke(AstValue.java:266)
 at org.apache.el.MethodExpressionImpl.invoke(MethodExpressionImpl.java:278)
 at org.apache.jasper.el.JspMethodExpression.invoke(JspMethodExpression.java:70)
 at javax.faces.component._MethodExpressionToMethodBinding.invoke(_MethodExpressionToMethodBinding.java:88)
 at org.apache.myfaces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:100)
 at javax.faces.component.UICommand.broadcast(UICommand.java:120)
 at javax.faces.component.UIViewRoot._broadcastAll(UIViewRoot.java:937)
 at javax.faces.component.UIViewRoot.broadcastEvents(UIViewRoot.java:271)
 at javax.faces.component.UIViewRoot._process(UIViewRoot.java:1249)
 at javax.faces.component.UIViewRoot.processApplication(UIViewRoot.java:675)
 at org.apache.myfaces.lifecycle.InvokeApplicationExecutor.execute(InvokeApplicationExecutor.java:34)
 at org.apache.myfaces.lifecycle.LifecycleImpl.executePhase(LifecycleImpl.java:171)
 at org.apache.myfaces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118)
 at javax.faces.webapp.FacesServlet.service(FacesServlet.java:189)
 at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1221)
 at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:757)
 at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:440)
 at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:125)
 at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:92)
 at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:97)
 at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:192)
 at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
 at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:144)
 at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:192)
 at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
 at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:939)
 at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1036)
 at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:81)
 at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:930)
 at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$1.run(DynamicVirtualHost.java:253)
 at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:457)
 at com.ibm.ws.threading.internal.Worker.executeWork(Worker.java:398)
 at com.ibm.ws.threading.internal.Worker.run(Worker.java:380)
 at java.lang.Thread.run(Thread.java:662)

Notice that (2) has much shorter stack trace. I personally prefer the (1) due to the reason I have more information on understanding the original root cause of the problem.

No comments: