Стек трейс ошибки

Простыми словами, трассировка стека – это список методов, которые были вызваны до момента, когда в приложении произошло исключение.

Простой случай

В указанном примере мы можем точно определить, когда именно произошло исключение. Рассмотрим трассировку стека:

Exception in thread "main" java.lang.NullPointerException
       at com.example.myproject.Book.getTitle(Book.java:16)
       at com.example.myproject.Author.getBookTitles(Author.java:25)
       at com.example.myproject.Bootstrap.main(Bootstrap.java:14)

Это пример очень простой трассировки. Если пойти по списку строк вида «at…» с самого начала, мы можем понять, где произошла ошибка. Мы смотрим на верхний вызов функции. В нашем случае, это:

at com.example.myproject.Book.getTitle(Book.java:16)

Для отладки этого фрагмента открываем Book.java и смотрим, что находится на строке 16:

public String getTitle() {
    System.out.println(title.toString()); <-- line 16
    return title;
}

Это означает то, что в приведенном фрагменте кода какая-то переменная (вероятно, title) имеет значение null.

Пример цепочки исключений

Иногда приложения перехватывают исключение и выбрасывают его в виде другого исключения. Обычно это выглядит так:

try {
    ....
} catch (NullPointerException e) {
    throw new IllegalStateException("A book has a null property", e)
}

Трассировка в этом случае может иметь следующий вид:

Exception in thread "main" java.lang.IllegalStateException: A book has a null property
       at com.example.myproject.Author.getBookIds(Author.java:38)
       at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Caused by: java.lang.NullPointerException
       at com.example.myproject.Book.getId(Book.java:22)
       at com.example.myproject.Author.getBookIds(Author.java:35)
       ... 1 more

В этом случае разница состоит в атрибуте «Caused by» («Чем вызвано»). Иногда исключения могут иметь несколько секций «Caused by». Обычно необходимо найти исходную причину, которой оказывается в самой последней (нижней) секции «Caused by» трассировки. В нашем случае, это:

Caused by: java.lang.NullPointerException <-- root cause
       at com.example.myproject.Book.getId(Book.java:22) <-- important line

Аналогично, при подобном исключении необходимо обратиться к строке 22 книги Book.java, чтобы узнать, что вызвало данное исключение – NullPointerException.

Еще один пугающий пример с библиотечным кодом

Как правило, трассировка имеет гораздо более сложный вид, чем в рассмотренных выше случаях. Приведу пример (длинная трассировка, демонстрирующая несколько уровней цепочек исключений):

javax.servlet.ServletException: Произошло что–то ужасное
   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 more

В этом примере приведен далеко не полный стек вызовов. Что вызывает здесь наибольший интерес, так это поиск функций из нашего кода – из пакета com.example.myproject. В предыдущем примере мы сначала хотели отыскать «первопричину», а именно:

Caused by: java.sql.SQLException

Однако все вызовы методов в данном случае относятся к библиотечному коду. Поэтому мы перейдем к предыдущей секции «Caused by» и найдем первый вызов метода из нашего кода, а именно:

at com.example.myproject.MyEntityService.save(MyEntityService.java:59)

Аналогично предыдущим примерам, необходимо обратить внимание на MyEntityService.java, строка 59: именно здесь появилась ошибка (в данном случае ситуация довольно очевидная, так как об ошибке сообщает SQLException, но в этом вопросе мы рассматриваем именно процедуру отладки с помощью трассировки).

_{Перевод ответа: «What is a stack trace, and how can I use it to debug my application errors?» @Rob Hruska}

From Wikipedia, the free encyclopedia

«Backtrace» redirects here. For the 2018 film, see Backtrace (film).

