The following listing shows a first version of our latency benchmark:

 object FirstLatencyBenchmark { 
 
  def main(args: Array[String]): Unit = { 
 
    val commandSample = DataCodec.read(new File(args(0))) 
    val (commandsPerSecond, iterations) = (args(1).toInt, args(2).toInt) 
    val totalCommandCount = commandsPerSecond * iterations 
 
    jvmWarmUp(commandSample) 
 
    @tailrec 
    def sendCommands( 
      xs: List[(List[Command], Int)], 
      ob: OrderBook, 
      testStart: Long, 
      histogram: HdrHistogramReservoir): (OrderBook, HdrHistogramReservoir) 
      = 
      xs match { 
        case head :: tail => 
          val (batch, offsetInSeconds) = head 
          val shouldStart = testStart + (1000 * offsetInSeconds) 
 
          while (shouldStart > System.currentTimeMillis()) { 
            // keep the thread busy while waiting for the next batch to be 
            sent 
          } 
 
          val updatedBook = batch.foldLeft(ob) { 
            case (accBook, c) => 
              val operationStart = System.currentTimeMillis() 
              val newBook = OrderBook.handle(accBook, c)._1 
              val operationEnd = System.currentTimeMillis() 
              // record latency 
              histogram.update(operationEnd - operationStart) 
              newBook 
          } 
 
          sendCommands(tail, updatedBook, testStart, histogram) 
        case Nil => (ob, histogram) 
      } 
 
    val (_, histogram) = sendCommands( 
      // Organizes commands per 1 second batches 
      generateCount(commandSample, totalCommandCount) 
        .grouped(commandsPerSecond).zipWithIndex 
        .toList, 
      OrderBook.empty, 
      System.currentTimeMillis(), 
      new HdrHistogramReservoir()) 
 
    printSnapshot(histogram.getSnapshot) 
  } 
} 

The beginning of this code is similar to what we had in our throughput benchmark. We use an HdrHistogram to record each operation's latency. The tail-recursive method sendCommands is where most of the interesting things happen (we take a closer look at tail-recursion in a later chapter). Our commands are grouped by batches of size and commandsPerSecond, meaning that we will send one batch per second. We record the current time before sending a command (operationStart) and after receiving a response (operationEnd). These timestamps are used to update the histogram.

At the end, after all batches have been processed, we take a snapshot of the state of the histogram and print interesting metrics. Let's give this a run:

    sbt 'project chapter2' 'set javaOptions := Seq("-Xmx1G")' 'runMain highperfscala.benchmarks.FirstLatencyBenchmark src/main/resources/historical_data 45000 10'
    ... // removed for brevity
    [info] Processed 450000 commands
    [info] 99p latency: 1.0 ms
    [info] 99.9p latency: 1.0 ms
    [info] Maximum latency: 24 ms

We exercise our system with a rate of 45,000 operations per second for 10 seconds, and we see a latency of 1 ms for the 99.9^th percentile. These are outstanding results! They are also completely wrong. In our hurry to write a latency benchmark, we overlooked a too often ignored issue: the coordinated omission problem.

Our benchmark is broken because we measure the time required to process a command without taking into account the time the command had to wait to be processed. This becomes a problem if the previous command took longer than expected to be processed. Take our previous example: we ran 45,000 commands per second, that is, 45 commands per millisecond. What if processing the first 45 commands takes longer than 1 millisecond? The next 45 commands have to wait before being picked up and processed. However, with our current benchmark, we ignore this waiting time. Let's take an example of a web application serving pages over HTTP. A typical benchmark may record request latency by measuring the elapsed time between the moment a request is handled by the web server and the time a response is ready to be sent back. However, this would not account for the time it took for the web server to read the request and actually send back the response. A better benchmark will measure the latency as the time between the moment the client sent the request and the moment it actually received a response. To learn more about the coordinated omission problem, refer to the discussion thread containing direct links to articles and presentations at https://groups.google.com/forum/#!msg/mechanical-sympathy/icNZJejUHfE/BfDekfBEs_sJ.

To fix this problem, we need to record operationStart not when we start processing a batch of commands, but when the batch of commands should have been processed, regardless of whether the system is late.

In our second attempt, we make sure to start the clock to take into account when a command is meant to be sent, as opposed to when it is ready to be processed.

The benchmark code remains unchanged except for the recording of latency, which now uses shouldStart instead of operationStart:

