上QQ阅读APP看书，第一时间看更新

Thread.print

If you execute the Thread.print command, the output will look like the following:

$ jcmd 7577 Thread.print
7577:
2017-09-10 16:39:12
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.144-b01 mixed mode):

"....." #xxx [daemon] prio=xxx os_prio=xxx tix=0x.... nid=0x.... [condition]
  java.lang.Thread.State: XXXXX
  at ......
  at ......
  ...


"....." #xxx [daemon] prio=xxx os_prio=xxx tix=0x.... nid=0x.... [condition]
  java.lang.Thread.State: XXXXX
  at ......
  at ......
  ...


"....." #xxx [daemon] prio=xxx os_prio=xxx tix=0x.... nid=0x.... [condition]
  java.lang.Thread.State: XXXXX
  at ......
  at ......
  ...

Since reproducing the full output of this command will take the entire chapter, it has been replaced by a skeleton of sorts of the thread stacks. What is important here is to identify that each block starting with a line that has quotes is a thread.

Therefore, the dump repeats this pattern:

"thread_name" #thread_id_as_int [daemon if the thread is daemon] prio=java_priority os_prio=native_priority tid=thread_id_pointer_format nid=native_id [state]
   thread_stack_trace

When the server is idle—that is, when it is not serving any request or executing any scheduled tasks—we can identify that most of the threads are just waiting for a task (in thread pools):

"dol-jar-scanner" #50 daemon prio=5 os_prio=0 tid=0x00007f3b7dd0a000 nid=0x1ddf waiting on condition [0x00007f3ae6bae000]
   java.lang.Thread.State: WAITING (parking)
  at sun.misc.Unsafe.park(Native Method)
  - parking to wait for <0x00000000877529a8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  at java.lang.Thread.run(Thread.java:748)

To understand this dump, you will need to know how ExecutorService works. It basically creates threads with tasks called Workers, and each work can take some tasks from a queue (to simplify things). Here we can see the following:

ThreadPoolExecutor$Work, which means that we are in a thread pool task handler
LinkedBlockingQueue.take, which means that the thread is waiting for a new task

We can also identify in this dump some incoming requests in the I/O layer, such as waiting for a socket to connect to an NIO Selector:

"http-listener-kernel(1) SelectorRunner" #27 daemon prio=5 os_prio=0 tid=0x00007f3b7cfe7000 nid=0x1dc8 runnable [0x00007f3b1eb7d000]
   java.lang.Thread.State: RUNNABLE
  at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
  at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
  at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
  at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
  - locked <0x000000008675cc20> (a sun.nio.ch.Util$3)
  - locked <0x000000008675cc10> (a java.util.Collections$UnmodifiableSet)
  - locked <0x000000008675c1f8> (a sun.nio.ch.EPollSelectorImpl)
  at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
  at org.glassfish.grizzly.nio.DefaultSelectorHandler.select(DefaultSelectorHandler.java:115)
  at org.glassfish.grizzly.nio.SelectorRunner.doSelect(SelectorRunner.java:339)
  at org.glassfish.grizzly.nio.SelectorRunner.run(SelectorRunner.java:279)
  at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:593)
  at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:573)
  at java.lang.Thread.run(Thread.java:748)

An important line here is either epollWait (if you are familiar with OS natives) or Selector*.select (if you are more familiar with the Java side of the code, which means it is waiting for a connection).

Now, if we inject some requests into our application (let's just use Apache Bench or AB to undertake some GET requests on our findById endpoint), we can see some threads that are actually working. (Note that because of its length and to avoid having several pages of thread stacktrace, the [...] have been shortened):

"http-listener(3)" #23 daemon prio=5 os_prio=0 tid=0x00007f3b7d063800 nid=0x1dc4 runnable [0x00007f3b1ef7d000]
   java.lang.Thread.State: RUNNABLE
  [...]
  at com.sun.enterprise.connectors.ConnectionManagerImpl.internalGetConnection(ConnectionManagerImpl.java:254)
  [...]
  at com.sun.gjc.spi.base.AbstractDataSource.getConnection(AbstractDataSource.java:115)
  at org.eclipse.persistence.sessions.JNDIConnector.connect(JNDIConnector.java:135)
  [...]
  at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1221)
  at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:911)
  at org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1180)
  at org.eclipse.persistence.queries.ReadAllQuery.execute(ReadAllQuery.java:464)
  [...]
  at org.eclipse.persistence.indirection.IndirectSet.size(IndirectSet.java:624)
  [...]
  at java.util.Optional.map(Optional.java:215)
  at com.github.rmannibucau.quote.manager.front.QuoteResource.findById(QuoteResource.java:48)
  [...]
  at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:370)
  at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:389)
  [...]
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
  at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:256)
  at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)
  [...]
  at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:206)
  at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:180)
  [...]
  at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:593)
  at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:573)
  at java.lang.Thread.run(Thread.java:748)

There are other kinds of thread stacks but this one is particularly interesting, as we can identify most of our endpoint stacks. Keep in mind that we are calling a JAX-RS endpoint that calls JPA to find a quote that will rely on DataSource to connect to the current database. We can identify the JAX-RS layer with org.glassfish.jersey lines, the JPA layer with the org.eclipse.persistence lines, our application with our own package (com.github.rmannibucau, in this example), and the datasource connection retrieval with the ConnectionManager lines. We can also identify that Jersey (JAX-RS implementation of GlassFish) is deployed over Tomcat, thanks to the org.apache.catalina packages (but only for the application pipeline management) and Grizzly for I/O handling (org.glassfish.grizzly packages).

This analysis is interesting as it shows something you need to take care of in Java EE: Java EE defines APIs but the runtime actually runs implementations. You rarely see javax.* entries in thread dumps, so you may need to check which implementations your server uses to make your analysis easier and faster.

Now the question is, can we conclude anything about this stack? Yes, of course! We can conclude that our application goes through the stack we expected. However, in terms of the performance, it doesn't mean anything. What will be impacting is how often you see the same stack being called. Concretely, if you see 30 threads over 100 waiting in a particular call, it may mean that this is a good place to optimize. If the stack even adds BLOCKED next to the line, it means that you need to ensure it is normal for the application to lock here and, maybe, change something (either the code or the configuration).

Before going on to the next section, keep in mind that you can get the same kind of output in multiple ways. The jstack tool is another Java tool that you can use for doing more or less the same thing, but an interesting tip is to use Linux (or Windows) native tools to get exactly the same information. If you have JRE (Java without the development tools) instead of JDK, here is how to do it on Linux:

kill -3 $JAVA_SERVER_PID