In computing, a stack trace (also called stack backtrace^[1] or stack traceback^[2]) is a report of the active stack frames at a certain point in time during the execution of a program. When a program is run, memory is often dynamically allocated in two places; the stack and the heap. Memory is continuously allocated on a stack but not on a heap, thus reflective of their names. Stack also refers to a programming construct, thus to differentiate it, this stack is referred to as the program’s function call stack. Technically, once a block of memory has been allocated on the stack, it cannot be easily removed as there can be other blocks of memory that were allocated before it. Each time a function is called in a program, a block of memory called an activation record is allocated on top of the call stack. Generally, the activation record stores the function’s arguments and local variables. What exactly it contains and how it’s laid out is determined by the calling convention.

Programmers commonly use stack tracing during interactive and post-mortem debugging. End-users may see a stack trace displayed as part of an error message, which the user can then report to a programmer.

A stack trace allows tracking the sequence of nested functions called — up to the point where the stack trace is generated. In a post-mortem scenario this extends up to the function where the failure occurred (but was not necessarily caused). Sibling calls do not appear in a stack trace.

Language support[edit]

Many programming languages, including Java^[3] and C#,^[4] have built-in support for retrieving the current stack trace via system calls. Before std::stacktrace was added in standard library as a container for std::stacktrace_entry, pre-C++23 has no built-in support for doing this, but C++ users can retrieve stack traces with (for example) the stacktrace library. In JavaScript, exceptions hold a stack property that contain the stack from the place where it was thrown.

Python[edit]

As an example, the following Python program contains an error.

def a():
    i = 0
    j = b(i)
    return j

def b(z):
    k = 5
    if z == 0:
        c()
    return k + z

def c():
    error()

a()

Running the program under the standard Python interpreter produces the following error message.

Traceback (most recent call last):
  File "tb.py", line 15, in <module>
    a()
  File "tb.py", line 3, in a
    j = b(i)
  File "tb.py", line 9, in b
    c()
  File "tb.py", line 13, in c
    error()
NameError: name 'error' is not defined

The stack trace shows where the error occurs, namely in the c function. It also shows that the c function was called by b, which was called by a, which was in turn called by the code on line 15 (the last line) of the program. The activation records for each of these three functions would be arranged in a stack such that the a function would occupy the bottom of the stack and the c function would occupy the top of the stack.

Java[edit]

In Java, stack traces can be dumped manually with Thread.dumpStack()^[5] Take the following input:

public class Main {
  public static void main(String args[]) {
    demo();
  }
  static void demo() {
    demo1();
  }
  static void demo1() {
    demo2();
  }
  static void demo2() {
    demo3();
  }
  static void demo3() {
    Thread.dumpStack();
  }
}

The exception lists functions in descending order, so the most-inner call is first.

java.lang.Exception: Stack trace
        at java.lang.Thread.dumpStack(Thread.java:1336)
        at Main.demo3(Main.java:15)
        at Main.demo2(Main.java:12)
        at Main.demo1(Main.java:9)
        at Main.demo(Main.java:6)
        at Main.main(Main.java:3)

C and C++[edit]

Both C and C++ (pre-C++23) do not have native support for obtaining stack traces, but libraries such as glibc and boost provide this functionality.^[6][7] In these languages, some compiler optimizations may interfere with the call stack information that can be recovered at runtime. For instance, inlining can cause missing stack frames, tail call optimizations can replace one stack frame with another, and frame pointer elimination can prevent call stack analysis tools from correctly interpreting the contents of the call stack.^[6]

For example, glibc’s backtrace() function returns an output with the program function and memory address.

./a.out() [0x40067f]
./a.out() [0x4006fe]
./a.out() [0x40070a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5) [0x7f7e60738f45]
./a.out() [0x400599]

As of C++23, stack traces can be dumped manually by printing the value returned by static member function std::stacktrace::current():^[8]

std::cout << std::stacktrace::current() << 'n';

Rust[edit]

Rust has two types of errors. Functions that use the panic macro are «unrecoverable» and the current thread will become poisoned experiencing stack unwinding. Functions that return a std::result::Result are «recoverable» and can be handled gracefully.^[9] However, recoverable errors cannot generate a stack trace as they are manually added and not a result of a runtime error.