histogram.update(operationEnd - shouldStart) 

After this change, this is the new benchmark output:

    sbt 'project chapter2' 'set javaOptions := Seq("-Xmx1G")' 'runMain highperfscala.benchmarks.SecondLatencyBenchmark src/main/resources/historical_data 45000 10'
    ... // removed for brevity
    [info] Processed 450000 commands
    [info] 99p latency: 743.0 ms
    [info] 99.9p latency: 855.0 ms
    [info] Maximum latency: 899 ms

The results are very different when compared to our first benchmark. Actually, this new code also has a flaw. This assumes that all the requests sent in the same second are supposed to be processed at the very beginning of this second. While technically possible, it is more likely that these commands will be sent at different times during the second (a few during the first millisecond, some more during the second millisecond, and so on). Our current benchmark probably greatly overestimates our latency by starting the timer too soon for most commands.

We will attempt to fix the latest issue and finally come up with a reliable benchmark. At this point, we are trying to address the problem of the distribution of the commands over each second. The best way to solve this issue would be to use real production data. If the recorded commands that we are using for our benchmark had a timestamp attached to them (that is, the moment they were received by the production system), we could replicate the distribution of commands observed in production.

Unfortunately, our current order book application does not record the timestamp when logging data. We could go different routes. One option is to randomly send the commands over a second. Another is to assume an even distribution of the commands (that is, the same amount is sent on each millisecond).

We choose to modify the benchmark assuming the latter. To accomplish this goal, we modify the generation of events. As our new strategy distributes commands over time rather than batching commands, for a single instant, the new command list return type changes from List[(List[Command], Int)] to List[(Command, Int)]. The logic to generate the command list changes to account for our new strategy, as follows:

  generateCount(sampleCommands, totalCommandCount) 
    .grouped(cps.value) 
    .toList.zipWithIndex 
    .flatMap { 
      case (secondBatch, sBatchIndex) => 
        val batchOffsetInMs = sBatchIndex * 1000 
        val commandIntervalInMs = 1000.0 / cps.value 
        secondBatch.zipWithIndex.map { 
          case (command, commandIndex) => 
            val commandOffsetInMs = 
              Math.floor(commandIntervalInMs * commandIndex).toInt 
            (command, batchOffsetInMs + commandOffsetInMs) 
        } 
    }  

The creation of our set of commands is a bit more involved. We now calculate an offset for each command, taking into account the amount of milliseconds that should elapse between each command. Our final results with this benchmark are as follows:

    sbt 'project chapter2' 'set javaOptions := Seq("-Xmx1G")' 'runMain highperfscala.benchmarks.FinalLatencyBenchmark src/main/resources/historical_data 45000 10'
    [info] Processed 450000 commands
    [info] 99p latency: 92.0 ms
    [info] 99.9p latency: 137.0 ms
    [info] Maximum latency: 145 ms

We finally established a good latency benchmark for our system, and sure enough, our results come close to what is currently being observed in production.

If the test environment was set up to use incorrect resources, the results are invalidated. For this reason, it makes sense to double-check the environment setup first. Fortunately, Flight Recorder captures much of this information for you.

The General and System tab groups are the areas to focus on for this checklist item. In General, click on JVM Information to identify key JVM facts. In this section, confirm the following:

To supplement confirmation of JVM configuration, view the GC Configuration tab under the Memory tab group. This tab details garbage collection configuration, which reflects a combination of user-supplied configuration and JVM defaults. As you are likely aware, small changes in the garbage collection configuration can yield significant runtime performance changes. Given the sensitivity of application performance to garbage collection configuration, you should reflect on each parameter in this tab. Questions to consider while reviewing are as follows:

Next, we focus on the System tab group. The Overview tab itemizes non-JVM resources to make it clear which resources were used to create this profile. Continuing with the theme of questions from the General tab group, the overarching goals are as follows:

If you are configuring your system via environment variables, there is an Environment Variables tab that should be reviewed. Like the Overview tab, you are looking to ensure your test resources are provisioned and configured as you intended. It bears repeating that any unexpected differences in your test resources always invalidate test results.

Once you are comfortable that the appropriate resources were used, the next step is to confirm that only the application being profiled used resources. This is an important diagnostic step prior to reviewing test results because it ensures that the profiled application was truly isolated for the test. Fortunately, Flight Recorder catalogs useful information to answer this question. In the System tab group, the Processes tab captures all the processes running during the profiling. Scan this list with the following questions in mind:

