After the 60 second Thread.sleep() calls, the “hung” program will return control back to the prompt, so you have 60 seconds to open another prompt, find the process id (PID) using the JDK’s jcmd utility, and capture a thread dump using the JDK’s jstack.

In the new prompt that you open, get the PID using the JDK’s jcmd program (8341 in Listing 11-3), which is passed to jstack, and then the jstack output (the text of the thread dump) is redirected into the file myThreadDump.txt. Note that the JDK’s jps command could also be used, but it requires a few extra command-line parameters (which I’m too lazy to type) to display the name of the Java class running. The 60 second sleep time in the program means the program will finish after 60 seconds, so don’t waste any time. The last line shows that the PID we care about is 8341.

Now that we know the PID of the process that of the program launched in Listing 11-2, the JDK comes with a number of plug-it-in-now tools we could use to learn more about the process: jstat, jmap, jinfo, and jdb. Listing 11-4 shows how we’ll pass the PID to jstack to capture a thread dump. The syntax > myThreadDump.txt is used to redirect the thread dump text to the .txt file instead of displaying it in the command-line window.

This example shows how thread dumps point you to a performance defect, even one without Java synchronization issues. Start by following the instructions at https://github.com/eostermueller/littleMock to download and start a Spring Boot server, and then apply three threads of load. If Maven and Java 8 (or greater) are already installed, this should take five minutes or so. The general idea is to download the zip file or do a git clone. In one terminal window, launch ./startWar.sh. In a separate window, launch ./load.sh. Then do the following:

The red line shows that 99% of all requests finished in about 58 ms or faster, until we added 50 additional ms at 8:04am, where response time jumped to about 110ms for the same 99% metric. This is a nice result—we added 50ms of sleep, and response time increased by just about the same amount (110–50 = ∼58ms). But the question is this: If your client complains that response time more than doubled (like this), how would you find the root cause? If you explore the Glowroot interface, there is a good chance it will point to the Thread.sleep(), which is great. But finding the bug in any environment is the goal here, so we will use jstack, which comes with every JDK.

I invoked jstack four times (Figure 11-2) to get four text files, each with a thread dump. Then, I used the techniques in the previous section to find which threads in the dump were under load: each thread dump text file had exactly three threads with code in the com.github.eostermueller package space, and each of those had a Tomcat HTTP-looking entry mark, along with an HTTP-like thread name, such as http-nio-8080-exec-10.

I mentioned earlier that to be considered “under load,” a thread state much be running. Well, this is one exception, because my scenario uses Thread.sleep() to slow down the code, and that means the RUNNING state changes to TIMED_WAITING while inside Thread.sleep().

It is no coincidence that each thread dump had three threads under load, because the JMeter load script in use (load.sh invokes src/test/jmeter/littleMock.jmx) has three threads of load configured in it. If you launch the JMeter GUI with loadGui.sh (it is in same folder as load.sh) and point to the aforementioned .jmx file, you can confirm this number three in the JMeter Thread Group.

Had I added think time to the .jmx or ran JMeter from a slow network (over the Internet, or from a different data center) instead of running it locally on the same box, the number of threads under load in each dump (aka “JVM concurrency”) would vary between zero and three.

So we have four threads dumps, each with three threads under load, for a total of 3x4=12 “sample” threads. Thus, we have 12 smiley faces in Figure 11-2. Let’s get back to finding the code that caused this slowdown. The instructions for Manual Thread Dump Profiling (MTDP) say this:

Of the twelve threads in the sample (the ones under load), eight of them were sitting on the Thread.sleep() that we introduced using the Sleep Time parameter on http://localhost:8080/ui. Listing 11-8 shows one of them.

Furthermore, the instructions earlier tell us that seeing the same code show up just twice in 12 thread dumps is enough to cause concern. My test yielded four times that many—eight.

In the preceding example, we found that 8 out of 12 threads sampled were in Thread.sleep(), and we felt confident enough to claim we had found the culprit. Is 12 really a large enough sample to base real development/tuning changes on? What if I captured a new set four additional thread dumps and Thread.sleep() only showed in one or none of them? This is a fair point, one that I asked myself for many months when I first started using this technique.