As of June 2021, Rust has experimental support for stack traces on unrecoverable errors. Rust supports printing to stderr when a thread panics, but it must be enabled by setting the RUST_BACKTRACE environment variable.^[10]

When enabled, such backtraces look similar to below, with the most recent call first.

thread 'main' panicked at 'execute_to_panic', main.rs:3
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
   1: std::panicking::default_hook::{{closure}}
   2: std::panicking::default_hook
   3: std::panicking::rust_panic_with_hook
   4: std::panicking::begin_panic
   5: futures::task_impl::with
   6: futures::task_impl::park
...

See also[edit]

• Tail call
• Context (computing)
• Stack overflow
• Exception handling
• Call stack

References[edit]

Deploying your Java code to production limits your troubleshooting options. Connecting to your app in production with a debugger is usually out of the question, and you might not even be able to get console access. So even with monitoring, you’re going to end up troubleshooting many problems post-mortem. This means looking at logs and, if you’re lucky, working with a Java stack trace.

That’s right, I said you’re lucky if you have a stack trace. It’s like getting a compass, a map, and a first-class airplane ticket handed to you all at once! Let’s talk about what a Java stack trace is and how you can use it.

What’s a Java Stack Trace?

A stack trace, also called a stack backtrace or even just a backtrace, is a list of stack frames. These frames represent a moment during an application’s execution. A stack frame is information about a method or function that your code called. So the Java stack trace is a list of frames that starts at the current method and extends to when the program started.

Sometimes there’s confusion between a stack and the Stack. A stack is a data structure that acts as a stack of papers on your desk: it’s first-in-last-out. You add documents to the pile and take them off in the reverse order you put them there. The Stack, more accurately called the runtime or call stack, is a set of stack frames a program creates as it executes, organized in a stack data structure.

Let’s look at an example.

Java Stack Trace Example

Let’s take a look at a Java program. This class calls four methods and prints a stack trace to the console from the

public class StackTrace {

  public static void main(String[] args) {
    a();
  }

  static void a() {
    b();
  }

  static void b() {
    c();
  }

  static void c() {
    d();
  }

  static void d() {
    Thread.dumpStack();
  }
}

When you run the class, you’ll see something like this:

java.lang.Exception: Stack trace
at java.base/java.lang.Thread.dumpStack(Thread.java:1383)
at com.ericgoebelbecker.stacktraces.StackTrace.d(StackTrace.java:23)
at com.ericgoebelbecker.stacktraces.StackTrace.c(StackTrace.java:19)
at com.ericgoebelbecker.stacktraces.StackTrace.b(StackTrace.java:15)
at com.ericgoebelbecker.stacktraces.StackTrace.a(StackTrace.java:11)
at com.ericgoebelbecker.stacktraces.StackTrace.main(StackTrace.java:7)

The d() method() is at the top of the stack because that’s where the app generated the trace. The main() method is at the bottom because that’s where the program started. When the program started, the Java runtime executed the main() method. Main() called a(). A() called b(),  and b() called c(), which called d(). Finally, d() called dumpStack(), which generated the output. This Java stack trace gives us a picture of what the program did, in the order that it did it.

A Java stack trace is a snapshot of a moment in time. You can see where your application was and how it got there. That’s valuable insight that you can use a few different ways.

How to Use Java Stack Traces

Now that you’ve seen what Java stack traces show you, how can you use them?

Java Exceptions

Stack traces and exceptions are often associated with each other. When you see a Java application throw an exception, you usually see a stack trace logged with it. This is because of how exceptions work.

When Java code throws an exception, the runtime looks up the stack for a method that has a handler that can process it. If it finds one, it passes the exception to it. If it doesn’t, the program exits. So exceptions and the call stack are linked directly. Understanding this relationship will help you figure out why your code threw an exception.