Next, inspect the Recording tab under the General tab group. Flight Recorder provides the ability to create concurrent recordings. The profile results will contain the union of the concurrent recordings. If there are multiple recordings unexpectedly happening in only one of several runs, then you may not have an apples-to-apples results comparison between recordings.

The next area to focus on is system CPU usage over the duration of the profiling. Within the General tab group, select the Overview tab. This view displays the CPU usage panel, which provides you with the ability to inspect machine CPU usage throughout the recording. Here, you are looking for unexpected divergences between JVM and machine total CPU usage. The following screenshot depicts a scenario where there is a divergence worth investigating:

Unexpected non-JVM CPU usage highlighted by the CPU Usage panel

In the preceding screenshot, the combination of JVM + Application (User) and JVM + Application (Kernel) indicates the JVM-under-test's CPU usage, and Machine Total indicates machine (that is, JVM-under-test and all other processes) CPU usage. For the majority of this recording, the JVM-under-test CPU usage represents the majority of machine CPU usage. If your application should be the only process using system resources, then the small delta between the small delta between JVM + Application (User) and Machine Total represents the desired state. The divergences near the middle of the recording period indicate that another process or other processes were using CPU resources. These spikes suggest abnormal behavior that can negatively impact profiling results. It is worth considering what other processes are using system resources and whether or not your test results remain valid.

This is a good opportunity to introduce the range navigator, which is the small horizontal widget at the top of each tab containing red marks. The range navigator is a timeline that displays events from the current tab that happen over time with red marks. By default, the entire timeline is selected and the duration of the profiling is displayed above the center of the timeline. You can select a subset of the timeline to zoom in on an area of interest. For example, you may wish to zoom in on CPU usage when the machine CPU usage spikes up. When selecting a subset of the timeline and data is only available for a specific point in time (for example, at start of recording) or the data does not represent a time series (for example, the JVM version), then the data is hidden or replaced with N/A.

A final spot check is to check the used machine physical memory in the Memory Usage panel in the Overview tab under the Memory tab group. During this spot, check whether you are trying to assess if the amount of used machine physical memory is a sensible value. If there is little machine physical memory remaining and the reserved heap is a small fraction of the total machine physical memory, you should pause to consider what other processes are using memory. This scenario is illustrated in the following screenshot:

Non-JVM processes using most of the available memory captured by the Memory Usage panel

In the preceding example, the reserved heap space is 2 GB out of an available 16 GB system memory, and 13 GB of system memory is used. This implies that 11 GB of system memory is consumed by processes other than the profiled JVM. Unless you expect to have other processes running in your test environment, this type of memory-usage discrepancy warrants further investigation. For example, if your application makes use of off-heap memory, this discrepancy may invalidate your test results because your application may be unable to allocate memory as needed, or may result in excessive system swapping.

We began our profiling checklist with the widest possible criterion by verifying that the resources are provisioned and configured correctly. We continue to tighten the scope of our checklist by focusing on JVM configuration to ensure that test results are created from valid configurations. Now, we introspect JVM internals to continue verifying that the profile has not been compromised.

Nearly all production applications involve multithreading to make better use of multiple CPU cores or to separate I/O intensive work from CPU-centric work. The Threads tab group helps you familiarize yourself with the division of labor within the application and provides hints for where it may make sense to look deeper. The following table outlines areas of focus within the Threads tab group and highlights questions that you need to consider when you are new or unfamiliar with the application that is being profiled and when you have several profile results to compare:

After thoroughly inspecting the Threads tab group, you should begin to have a mental picture forming about how this application functions and which areas are likely to be most interesting for further study. We now turn to a topic that links closely to JVM threading: I/O.

The I/O tab group provides valuable information about the profiled application's file and socket access. Like the review of the Threads tab group, this section may provide hints that your application has unexpected or undesirable behavior. Before diving into this tab group, pause to consider when or what causes disk reads and writes, and network reads and writes. As you review the Overview tab, do you see divergences between your thinking and the profiler results? If so, you should identify why this discrepancy exists and whether it invalidates your test results.

An example of unexpected I/O behavior could be excessive writes to standard out. This might happen accidentally when a debugging statement is left behind. Imagine if this side-effect occurs on the critical path of your application. This will negatively impact profile results and invalidates testing. In Flight Recorder, writes to standard out are captured by a blank write path. The following screenshot shows file write results from a simple, one-off application that repeatedly writes to standard out at a high frequency:

Identifying unexpected writes to standard out via the I/O tab group

This example is exaggerated for effect, which is why there is a continuous block of constant writes over time. By inspecting the File Write tab, we can also see how much time was spent writing to standard out, how much data was written, and how many writes occurred. In approximately 15 seconds of execution, a whopping 40,000 writes took place! The file write stack trace provides invaluable information, allowing us to backtrack to identify which parts of the application are responsible for the writes. Flight Recorder also allows you to view writes by thread. In a production application with dedicated writer threads, you can quickly isolate undesired I/O access.

Monitoring I/O reads and writes presents a good opportunity to discuss how to configure Flight Recorder recording parameters. The -XX:+FlightRecorderOptions accepts a parameter named settings, which, by default, points to $JAVA_HOME/jre/lib/jfr/default.jfc. You can either provide your own configuration file or modify the default file. In this configuration file, you can tweak the events that are recorded by Flight Recorder and the frequency at which to capture certain events. For example, by default, the java/file_write event has a threshold of 20 ms. This is a reasonable default, but you may wish to tune the value lower if you are focused on profiling file writes. Setting the threshold lower means that more event samples are captured. Tune carefully because more is not always better. A lower threshold implies higher overhead and more information to sift through.

A final area to investigate is the Exceptions tab under the Code tab group. Even if you are closely monitoring application logs during a profiling, you may not be persisting the logs for historical analysis. Fortunately, Flight Recorder captures exceptions and errors for review. Scanning the exceptions and errors, take note of how many total exceptions and errors occurred and which ones happen most frequently. Shrink the time horizon with the range navigator to better understand if exceptions and errors are concentrated at application startup, later in the profiling, or uniformly occurring. The timing at which exceptions and errors occur often provides insight into whether or not the root cause is misconfiguration or unexpected runtime behavior. As always, if you notice an alarming number of exceptions or errors, consider invalidating the profile results until you have a deeper understanding about why they are happening.

At this stage, we have completed all checks necessary to maximize the likelihood that the profiler results are valid and worth investigating further. Now, we begin arguably the most fun part of the profiling process: identifying CPU bottlenecks. This is an enjoyable process because the profiler gives you a detailed look inside the black box of your application. It is an opportunity to objectively test your hypotheses and mental model of how the application works by comparing with the profiler results. Once you identify the bottlenecks, you will feel a sense of relief that you now know where to pinpoint your next set of changes to improve application performance.

Let's start on the Overview tab of the Code tab group. This view is useful to sensitize yourself from the bottom-up on which areas of the code are most expensive. The following figure displays the Overview tab for a sample run of the order book:

The Code Overview tab summarizing expensive packages and classes

In this view, the initial goal is to get a sense for the distribution of CPU time in the application. The Hot Packages panel quickly makes it clear to us that the order book is heavily reliant upon code from the scala.collection package. The Hot Classes panel shows that the order book is spending a significant amount of time, approximately 55% of the time, performing some type of iteration operations. In this screenshot, we also see that only a subset of the profile duration is selected with the range navigator. It is often helpful to view different subsets of the profile period to determine if hot spots remain constant over time. In this example, the early part of the profile results are excluded because they include time spent preparing requests to be sent to the order book. Selecting this subset allows us to focus purely on order book operations without pollution from test setup.

It is important to note that the percentage column indicates the amount of application time spent executing in the displayed package and class. This means that this view, along with the Hot Methods tab, are bottom-up views rather than top-down views. In a top-down view, the percentage column indicates the sum total amount of time spent in part of a stack trace. This view is captured in the Call Tree tab. This distinction is key because these two views help us answer different questions. The following table explores several topics from both perspectives to better understand when each view is most helpful:

As a first-time profiler of the order book, you now know from the Overview tab that the order book makes heavy usage of Scala collections, but you do not yet have a feel for which order book operations are causing the performance to suffer. To deepen your understanding about the cost of different order book operations, you take a top-down view by investigating the Call Tree tab:

Investigating order book bottlenecks using Call Tree

