[Java] StackTrace란

StackTrace

스택 추적(스택 트레이스)란

프로그램이 시작된 시점부터 현재 위치까지의 메서드 호출 목록으로 어디서 예외가 발생했는지 추적하여 알려주는 역할

• 예외의 유형과 메시지, 예외가 발생했을 때 진행 중이던 모든 메서드 호출 목록

첫 번째 프레임은 JVM이 스택 추적을 생성하는 실행 지점

가장 먼저 실행된 메서드가 스택 추적의 마지막 스택 프레임이 되고 마지막에 실행된 메서드가 스택 추적의 첫 번째 스택 프레임

어떻게 생성?

• JVM은 예외가 발생하면 자동으로 Stack Trace를 생성
• Stack Trace에서 각 요소는 메서드 호출부를 나타내 예외가 발생한 위치를 추적
  • Stack Trace → 예외 → call stack에 있는 메소드 리스트를 저장
  • Throwable 클래스에서는 콘솔에서 Stack Trace를 출력하는 printStackTrace() 메서드를 제공

그래서 어떻게 읽을까요

• 예시

java.lang.reflect.InvocationTargetException
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
     at java.lang.reflect.Method.invoke(Unknown Source)
     at com.mylibrary.ap.xul.builder.handler.MethodCallback.invokeCallback(MethodCallback.java:32)
     at com.mylibrary.ap.xul.builder.handler.ViewHandler.invokeActionResult(ViewHandler.java:581)
     at com.mylibrary.ap.xul.context.impl.ViewContextImpl$2.onActionResult(ViewContextImpl.java:283)
     at com.mylibrary.ap.xul.context.impl.ActionContextImpl.setResult(ActionContextImpl.java:90)
     at com.mylibrary.ap.xul.action.stock.DialogAction.handleDialogClose(DialogAction.java:156)
     at com.mylibrary.ap.xul.action.stock.DialogAction$1.windowClosed(DialogAction.java:142)
     at com.mylibrary.api.Window.fireWindowClosedEvent(Unknown Source)
     at com.mylibrary.api.Window.onClose(Unknown Source)
     at com.mylibrary.api.platform.WindowBase.BaseClose(Native Method)
     at com.mylibrary.api.platform.WindowBase.BaseClose(Unknown Source)
     at com.mylibrary.api.Window.close(Unknown Source)
     at com.mylibrary.ap.xul.ui.MessageDialog.handleButtonClick(MessageDialog.java:145)
     at com.mylibrary.ap.xul.ui.MessageDialog$1.handleClick(MessageDialog.java:134)
     at com.mylibrary.api.ClickableSupport.fireClickEvent(Unknown Source)
     at com.mylibrary.api.ClickableSupport.handleAction(Unknown Source)
     at com.mylibrary.api.Button.actionHook(Unknown Source)
     at com.mylibrary.api.Component.action(Unknown Source)
Caused by: java.lang.NullPointerException
     at com.mycompany.service.impl.PortalManagerImpl.deleteMenuItem(PortalManagerImpl.java:603)
     at com.mycompany.service.impl.PortalManagerImpl.deletePortal(PortalManagerImpl.java:358)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
     at java.lang.reflect.Method.invoke(Unknown Source)
     at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
     at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
     at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
     at org.springframework.security.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:66)
     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
     at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
     at $Proxy54.deletePortal(Unknown Source)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
     at java.lang.reflect.Method.invoke(Unknown Source)
     at com.mycompany.util.SpringSecurityContextInvocationHandler.invoke(SpringSecurityContextInvocationHandler.java:62)
     at $Proxy84.deletePortal(Unknown Source)
     at com.mycompany.ui.binding.PortalDataProvider.doDelete(PortalDataProvider.java:81)
     at com.mycompany.ui.binding.PortalDataProvider.doDelete(PortalDataProvider.java:12)
     at com.mycompany.ui.binding.AbstractEISDataProvider.delete(AbstractEISDataProvider.java:105)
     at com.mylibrary.ap.xul.binding.dataset.impl.DatasetImpl.doCommit(DatasetImpl.java:90)
     at com.mylibrary.ap.xul.binding.dataset.impl.AbstractDataset.commit(AbstractDataset.java:251)
     at com.mylibrary.ap.xul.binding.dataset.impl.AbstractDataset.deleteRow(AbstractDataset.java:201)
     at com.mylibrary.ap.xul.action.dataset.DeleteDataRowAction.execute(DeleteDataRowAction.java:22)
     at com.mylibrary.ap.xul.context.impl.ViewContextImpl.execute(ViewContextImpl.java:294)
     at com.mycompany.ui.portal.PortalInfoHandler.onPostConfirmDeleteAction(PortalInfoHandler.java:192)
     ... 21 more

1. 먼저 예외 파악

java.lang.reflect.InvocationTargetException
// ...
Caused by: java.lang.NullPointerException

2. Caused by 보기

Caused by → 근본 즉, 원인인 부분 → 분석하기!

Caused by: java.lang.NullPointerException
     at com.mycompany.service.impl.PortalManagerImpl.deleteMenuItem(PortalManagerImpl.java:603)
     at com.mycompany.service.impl.PortalManagerImpl.deletePortal(PortalManagerImpl.java:358)

3. 해석하기

• 'com.mycompany.service.impl.PortalManagerImpl' 클래스의 'deletePortal' 메소드 358라인에서, 같은 클래스의 'deleteMenuItem'메소드를 호출했는데 해당 메소드 603번 째 줄에서 널포인터 예외가 발생