Let’s change our sample code.

First, modify the d() method:

static void d() {
  throw new NullPointerException("Oops!");
}

Then, change main() and a() so main can catch an exception. You’ll need to add a checked exception to a() so the code will compile.

public static void main(String[] args) 
{
  try {
    a();
  } catch (InvalidClassException ice) {
    System.err.println(ice.getMessage());
  }
}

static void a() throws InvalidClassException 
{
  b();
}

You’re deliberately catching the “wrong” exception. Run this code and watch what happens.

Exception in thread "main" java.lang.NullPointerException: Oops!
at com.ericgoebelbecker.stacktraces.StackTrace.d(StackTrace.java:29)
at com.ericgoebelbecker.stacktraces.StackTrace.c(StackTrace.java:24)
at com.ericgoebelbecker.stacktraces.StackTrace.b(StackTrace.java:20)
at com.ericgoebelbecker.stacktraces.StackTrace.a(StackTrace.java:16)
at com.ericgoebelbecker.stacktraces.StackTrace.main(StackTrace.java:9)

The exception bubbled up the stack past main() because you were trying to catch a different exception. So the runtime threw it, terminating the application. You can still see a stack trace though, so it’s easy to determine what happened.

Now, change main() to catch a NullPointerException instead. You can remove the checked exception from a() too.

public static void main(String[] args) {
  try {
    a();
  } catch (NullPointerException ice) {
    System.err.println(ice.getMessage());
  }
}

static void a() {
  b();
}

Rerun the program.

Oops!

We lost the stack trace! By only printing the message attached to the exception, you missed some vital context. Unless you can remember why you wrote Oops! in that message, tracking down this problem is going to be

public static void main(String[] args) {
  try {
    a();
  } catch (NullPointerException npe) {
    npe.printStackTrace();
  }
}

Rerun the application.

java.lang.NullPointerException: Oops!
at com.ericgoebelbecker.stacktraces.StackTrace.d(StackTrace.java:28)
at com.ericgoebelbecker.stacktraces.StackTrace.c(StackTrace.java:24)
at com.ericgoebelbecker.stacktraces.StackTrace.b(StackTrace.java:20)
at com.ericgoebelbecker.stacktraces.StackTrace.a(StackTrace.java:16)
at com.ericgoebelbecker.stacktraces.StackTrace.main(StackTrace.java:9)

That’s better! We see the stack trace, and it ends at d() where the exception occurred, even though main() printed it.

Logging Java Stack Traces

What if you don’t want to print an error message to the console but to a log file instead? The good news is that most loggers, including Log4j and Logback, will write exceptions with stack traces if you call them with the right arguments.

Pass in the exception object as the last argument to the message, without a formatting directive. So if you used Log4j or Logback with the sample code like this:

logger.error(“Something bad happened:”, npe);

You would see this in your log file:

Something bad happened:
java.lang.NullPointerException: Oops!
at com.ericgoebelbecker.stacktraces.StackTrace.d(StackTrace.java:28)
at com.ericgoebelbecker.stacktraces.StackTrace.c(StackTrace.java:24)
at com.ericgoebelbecker.stacktraces.StackTrace.b(StackTrace.java:20)
at com.ericgoebelbecker.stacktraces.StackTrace.a(StackTrace.java:16)
at com.ericgoebelbecker.stacktraces.StackTrace.main(StackTrace.java:9)

One of the best things you can do with exceptions and stack traces is to log them so you can use them to isolate a problem. If you get in the habit of printing useful log messages with details like stack traces and log indexing, then search tools, like Scalyr, become one of the most powerful tools in your troubleshooting tool bag.

The Java Debugger

Debuggers work by taking control of a program’s runtime and letting you both observe and control it. To do this, it shows you the program stack and enables you to traverse it in either direction. When you’re in a debugger, you get a more complete picture of a stack frame than you do when looking at stack traces in a log message.