Drilling down Call Tree, it becomes abundantly clear that the cancelation operation is the bottleneck. Overwhelmingly, CPU time is spent canceling orders rather than adding them. You call over the company's sharpest trader, Dave, to share this finding. Dave's eyes light up when you mention that cancelations are costly. As a trading domain expert, he is well aware that in volatile times, the frequency of cancelations increases significantly as compared to calmer market periods. Dave explains that traders frequently cancel orders in volatile markets to quickly adjust to swinging prices. Cancelations beget cancelations because traders are learning valuable pricing information. Ending the conversation, he tells you to cancel everything else that you are doing (no pun intended!) and focus on improving the performance of order canceling.

You walk away from the conversation feeling better knowing that you have identified the bottleneck that is likely to be the source of MVT trade losses. To get a better feel, you dig a bit deeper into the Call Tree to reveal which functions within Cancel Order are expensive. This is the process of moving from a macro view to a micro view. You end up looking at the Call Tree tab, which is displayed as follows:

Understanding which cancel order functions are the slowest via Call Tree

The Call Tree shows that canceling an order involves an invocation of the RedBlackTree find() function and the exists() function. As you look deeper into the call, you also notice that the percentage column becomes smaller. This is because in a top-down view, the percentage column represents the sum total CPU time spent on a particular function and all the functions beneath it. According to the results, 84.48% of CPU time was spent executingOrderBook$$anonfun$handleCancelOrder$1.apply() and the functions deeper in the Call Tree. From this view, we also see that of the 84.48% of CPU time, 53.24% of the time is spent withinAbstractIterator.exists() and deeper function calls. This looks like the biggest bottleneck, with the invocation of Queue.iterator() in second place, taking 31.24% of CPU time.

Reflecting on this information, you are curious to start at the bottom, so-to-speak, with the most expensive functions, and work your way through the backtrace to identify affected order book operations. To address your curiosity, you investigate the Hot Methods tab and see the following view:

Going from the micro to the macro view with Hot Methods

By an order of magnitude, you discover the same two culprits from the Call Tree investigation are the hottest methods. This is a reassuring finding because it builds confidence that changes to the implementation of canceling an order are likely to yield qualitative benefits. As you have not spent any time studying the source code, there is still a significant amount of mystery about the implementation. Taking a step back to consider the situation, you think about the operations being modeled in the abstract. Canceling an order involves finding the existing order that could have any price and then once found, modifying the state of the order book to remove the order. Your intuition suggests that some of these operations are likely linear, or possibly logarithmic at best. As you begin considering what other implementation could be faster, Dave interrupts your thoughts.

In a rushed voice, you hear, "Have you fixed the order book? We need to get it deployed now!" Of course, you have no idea how to respond, and the thought of deploying code on day one makes you a bit uneasy. You share your findings with Dave, hoping that your findings will satisfy his appetite for progress and buy you more time to think. Unfortunately, Dave is not thrilled to hear the order book performance mystery remains unsolved, "We're losing money everyday because of this!" You acknowledge that you understand the gravity of the situation and that you are moving as fast as you can. It is your first day, after all! Dave sighs and acknowledges he is being a bit tough, and that his exasperation is causing him to overreact. As the conversation is winding down, Dave mentions his appreciation for how quickly you came up to speed, and he makes some small talk about how he cannot understand how his brand new smartphone, loaded with extra memory, still runs slowly. "Nothing seems to be working quickly anymore!" he exclaims. His mention of memory causes you to have an epiphany.

You remember that you have not yet reviewed memory usage results. You are hoping that there are some easy wins available by tuning the garbage collector to improve performance without making code changes. Before making any changes, you check out the Memory tab group for insight into memory allocation patterns.

The Memory tab group is the final area that remains to dive into for our analysis. Even though we have not spent time looking at the order book source code, the Code tab group illustrated the relative costs of the different order of operations. Studying the Hot Methods provides insight into the types of objects that are used by various areas of the order book. Looking into the memory allocation patterns, we want to identify young and old generation garbage collection trends and which objects are most and least allocated.

The default Flight Recorder configuration settings do not track object allocations. For a more complete view of memory consumption, the following configuration settings should be enabled:

Once a profile is generated with all the preceding parameters enabled, you will get a first glimpse into application memory allocation patterns in the Heap panel on the Garbage Collections tab:

Visualizing memory allocation patterns via the Garbage Collections tab