The short answer is that it is extremely rare for relatively fast methods to show up as the Current mark in a thread dump. For instance, trivial getters and setters never show up. If one ever did, it would be years before you saw it again. The slower the execution time, the more a method will show up in the stack trace. Think of MTDP as an exclusive club for the slow, which is completely different than having equal probability that any single line of code executed will be positioned at the Current mark. This equal probability situation never happens.

If you are looking for a more complete justification for why it is safe to make development changes based on such small sample sizes, here are two math-based opinions on that matter. For full disclosure, one of the justifications is written by Mike Dunlavey, the guy who first published this technique:

http://ostermueller.blogspot.com/2017/04/the-math-behind-manual-thread-dump.html

Personally, I use this technique not because the math is convincing, but because it works. The next section shows the results from one such tuning success story, and you can have a close look at all the optimizations discovered by this technique, a technique you can finally take into any environment in the enterprise.

The example above showed how MTDP can detect a 50ms response time increase, where the response time was doubled. Regardless of whether you think that is a large or a small slowdown, the next section shows how MTDP is capable of detecting response time problems much smaller than 50ms.

The performance anti-patterns discussed in Chapter 1, admittedly, are a bit over-generalized. But that all changes, now that we have the Entry, Trigger, and Current vocabulary in hand; we can get a little more specific.

The answer to the question about where in the timeline of a request was a particular stack trace captured, makes all the difference in painting a story around how this defect came to be. Let’s do a quick review:

If the trigger mark comes before the “main” processing, check to see whether this is an Unnecessary Initialization problem—number 1. An unsettling number of performance defects happen here. If there is a lot of data to initialize (like 500MB of product descriptions loading from a database), then consider processing the data once at start-up (or when the first request comes thru) and then cache the result for quick access later.

If the process doesn’t have 500MB of product description loading or other similar large data tasks, then you should ask yourself why it’s taking so long (remember, the MTDP is the exclusive club for the slow) to process just a small amount of data. If the amount of data is small, then perhaps the path the trigger code takes to get to the current mark needs to be rethought. Most APIs have multiple usage idioms, and perhaps the one your code took is not optimal. When the trigger code makes its first call that leads to the current mark, it is broadcasting to you which idiom (or at least part of the idiom) was selected by the trigger.

If the stack trace is part of the main process, then check to see whether you’re looking at number 2—Strategy/Algorithm inefficiency. A slow individual database query falls into this category, as well as a chatty database strategy caused by a SELECT N+1 issue, or perhaps just too many database calls in general. That said, these culprits can be more easily recognized using the toolset and approach in the P for Persistent part of the P.A.t.h. checklist.

The third anti-pattern is pretty easy to check for. Judging by the class and method names and even the entry mark, determine whether this is a business process that belongs in the load test. For example, perhaps sample data in the JMeter load test use that one special test customer from QA with a hundred times as many accounts as a regular customer (it was QA’s fault!). If so, fix the load script to call less off this business process.

For anti-pattern 4, the Large Processing Challenge, just as with anti-pattern 3, check the calls leading up to the trigger to assess which business process is executing. Large Processing Challenges are so large that you should know about them and start planning for them (installing extra disk space, scripting a large data load and backup, and so on) during development.

This is where the examples get detailed and you will really want to run this on your own desktop.

One of the first hurdles to get over when you start tuning is to decide on one particular stack trace to target for improvement. This example provides a walkthrough of one such example.

Use the following performance key as the starting point for this example.

X0,J25,K25,Q1,R1,S1

Once the load.sh/cmd was up and running, I ran jcmd to find the PID of littleMock and captured four thread dumps using jstack. I used the criteria discussed earlier to find which threads were under load. As we saw before, there were three threads under load in each thread dump, times four dumps, or 12 stack traces total.