Let’s make a small code change and then throw the sample code into a debugger.

First, add a local variable to the d() method:

static void d() {
  String message = “Oops.”
  throw new NullPointerException(message);
}

Then add a breakpoint where d() throws the exception in your debugger. I’m using IntelliJ’s debugger for this image.

Here you can see that the string we added to d() is part of the stack frame because it’s a local variable. Debuggers operate inside the Stack and give you a detailed picture of each frame.

Forcing a Thread Dump

Thread dumps are great post-mortem tools, but they can be useful for runtime issues too. If your application stops responding or is consuming more CPU or memory than you expect, you can retrieve information about the running app with jstack.

Modify main() so the application will run until killed:

public static void main(String[] args) throws Exception {
  try {
      while(true) {
          Thread.sleep(1000);
      }
  } catch (NullPointerException ice)  {
      ice.printStackTrace();
  }
}

Run the app, determine its pid, and then run jstack. On Windows, you’ll need to press ctrl-break in the DOS window you’re running your code in.

$ jstack <pid>

Jstack will generate a lot of output.

2019-05-13 10:06:17
Full thread dump OpenJDK 64-Bit Server VM (12+33 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x00007f8bb2727190, length=10, elements={
0x00007f8bb3807000, 0x00007f8bb2875000, 0x00007f8bb2878000, 0x00007f8bb4000800,
0x00007f8bb300a800, 0x00007f8bb287b800, 0x00007f8bb287f000, 0x00007f8bb28ff800,
0x00007f8bb300b800, 0x00007f8bb3805000
}

"main" #1 prio=5 os_prio=31 cpu=60.42ms elapsed=103.32s tid=0x00007f8bb3807000 nid=0x2503 waiting on condition  [0x0000700001a0e000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep([email protected]/Native Method)
	at com.ericgoebelbecker.stacktraces.StackTrace.main(StackTrace.java:9)

"Reference Handler" #2 daemon prio=10 os_prio=31 cpu=0.08ms elapsed=103.29s tid=0x00007f8bb2875000 nid=0x4603 waiting on condition  [0x0000700002123000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList([email protected]/Native Method)
	at java.lang.ref.Reference.processPendingReferences([email protected]/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run([email protected]/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=31 cpu=0.13ms elapsed=103.29s tid=0x00007f8bb2878000 nid=0x3903 in Object.wait()  [0x0000700002226000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait([email protected]/Native Method)
	- waiting on <0x000000070ff02770> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
	- locked <0x000000070ff02770> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run([email protected]/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 cpu=0.27ms elapsed=103.28s tid=0x00007f8bb4000800 nid=0x3e03 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 cpu=6.12ms elapsed=103.28s tid=0x00007f8bb300a800 nid=0x5603 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #7 daemon prio=9 os_prio=31 cpu=12.01ms elapsed=103.28s tid=0x00007f8bb287b800 nid=0xa803 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #8 daemon prio=9 os_prio=31 cpu=0.73ms elapsed=103.28s tid=0x00007f8bb287f000 nid=0xa603 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #9 daemon prio=9 os_prio=31 cpu=0.04ms elapsed=103.27s tid=0x00007f8bb28ff800 nid=0xa503 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #10 daemon prio=8 os_prio=31 cpu=0.27ms elapsed=103.27s tid=0x00007f8bb300b800 nid=0xa303 in Object.wait()  [0x000070000293b000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait([email protected]/Native Method)
	- waiting on <0x000000070ff91690> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
	- locked <0x000000070ff91690> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run([email protected]/CleanerImpl.java:148)
	at java.lang.Thread.run([email protected]/Thread.java:835)
	at jdk.internal.misc.InnocuousThread.run([email protected]/InnocuousThread.java:134)

"Attach Listener" #11 daemon prio=9 os_prio=31 cpu=0.72ms elapsed=0.10s tid=0x00007f8bb3805000 nid=0x5e03 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=31 cpu=3.83ms elapsed=103.29s tid=0x00007f8bb2874800 nid=0x3703 runnable

"GC Thread#0" os_prio=31 cpu=0.13ms elapsed=103.31s tid=0x00007f8bb282b800 nid=0x3003 runnable

"G1 Main Marker" os_prio=31 cpu=0.26ms elapsed=103.31s tid=0x00007f8bb2845000 nid=0x3103 runnable

"G1 Conc#0" os_prio=31 cpu=0.04ms elapsed=103.31s tid=0x00007f8bb3810000 nid=0x3303 runnable

"G1 Refine#0" os_prio=31 cpu=0.39ms elapsed=103.31s tid=0x00007f8bb2871000 nid=0x3403 runnable

"G1 Young RemSet Sampling" os_prio=31 cpu=13.60ms elapsed=103.31s tid=0x00007f8bb2872000 nid=0x4d03 runnable
"VM Periodic Task Thread" os_prio=31 cpu=66.44ms elapsed=103.27s tid=0x00007f8bb2900800 nid=0xa403 waiting on condition

JNI global refs: 5, weak refs: 0

My application was running 11 threads, and jstack generated a stack trace for all of them. The first thread, helpfully named main, is the one we’re concerned with. You can see it sleeping on wait().

Java Stack Traces: Your Roadmap

A stack trace is more than just a picture inside your application. It’s a snapshot of a moment in time that includes every step your code took to get there. There’s no reason to dread seeing one in your logs because they’re a gift from Java that tells you exactly what happened. Make sure you’re logging them when an error crops up and send them to a tool like Scalyr so they’re easy to find.

Now that you understand what a Java stack trace is and how to use it, take a look at your code. Are you throwing away critical information about errors and exceptions in your code? Is there a spot where a call to Thread.dumpstack() might help you isolate a recurring bug? Perhaps it’s time to run your app through the debugger a few times with some strategically-chosen breakpoints.

In simple terms, a stack trace is a list of the method calls that the application was in the middle of when an Exception was thrown.

Simple Example

With the example given in the question, we can determine exactly where the exception was thrown in the application. Let’s have a look at the stack trace:

Exception in thread "main" java.lang.NullPointerException
        at com.example.myproject.Book.getTitle(Book.java:16)
        at com.example.myproject.Author.getBookTitles(Author.java:25)
        at com.example.myproject.Bootstrap.main(Bootstrap.java:14)

This is a very simple stack trace. If we start at the beginning of the list of «at …», we can tell where our error happened. What we’re looking for is the topmost method call that is part of our application. In this case, it’s:

at com.example.myproject.Book.getTitle(Book.java:16)

To debug this, we can open up Book.java and look at line 16, which is:

15   public String getTitle() {
16      System.out.println(title.toString());
17      return title;
18   }

This would indicate that something (probably title) is null in the above code.

Example with a chain of exceptions

Sometimes applications will catch an Exception and re-throw it as the cause of another Exception. This typically looks like:

34   public void getBookIds(int id) {
35      try {
36         book.getId(id);    // this method it throws a NullPointerException on line 22
37      } catch (NullPointerException e) {
38         throw new IllegalStateException("A book has a null property", e)
39      }
40   }

This might give you a stack trace that looks like:

Exception in thread "main" java.lang.IllegalStateException: A book has a null property
        at com.example.myproject.Author.getBookIds(Author.java:38)
        at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Caused by: java.lang.NullPointerException
        at com.example.myproject.Book.getId(Book.java:22)
        at com.example.myproject.Author.getBookIds(Author.java:36)
        ... 1 more

What’s different about this one is the «Caused by». Sometimes exceptions will have multiple «Caused by» sections. For these, you typically want to find the «root cause», which will be one of the lowest «Caused by» sections in the stack trace. In our case, it’s:

Caused by: java.lang.NullPointerException <-- root cause
        at com.example.myproject.Book.getId(Book.java:22) <-- important line

Again, with this exception we’d want to look at line 22 of Book.java to see what might cause the NullPointerException here.

More daunting example with library code

Usually stack traces are much more complex than the two examples above. Here’s an example (it’s a long one, but demonstrates several levels of chained exceptions):

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 more

In this example, there’s a lot more. What we’re mostly concerned about is looking for methods that are from our code, which would be anything in the com.example.myproject package. From the second example (above), we’d first want to look down for the root cause, which is:

Caused by: java.sql.SQLException

However, all the method calls under that are library code. So we’ll move up to the «Caused by» above it, and in that «Caused by» block, look for the first method call originating from our code, which is:

at com.example.myproject.MyEntityService.save(MyEntityService.java:59)

Like in previous examples, we should look at MyEntityService.java on line 59, because that’s where this error originated (this one’s a bit obvious what went wrong, since the SQLException states the error, but the debugging procedure is what we’re after).

In simple terms, a stack trace is a list of the method calls that the application was in the middle of when an Exception was thrown.

Simple Example

With the example given in the question, we can determine exactly where the exception was thrown in the application. Let’s have a look at the stack trace:

Exception in thread "main" java.lang.NullPointerException
        at com.example.myproject.Book.getTitle(Book.java:16)
        at com.example.myproject.Author.getBookTitles(Author.java:25)
        at com.example.myproject.Bootstrap.main(Bootstrap.java:14)

This is a very simple stack trace. If we start at the beginning of the list of «at …», we can tell where our error happened. What we’re looking for is the topmost method call that is part of our application. In this case, it’s:

at com.example.myproject.Book.getTitle(Book.java:16)

To debug this, we can open up Book.java and look at line 16, which is:

15   public String getTitle() {
16      System.out.println(title.toString());
17      return title;
18   }

This would indicate that something (probably title) is null in the above code.

Example with a chain of exceptions

Sometimes applications will catch an Exception and re-throw it as the cause of another Exception. This typically looks like:

34   public void getBookIds(int id) {
35      try {
36         book.getId(id);    // this method it throws a NullPointerException on line 22
37      } catch (NullPointerException e) {
38         throw new IllegalStateException("A book has a null property", e)
39      }
40   }

This might give you a stack trace that looks like:

Exception in thread "main" java.lang.IllegalStateException: A book has a null property
        at com.example.myproject.Author.getBookIds(Author.java:38)
        at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Caused by: java.lang.NullPointerException
        at com.example.myproject.Book.getId(Book.java:22)
        at com.example.myproject.Author.getBookIds(Author.java:36)
        ... 1 more

What’s different about this one is the «Caused by». Sometimes exceptions will have multiple «Caused by» sections. For these, you typically want to find the «root cause», which will be one of the lowest «Caused by» sections in the stack trace. In our case, it’s:

Caused by: java.lang.NullPointerException <-- root cause
        at com.example.myproject.Book.getId(Book.java:22) <-- important line

Again, with this exception we’d want to look at line 22 of Book.java to see what might cause the NullPointerException here.

More daunting example with library code

Usually stack traces are much more complex than the two examples above. Here’s an example (it’s a long one, but demonstrates several levels of chained exceptions):

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 more

In this example, there’s a lot more. What we’re mostly concerned about is looking for methods that are from our code, which would be anything in the com.example.myproject package. From the second example (above), we’d first want to look down for the root cause, which is:

Caused by: java.sql.SQLException

However, all the method calls under that are library code. So we’ll move up to the «Caused by» above it, and in that «Caused by» block, look for the first method call originating from our code, which is:

at com.example.myproject.MyEntityService.save(MyEntityService.java:59)

Like in previous examples, we should look at MyEntityService.java on line 59, because that’s where this error originated (this one’s a bit obvious what went wrong, since the SQLException states the error, but the debugging procedure is what we’re after).