This view shows a shape that is commonly referred to as a sawtooth pattern. There are frequent garbage collections creating a tooth-like pattern in the data as the JVM is constantly freeing young generation memory. Garbage collection tuning is a vast topic that is beyond the scope of this book. We encourage you to dig deeper into this area by reading through this well-written blog post entitled, "Understanding Java Garbage Collection" (http://www.cubrid.org/blog/dev-platform/understanding-java-garbage-collection/).

As shown in the following screenshot, Flight Recorder also provides summary metrics per garbage collection category in the GC Times tab:

Summarizing garbage per collection event type

The following are some questions worth considering when inspecting a visualization of heap usage and a breakdown of garbage collection per collection type:

Studying these views of memory allocation provides a summary of memory allocation activity. Investigating the Allocations tab provides several different ways to see which parts of the application are applying memory pressure. Flight Recorder provides three allocation views: by class, by thread, and by profile:

Correlating high-pressure List allocations via Allocations by Class

Class and profile allocations are shown in the preceding screenshot. Note that Allocations by Thread are skipped in this case because the order book is single-threaded.

Confirming memory allocation pressure using top-down Allocation Profile view

When you are reviewing these allocation views, you should consider the following questions. As you read through these questions, reflect on how you would answer them to better understand how to improve order book performance:

Knowing that Dave will soon ask you again about improvements to order book performance, you take a few minutes to reflect on your findings. It is clear that handling Cancel Orders is both the CPU time and the memory allocation bottleneck. With more time to think about the problem, you are confident you can change the order book implementation to address either concern or possibly both. Unfortunately, time is one thing you do not currently have. One interesting observation from the memory allocations is that most garbage tends to be short-lived in a volatile market. Two inexpensive options to test come to mind:

The following table summarizes the results for each experiment:

sbt 'project chapter2' 'set   javaOptions := Seq("-Xmx1G")' 'runMain   highperfscala.benchmarks.FinalLatencyBenchmark src/main/resources/historical_data   45000 10'

sbt 'project chapter2' 'set   javaOptions := Seq("-Xmx1G",   "-XX:+UseConcMarkSweepGC")' 'runMainhighperfscala.benchmarks.FinalLatencyBenchmark   src/main/resources/historical_data 45000 10'

sbt 'project chapter2' 'set   javaOptions := Seq("-Xmx1G", "-XX:NewSize=750M")' 'runMain   highperfscala.benchmarks.FinalLatencyBenchmark   src/main/resources/historical_data 45000 10'

sbt 'project chapter2' 'set   javaOptions := Seq("-Xmx1G", "-XX:NewSize=750M", "-XX:+UseConcMarkSweepGC")'   'runMain highperfscala.benchmarks.FinalLatencyBenchmark   src/main/resources/historical_data 45000 10'

It looks like it will be more complicated than expected to improve the performance of the order book. At least one of the options, increasing the new size, seems to yield a better overall latency. We suggest that you take the time to go over this chapter again and repeat the process of benchmarking and profiling the application with these new sets of options. Observe what new behaviors these JVM options introduce, and try to understand the resulting increase or decrease in latency.

We want to take a moment to highlight some context about the profiling results that we interpreted in the previous section. We worked through an example that exhibited multiple real-world concerns. We laid out a pragmatic approach to working through the performance problem that has been applied by your authors at their day jobs. The point to be cautious of is that the order book is likely much simpler than most applications you work on day-to-day. We deliberately chose an example that was complicated enough to illustrate how to work through a performance problem, but also simple enough to understand without hours of code review. In practice, you will possibly need to repeat profiling numerous times, each time testing out a new hypothesis, in order to gain traction with your performance problem. Applying the structured approach that we walked through will ensure that you validate your results before analyzing them, and it will also ensure that you have well-founded evidence to pinpoint where to make changes.

We worked through each item on the profiling checklist throughout the chapter. We present the entire checklist for ease of reference, as follows:

Having made progress towards improving performance by tweaking JVM memory settings, you set your eyes towards better understanding cancel performance. Based on the existence of a scala.collection.immutable.Queue in the profiler results, you hypothesize that there may be a linear time traversal of a FIFO queue to support order cancels. One way to test this hypothesis is to devise a microbenchmark that measures the cancelation performance in different scenarios. You brainstormed the following scenarios:

Canceling a nonexistent order happens in the real world when a resting order is crossed before the cancel request arrives. This is an interesting scenario because you are unsure whether there is early termination logic to make this operation cheaper or whether canceling a nonexistent order requires inspecting the entire order book. The remaining two scenarios focus on the fill guarantees that are provided by stock exchanges. When multiple orders are placed at the same price, they are guaranteed to be filled on a first-come, first-served basis. You are speculating that the FIFO queue seen in the profile results is preserving the time ordering of resting orders for a price level. You expect canceling the first order in line to be faster by a linear factor than canceling the final order in line.

After reading through the excellent JMH examples at http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-samples/src/main/java/org/openjdk/jmh/samples/ and some deep thinking, you are able to put together the following tests that capture the scenarios that you are interested in. The code is in-full and is followed by a walkthrough, displayed as follows:

@BenchmarkMode(Array(Throughput)) 
@OutputTimeUnit(TimeUnit.SECONDS) 
class CancelBenchmarks { 
 
  @Benchmark 
  def cancelLastOrderInLine(b: BookWithLargeQueue): (OrderBook, Event) = OrderBook.handle(b.book, b.cancelLast) 
 
  @Benchmark 
  def cancelFirstOrderInLine(b: BookWithLargeQueue): (OrderBook, Event) = OrderBook.handle(b.book, b.cancelFirst) 
 
  @Benchmark 
  def cancelNonexistentOrder(b: BookWithLargeQueue): (OrderBook, Event) = OrderBook.handle(b.book, b.cancelNonexistent) 
} 
 
object CancelBenchmarks { 
 
  @State(Scope.Benchmark) 
  class BookWithLargeQueue { 
    private val p = Price(BigDecimal(1.00)) 
    private val firstId: Int = 1 
    private val defaultCancelLast = CancelOrder(OrderId(-1)) 
 
    @Param(Array("1", "100", "1000")) 
    var enqueuedOrderCount: Int = 0 
 
    var book: OrderBook = OrderBook.empty 
 
    @Setup(Level.Trial) 
    def setup(): Unit = { 
      if (enqueuedOrderCount < 0) 
        sys.error(s"Invalid enqueued order count = $enqueuedOrderCount") 
      assert(book == OrderBook.empty) 
      assert(cancelLast == defaultCancelLast) 
 
      cancelLast = CancelOrder(OrderId(enqueuedOrderCount)) 
      book = { 
        (firstId to enqueuedOrderCount).foldLeft(OrderBook.empty) { 
           case (ob, i) => 
             OrderBook.handle(ob, AddLimitOrder(BuyLimitOrder(OrderId(i), 
             p)))._1 
         } 
      } 
 
      assert(cancelLast != defaultCancelLast) 
      if (enqueuedOrderCount > 0) 
        assert(book.bids.head._2.size == enqueuedOrderCount, 
          s"Book built incorrectly! Expected book to contain " + 
            s"$enqueuedOrderCount bids for $p, but actual book is $book") 
   } 
 
    var cancelLast: CancelOrder = defaultCancelLast 
    val cancelFirst: CancelOrder = CancelOrder(OrderId(firstId)) 
    val cancelNonexistent: CancelOrder = CancelOrder(OrderId(-1)) 
  } 
} 

Rather than duplicating JMH documentation, we will focus on the specific segments of interest and expect you to also investigate the JMH samples for additional context. Surveying the CancelBenchmarks class, you see the use of annotations to define benchmarks and control the benchmark outputs. Several benchmark modes exist. We are using the throughput mode to measure the number of times the benchmark completes in a fixed period of time. The implementation of each cancellation benchmark differs only by the ID of the order being canceled. Let's switch focus to the CancelBenchmarks object, which provides the necessary scaffolding to set up each benchmark.

The CancelBenchmarks object defines the BookWithLargeQueue state, which we observed is an argument to each benchmark. Defining the state that is required by the test is the first step towards parameterizing the benchmark. For this set of tests, we simplify the test setup by creating an order book with only a single price level at $1.00. We focus on sweeping the number of orders enqueued for the $1.00 price level in order to help identify the runtime behavior that we believe to be operating in linear time. The use of the param annotation supplies a set of default values to sweep for enqueued order count. We use the setup annotation to instruct JMH to prepare the state of the order book prior to invoking each of the three benchmarks. For each enqueued order count value, JMH invokes the setup method to create an order book with the desired number of resting orders at the $1.00 level.

Next, we run the benchmarks from sbt. JMH provides a number of command-line flags that control test configuration, which can be viewed from sbt using the following command:

sbt 'project chapter2' 'jmh:run -help'

All parameters that are configured as annotations can be overridden by supplying the associated command-line flag. The following is a sample invocation of CancelBenchmarks:

sbt 'project chapter2' 'jmh:run CancelBenchmarks -wi 3 -w 5s -i 30 -r 10s -jvmArgs "-Xmx1G -Xms1G" -gc true -foe true -p enqueuedOrderCount=1,10,50,100'

In this invocation of JMH, we configure three warm-up iterations, each running for 5 seconds. Warm-up iterations do not count toward the output throughput result. We configure 30 recorded iterations, each lasting 10 seconds to compute throughput. We supply a 1 GB heap size for this test and switch on exiting the benchmark on uncaught exceptions to defend against a regression in the code. Lastly, we parameterize the enqueued order counts that we wish to sweep, indicating that we want to run three warm-up iterations and 30 recorded iterations for an enqueued order count of 1, 10, 50, and 100 orders.

With a single order in the book, we hypothesize that all operations should be approximately equally expensive. As we believe that cancel operations run in linear time, our expectation is that each benchmark should be approximately five times slower when the enqueued order count is 50 than when the count is 10. We cap testing at 100 enqueued orders because in discussion with Dave, we learned that in his experience, he has never analyzed a book with more than 85 orders in a level. Capping at 100 orders ensures that we understand performance characteristics at a level that we do not expect to see in production but could conceivably occur.

After executing the test, we see the following results summarized, as follows:

From this result set, we can answer a number of interesting questions that help us characterize order book performance. Here are some questions for you to answer by inspecting the results:

In addition to these questions that are specific to the order book, it is critical to ask yourself the following questions of any benchmark result:

Errors in measurement or test setup destroy the integrity of your results. These questions aim to make you critically analyze the microbenchmark results. The test of reasonableness requires you to develop a mental model for the executed test. Using the order book, we need to consider what is a plausible number of cancel operations per second. One way to answer this question is to take one of the throughput results, for example, cancel last order with 50 queued orders, and compute the average milliseconds per operation. This is useful because we have a sense for the cost on a per-operation basis from earlier benchmarks; 509,339.595 cancels per second translates to approximately 0.002 ms per operation. This result might be surprisingly low, but bear in mind these results do not account for coordinated omission because there is no targeted throughput rate (that is, the test attempts to send as many cancels per second as possible). The other reason the cost might be lower than expected is because there is only one price level in the book. Typically, the book contains numerous price levels on the buying and selling sides. This may direct us toward designing benchmarks that sweep the number of price levels to better inform our understanding of the cost of managing multiple price levels.

The second question forces us to critically analyze the test setup and the test methodology. For example, how do we know that the setup function produces the intended order book? One way to defend against this is to add assertions to enforce intended constraints. Another concern to verify is that each cancel invocation in the benchmark yields the intended event. Adding assertions to the benchmark for a single trial may address this concern. However, leaving assertions in the benchmark code is likely to affect performance, and this should be used sparingly, if at all. For added safety, it could make sense to write unit tests for the scenarios that are being tested to ensure that the desired behavior occurs and ensure that the unit test and performance test code are shared.

When interpreting JMH results, it is important to consider the significance of the computed error. JMH computes error by constructing a confidence interval from a benchmark's iterations. The confidence interval assumes that the results follow a normal distribution, and the error represents the range of the computed 99.9% confidence interval. This suggests that all other things being equal, running more benchmark iterations improves your confidence in the results. The final column in the results table is illustrative of the variability of the results. The lower the variability, the more inclined you should be to trust the results. High result variability suggests that there is an error in measurement or that there is something inhibiting your ability to measure true performance characteristics. This is often a warning sign that you need to revisit your testing methodology and that you should put little trust in the results.

As our JMH configuration does not account for coordinated omission and instead sends a firehose of cancel requests to the order book, we should focus on the relative results rather than the absolute throughput values. The order book-related questions that are posed after the results hone in on relative differences that should be visible independent of the testing environment (for example, available cores or RAM). There is value in focusing on relative concerns because the answers should be more robust to change. If future code changes cause significant relative changes, for example, causing an exponential instead of linear cancel performance degradation, you can have higher confidence that this degradation is due to a code change instead of an environmental change.

In this section, we saw how to set up, execute, and interpret a JMH microbenchmark. Along the way, we looked at the shortcomings of microbenchmarking without JMH, and the concerns to be aware of during benchmark result analysis. We've only scratched the surface of the capabilities of JMH. We will build on this introduction to JMH in future chapters.