4. 예외가 발생한 부분으로 가기

if (item == null) {
    throw new NullArgumentException("item");
}

// 중간 생략
**List<PortalMenu> children = getMenuItems(item.getPortal().getId(), item.getId()); // 603번째 줄**

for (PortalMenu child : children) {
    deleteMenuItem(child);
 }

예외가 발생할만 한 경우의 수

1. children
2. item
3. item.getPortal()
4. item.getPortal().getId()
5. item.getId()

5. 예외가 발생한 부분 찾기

1. children
   • NPE는 명확하게 객체의 널값 참조에 메서드 호출이나 필드 참조 등의 작업을 했을 때 발생하는 문제 → null값이 할당되었다고 해서 NPE가 발생 X
2. item
   • 코드상에서 item 변수는 위에서 널 체크를 하기 때문에 603번째 줄에서 널값을 가질 수 없다.
3. item.getPortal() 
4. item.getPortal().getId()
5. item.getId()
   • 4, 5 → 만약 item.getPortal().getId()와 item.getId()이 null이라면 이는 null값 참조에 대한 호출이 아닌 널값을 getMenuItems 메서드의 인자로 넘기는 것뿐이기 때문에 NPE가 발생하는 원인이 될 수 없다.

추가로 성능에 대한 것들

Exception이 성능에 영향을 준다.

그 이유 중 하나가 Filling in the stack trace is slow

• 한 예외마다 대략 1~5ms정도의 시간이 걸린다.
• 이 대부분의 시간은 exception thread stack을 채우는 데 걸리는 시간이다. stack trace가 깊을 수록, 더 오랜 시간이 걸린다.

@ControllerAdvice

• stack depth에 따라 비용이 다른데 프레임워크(ex> Spring)위에서 실행되는 서비스의 경우 복잡도에 따라 stack depth가 엄청 깊어지기 때문에
• exception 생성 비용은 훨씬 더 비싸지게 됩니다

Java Exception 생성 비용은 비싸다. : NHN Cloud Meetup

 

라이브러리…

라이브러리가 많은 대규모 프로젝트에서는 스택 트레이스가 수백 줄에 달할 수 있으므로 큰 스택 트레이스가 보이면 at ...에서 ...에서 ...의 목록을 스캔하여 자신의 코드를 찾아보는 연습이 필요한 것 같다.

한 개 더 예시

javax.servlet.ServletException: Something bad happened
    at com.example.myproject.OpenSessionInViewFilter.doFilter(OpenSessionInViewFilter.java:60)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.example.myproject.ExceptionHandlerFilter.doFilter(ExceptionHandlerFilter.java:28)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.example.myproject.OutputBufferFilter.doFilter(OutputBufferFilter.java:33)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
    at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
    at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
    at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
    at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)
    at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
    at org.mortbay.jetty.Server.handle(Server.java:326)
    at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
    at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:943)
    at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756)
    at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
    at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
    at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.java:228)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)
**Caused by: com.example.myproject.MyProjectServletException**
    at com.example.myproject.MyServlet.doPost(MyServlet.java:169)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166)
    at com.example.myproject.OpenSessionInViewFilter.doFilter(OpenSessionInViewFilter.java:30)
    ... 27 more
**Caused by: org.hibernate.exception.ConstraintViolationException: could not insert: [com.example.myproject.MyEntity]**
    at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:96)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
    at org.hibernate.id.insert.AbstractSelectingDelegate.performInsert(AbstractSelectingDelegate.java:64)
    at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2329)
    at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2822)
    at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:71)
    at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:268)
    at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:321)
    at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:204)
    at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:130)
    at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:210)
    at org.hibernate.event.def.DefaultSaveEventListener.saveWithGeneratedOrRequestedId(DefaultSaveEventListener.java:56)
    at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:195)
    at org.hibernate.event.def.DefaultSaveEventListener.performSaveOrUpdate(DefaultSaveEventListener.java:50)
    at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93)
    at org.hibernate.impl.SessionImpl.fireSave(SessionImpl.java:705)
    at org.hibernate.impl.SessionImpl.save(SessionImpl.java:693)
    at org.hibernate.impl.SessionImpl.save(SessionImpl.java:689)
    at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:344)
    at $Proxy19.save(Unknown Source)
    **at com.example.myproject.MyEntityService.save(MyEntityService.java:59) <-- relevant call (see notes below)**
    at com.example.myproject.MyServlet.doPost(MyServlet.java:164)
    ... 32 more
**Caused by: java.sql.SQLException: Violation of unique constraint MY_ENTITY_UK_1: duplicate value(s) for column(s) MY_COLUMN in statement [...]**
    at org.hsqldb.jdbc.Util.throwError(Unknown Source)
    at org.hsqldb.jdbc.jdbcPreparedStatement.executeUpdate(Unknown Source)
    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:105)
    at org.hibernate.id.insert.AbstractSelectingDelegate.performInsert(AbstractSelectingDelegate.java:57)
    ... 54 moref

라이브러리 호출 메서드를 제외하고 우리가 작성한 코드의 메서드에서 첫 메서드 호출 찾기

 

 

참고한 글

OKKY - 초보 개발자를 위한 스택트레이스 읽는 법

What is a stack trace, and how can I use it to debug my application errors?

[JAVA] 예외처리의 비용