Listing 11-9 shows key parts from the 12 threads under load. The first two threads showed up in five threads each, and the last two threads show up one time each. 5+5+1+1 = 12. I encourage you to try this example yourself on your own machine to see whether you get stack traces in similar proportions; I think you will.

The application under load that we’ve been using since the beginning of this chapter is littleMock. It is a tiny little HTTP stub server that I modeled after wiremock.org. A stub server is basically a test double, used in a test environment as a stand-in for some other system that was too expensive or too troublesome to install. If the XML-over-HTTP input (from load.sh/JMeter) matches one of five XPath expressions configured in littleMock’s application.properties, it returns a preconfigured response XML that mimics a response from the stubbed-out system.

As such, XPath evaluation and XML parsing (of the HTTP input requests) are the main processing of this application, and this is our first task—to assess whether these four stack traces occurred before, during, or after the main processing.

The trigger in the first stack trace calls XpathImpl.evaluate(); the second calls DocumentBuilderImpl.parse(). Obviously, the bulk of the processing is happening in these 5+5 threads doing XPath evaluation and XML parsing, but there are no obvious optimizations, here—no low-hanging fruit.

But the third stack trace, which showed up just once out of 12 threads, is certainly suspect, and I will show you exactly why.

Listing 11-10 shows that the trigger is on line 22 of XPathWrapper.java. The stack trace shows that line 22 should be a call to XPathFactory.newInstance().

This code was taken from the following link:

https://github.com/eostermueller/littleMock/blob/1206673fc57b09effd2152c0c4e1414fd1911508/src/main/java/com/github/eostermueller/littlemock/XPathWrapper.java#L19-L29

Furthermore, the third stack trace’s trigger (line 22) clearly comes before the main processing of this request, right there in the same method in Listing 11-10, line 25.

The very important point is this:

We know this code is slow because it shows up in the “exclusive club for the slow”—MTDP.

We know that the slow code, the call to XPathFactory.newInstance() on line 22, is initialization code because it comes before the main processing—the XpathImpl.evaluate() on line 25.

Why does slow code beg for optimization? I went over this in the “Leveraging the Four Anti-Patterns” section earlier, but the general idea is this: it takes a lot of work to get large processing challenges to perform well, but initialization tasks often have static data that can be processed and cached one time at start-up, or there isn’t that much data to process at all—processing small amounts of data is generally fast.

Once you have found some slow code to focus on, unless you have some bright ideas on how to optimize, it’s time put this in the good hands of the Internet. If you factor out environment-specific factors like “processing too much data,” “misconfigured virtual machine,” or “faulty network cable,” your answer lies on the Internet. I’m telling you, you are not the first one to run into a performance problem with a commonly used API. My search for “XPathFactory.newInstance() performance,” for example, yielded a handful of discussions that led me to the fix in Listing 11-11. Actually, both the third thread and the fourth thread (the two that showed up in a single stack trace each) have similar problems, and both of them are addressed with the change shown here.

You should probably beat me up a bit because I broke my own rule. Earlier, I said this about MTDP:

and the thread dumps didn’t meet this criteria, yet I plodded ahead with the optimization and got roughly a 20% throughput boost. Early in this chapter, we added the Thread.sleep() to littleMock UI and easily found the Thread.sleep() in the thread dumps. That was an obvious problem, but this one, not so much. The thread dumps showed the problem in both cases (Figure 11-4).

I mentioned elsewhere that the P and the A in P.A.t.h. are spelled out with capital letters because they are special: most of the time, you have the luxury of being able to detect problems in those areas with just a single user’s traffic, and thus avoid the hassle of creating a load script and finding a performance environment. Well, here we are in the “t” part of the checklist and load is required here. The sampling techniques only make sense when constant load is applied, and understanding cumulative impact of all the processing is key.

But how much load should be applied? Frankly, I am undecided on which of these to recommend to you:

…but since the second idea is easier, perhaps that is the best place to start.

In fact, I think all components as big as an SOA service should undergo the torment of three threads of load with zero think time, and thread dumps should be captured during this test.