Continuous Production Profiling and Diagnostics

I’ve gotten a lot of questions about continuous production profiling lately. Why would anyone want to profile in production, or, if production profiling seems reasonable, why the heck leave it on continuously? I thought I’d take a few moments and share my take on the problem and the success I’ve seen the past years applying continuous production profiling in systems in the real world.

Trigger warning: this blog will not contain code samples. 😉

Profiling?

So what is software profiling then? It’s the ancient black magic art of trying to figure out how something is performing, for some aspect of performing. In American TV-series, the profiler is usually some federal agent who is adept at understanding the psychology of the criminal mind. The profiler attempts to understand key aspects of the criminal to make it easier for the law enforcement agents to catch him. In software profiling we’re kind of doing the same thing, but for software – your code as well as all the third party code you might be depending on.

We’re trying to build an accurate profile of what is going on in the software when it is being run, but in this case to find ways to improve a program. And to understand what is going on in your program, the profiler has to collect call traces and usually some additional context to make sense of it all.

In comparison to other observability tools, like metrics and logs, profilers will provide you with a holistic view of a running program, no matter the origin of the code and requiring no application specific instrumentation. Profilers will provide you with detailed information about where in the actual code, down to the line and byte code index, things are going down. A concrete example would be learning which line in a function/method is using most of the CPU, and how it was being called.

It used to take painting a red pentagram on the floor, and a healthy stock of black wax candles, to do profiling right. Especially in production. Overhead of early profilers weren’t really a design criteria; it was assumed you’d run the process locally, and in development. And, since it was assumed you’d be running the profiling frontend on the same machine, profiling remote processes were somewhat tricky and not necessarily secure. Production profilers, like JFR/JMC came along, but they usually focus on a single process, and since security is a bit tricky to set up properly, most people sidestep the problem altogether and run (yep, in production) with authentication and encryption off.

Different Kinds of Profiling

Profiling means different things to different people. There are various types of resources that you may be interested in knowing more about, such as CPU or locks, and there are different ways of profiling them.

Most people will implicitly assume that when talking about profiling, one means CPU-profiling – the ancient art of collecting data about where in the code the most CPU-time is spent. It’s a great place to start when you’re trying to figure out how to make your application consume less CPU. If you can optimize your application to do the same work with less resources, this of course directly translates into lowering the bill to your cloud provider, or being able to put off buying those extra servers for a while.

Any self-respecting modern profiling tool will be able to show more than just the CPU aspect of your application, for example allocation profiling or profiling thread halts. Profiling no longer implies just grabbing stack-traces, and assigning meaning to the stack trace depending on how it was sampled; some profilers collaborate closely with the runtime to provide more information than that. Some profilers even provide execution tracing capabilities.

Execution tracing is the capability to produce very specific events when something interesting happens. Execution tracing is available on different levels. Operating systems usually provide frameworks allowing you to listen on various operating system events, some even allowing you to write probe definitions to decide what data to get. Examples include ETW, DTrace and eBPF. Some runtimes, like the OpenJDK Java VM, provide support for integrating with these event systems, and/or have their own event system altogether. Java, being portable across operating systems, and wanting to provide context from the runtime itself, has a high performance event recorder built in, called the JDK Flight Recorder. Benefits include cheap access to information and emission of data and state already tracked by the runtime, not to mention an extensible and coherent data model.

Here are a few of my favourite kinds of profiling information:

  • CPU profiling
  • Wall-clock profiling
  • Allocation profiling
  • Lock / Thread halt / Stop-the-World profiling
  • Heap profiling

Let’s go through a few of them…

CPU Profiling

CPU profiling attempts to answer the question about which methods/functions are eating up all that CPU. If you can properly answer that question, and if you can do something about it (like optimizing the function or calling it less often) you will use less resources. If you want to reduce your cloud provider bill, this is a great place to start. Also, if you can scope the analysis down to a context that you care about, let’s say part of a distributed trace, you can target improving the performance of an individual API endpoint.

Wall-Clock Profiling

Wall-clock profiling attempts to answer the question about which method/function is taking all that time, no matter if on CPU or not. For runtimes supporting massively multithreaded applications, this information is much less useful without some context.

For example, let’s say you have a Java application with various thread pools running various kinds of operations. You may have hundreds of threads, all of them mostly parked, awaiting some work to do. Unless you have some context, all the wall-clock profiling will tell you is that most threads were parked. But if you do have some context, let’s say context around which span in a distributed trace is running when samples are taken, your wall-clock profiling data can tell you in which methods most of the time was spent during a particularly long lasting span. [1]

As a general rule of thumb, wall-clock profiling is useful for finding and optimizing away latencies, whereas CPU profiling is more suited for optimizing throughput. Also, execution tracing is a great complement to wall-clock profiling.

If you can tell where the wall-clock time is spent, you can help remove performance obstacles by seeing which method calls take time and optimize them, or reduce the number of calls to them.

Allocation Profiling

Allocation profiling is trying to answer where all that allocation pressure is coming from, and from allocating what. This is important, since all that allocated memory will usually have to be reclaimed at some point in time, and that uses both CPU and possibly causes stop-the-world pauses from GC (though modern GC technologies, for example ZGC for the Java platform, is making this less of an issue for some types of services).

If you can properly answer where the allocation pressure comes from, you can bring down GC activity by optimizing the offending methods, or have your application call them less.

Lock / Thread Halt / Stop-the-World (STW) Profiling

This kind of profiling tries to answer the question about why my thread didn’t get to run right there and right then. This is typically what you would use the wall-clock-profiler for, but the wall-clock-profiler usually has some serious limitations, making it necessary to collaborate with the runtime to get some additional context. The wall-clock profiler typically only gets sampled stack traces showing you which method you spent time in, but without context it may be hard to know why.

Here are some examples:

  • Your thread is waiting on a monitor
    Context should probably include which thread is currently holding the monitor, which address the monitor has, the time you had to wait etc.
  • Your runtime is doing something runtimey requiring stopping the world, showing your method taking its own sweet time, but not offering any clues as to why
    • STW phase due to GC happening in the middle of running your method.
    • STW phase due to a heap dump
    • STW phase due to full thread stack dump
    • STW phase due to bad behaving framework, or your well meaning colleague(s), forcing full GCs all the time, since they “know that a GC really improves performance if done right there”, not quite realizing that it’s just a small part of a much bigger system.
  • Your thread is waiting for an I/O operation to complete
    Context should probably include the IP address (socket I/O) or file (file I/O), the bytes read/written etc.

There are plenty of more examples, wait, sleep, park etc. To learn more, open JDK Mission Control and take a look at individual event types in the event browser.

Heap Profiling

This kind of profiling attempts to answer questions about what’s on your heap and, sometimes, why. This information can be used to reduce the amount of heap required to run your application, or help you solve memory leaks. Information may range from heap histograms showing you the number of instances of each type on the heap, to leak candidates, their allocation times and allocation stack traces, together with the reference chains still holding on to them.

 

Continuous Production Profiling

Assuming that your application always has the same performance profile, which implies always having exactly the same load and never being updated, with no edge cases or failure modes, and assuming perfectly random sampling, your profiler could simply take a few samples (let’s say 100 to get a nice distribution) over whichever time period you are interested in (let’s say 24 hours), and call it a day. You would have a very cheap breakdown over whatever profiling information you’re tracking.

These days, however, new versions of an application are deployed several times a day, evolving to meet new requirements at a break-neck speed. They are also subjected to rapidly changing load profiles. Sometimes there may be an edge case we didn’t foresee when writing the program. Being able to use profiling data to not only do high level performance profiling, but detailed problem resolution, is becoming more and more common, not to mention useful.

At Datadog, we’ve used continuous production profiling for our own services for many months now. The net result is that we’ve managed to lower the cost of running our services all over the company by quite large amounts of money. We’ve even used the profiler to improve our other components, like the tracer. I had the same experience at Oracle, where dedicated continuous profiling analysis was used to a great extent for problem resolution in production systems.

Aside from being incredibly convenient, there are many different reasons why you might want to have the profiler running continuously.

 

Change Analysis

These days new versions are deployed several times a day. This is certainly true for my team at Datadog. There is great value in being able to compare the performance profile, down to the line of code. This is true across new releases, specific time intervals, over other attributes like high vs low CPU load, and countless other facets.

 

Fine Grained Profiling

Some production profiling environments allow you to add context, for example custom events, providing the means to look at the profiling data in the light of something else happening in a thread at a certain time. This can be used for doing breakdowns of the profiling data for any context you put there, any time, anywhere.

Adding some contextual information can be quite powerful. For example, if we were able to extend the profiling data with information about what was actually going on in that thread, at that time, any other profiling data captured could be seen in the light of that context. For example, WebLogic Server produced Flight Recorder Events for things like SQL calls, servlet invocations etc, making it much easier to attribute the low-level information provided by the profiler to higher level constructs. These events were also associated with an Execution Context ID which spanned processes, making it possible to follow along in distributed transactions.

With the advent of distributed tracing, this can be done in a fairly general way, so that profiling data can be associated with thread local activations of spans in a distributed trace (so called scopes). [1]

That said, with a general recording framework, there is no limit to the kinds of contexts you can invent and associate your profiling data with.

Diagnostics

It’s 2:03 a.m., all of a sudden some spans in your distributed trace end up taking a really long time. Looking at the spans, there is nothing indicating something is actually going wrong, or that the data is bad. From what is present in the tag data, nothing seems to be related between the spans. You decide to open up the profile.
The automated analysis informs you that a third-party library has initiated safe pointing VM operations from a certain thread, in this case for doing full heap dumps. The analysis text points you to more documentation about what a safe point is. You read up on safe pointing VM operations, and the library, and find out that under certain conditions, the library can initiate an emergency heap dump, but that the feature can be turned off. You turn it off, redeploy and go back to sleep.

Or, perhaps the automated analysis informs you that there is heavy lock contention on the apache logger, and links you to the lock profiling information. Looking at the lock profiling information, it seems most of the contention is being caused by the logging done on one particular line. You decide that the logging there is not essential, remove it, commit, redeploy and go back to sleep.
When something happens in production, you will always have data at hand with a continuous profiler. There is no need to try to reproduce the exact environment and conditions under which the problem occurs. You will always have actionable data readily available.

Of course, the cure must not be worse than the ailment. If the performance overhead you pay for the information costs you too much, it will not be worth it. Therefore this rather detailed information must be collected quite inexpensively for a continuous production profiler.

 

Low-overhead Production Profiling

So, how can one go about producing this information at a reasonable cost? Also, we can’t introduce too much observer effect, as this will skew the data, and not truly represent the application behaviour without the instrumentation.

There are plenty of different methods and techniques we can use. Let’s dig into a few.

Using Already Available Information

If the runtime is already collecting the data, exporting it can usually be done quite cheaply. For example, if the runtime is already collecting information about the various garbage collection phases, perhaps to drive decisions like when to start initiating the next concurrent GC-cycle, that information is already readily available. There is usually quite a bit of information that an adaptively optimizing runtime keeps track of, and some of that information can be quite useful for application developers.

Sampling

One technique we can use is to not take every single possible value, but do statistical sampling instead. In many cases this is the only way which makes sense. Let’s take CPU profiling for example. In most cases, we will be able to select an upper boundary for how much data we produce by either selecting the CPU quanta between samples, or by selecting a fixed number of threads to look at any given time and the sampling period. There are also more advanced techniques for getting a fixed data rate.

An interesting example from Java is the new upcoming allocation profiling event. Allocation in Java is most of the time approximately the cost of bumping a pointer. The allocation takes place in thread local area buffers (TLABs). There is no way to do anything in that code path without introducing unacceptable overhead. There are however two “slow” paths in the allocator. One for when the TLAB is full. The other one for when the object is too large to fit in a TLAB (usually by allocating an enormous array) leading to the object being allocated directly on heap. By sampling our allocations at these points, we get relatively cheap allocation events that are proportional to the allocation pressure. If we were able to configure how often to subsample over the average amount of memory allocated between samples, we would be able to regulate the acceptable overhead. That said, what we’re really looking for is a constant data production rate, so regulating that is better left to a PID-style controller, giving us a relatively constant data production.

Of course, the less sample points we have, the less we can say about the behaviour over very short periods of time.

Thresholding

One sort of sampling is to simply only collect outliers. For some situations, we really would like to get more information. One example might be thread halts that take longer than, say, 10ms. Setting a threshold allows us to do a little bit of more work, when it’s very much warranted. For example, I might only be interested in tracking blocking I/O reads/writes lasting longer than a certain threshold, but for them I’d like to know the amount of bytes read/written, the IP address read from/written to etc.

Of course, the higher the threshold, the more data we will miss (unless we have other means to account for that time). Also, thresholds make it harder to reason about the actual data production rate.

Protect Against Edge Cases

Edge cases which make it hard to reason about their potential overhead should be avoided, or at least handled. For example, when calculating reference chains, you may provide a time budget for which you can scan, and then only do it when absolutely needed. Or, since the cost of walking a stack trace can be proportional to the number of frames on the stack, you can set an upper limit to how many frames to walk, so that recursion gone wild won’t kill your performance. Be careful to identify these edge cases, and protect against them.

One recent example is the Exception event available in the Flight Recorder (Java), which can be configured to only capture Errors. The Java Language Specification defines an Error like this:

“Error is the superclass of all the exceptions from which ordinary programs are not ordinarily expected to recover.”

You would be excused for believing that Errors would happen very rarely, and that recording all of them would not be a problem. Well, a very popular Java framework, which will remain unnamed, subclassed Error in an exception class named LookAheadSuccess. That error was used in a parser and used for control flow, resulting in the error being thrown about a gazillion times per minute. We ended up developing our own solution for exception profiling at DD, which records Datadog specific events into the JDK Flight Recorder.

Some Assembly Required

These techniques, and more, can be used together to provide a best-of-all-worlds profiling environment. Just be careful, as with most things in life a balance must be found. Just like there is (trigger warning) no single energy source that will solve our energy problems in a carbon neutral way (we should use all at our disposal – including nuclear power – to have a chance to go carbon neutral in a reasonable time [2][3]), a balance must be struck between sampling and execution tracing, and a balance for how much data to capture for the various types of profiling you’re doing.

 

Continuous Profiling in Large Deployments
Or, Finding What You’re Looking For

In a way this part of the blog will be a shameless plug for the work I’ve been involved with at Datadog, but it may offer insights into what matters for a continuous profiler to be successful. Feel free to skip if you dislike me talking about a specific commercial solution.

So, you’ve managed to get all that juicy profiling down to a reasonable amount of data (for Datadog / Java, on average about 100k events per minute, with context and stacktraces, or 2MB per minute, at less than 2% CPU overhead), that you can process and store without going broke. What do you do next?

That amount of data will be overwhelming to most people, so you’ll need to offer a few different ways into the data. Here are a few that we’ve found useful at Datadog:

  • Monitoring
  • Aggregation
  • Searching
  • Association by Context
  • Analysis

Monitoring

All that detailed data that has been collected can, of course, be used to derive metrics. We differentiate between two kinds in the profiling team at Datadog:

  • Key Performance Metrics
  • High Cardinality Metrics

Key performance metrics are simple scalar metrics, you typically derive a value, periodically, per runtime. For example CPU utilization or allocation rate.

Here’s an example showing a typical key performance metric (note that all pictures are clickable for a better look):

kpm

The graph above shows the allocation rate. It’s a simple number per runtime that can change over time. In this case the chart is an aggregate over the service, but it could just as well be a simple metric plotted for an individual runtime.

High Cardinality Metrics are metrics that can have an enormous amount of different buckets with which the values are associated with. An example would be the cpu time per method.

We use these kinds of metrics to support many different use cases, such as allowing you to see the hottest methods in your entire datacenter. The picture below shows the hottest allocation sites across a bunch of processes.

hcm2

Here are some contended methods. Yep, one is a demo…

locks

Metrics also allow you to monitor for certain conditions, like having alerts / watchdogs when certain conditions or changes in conditions occur. That said, they aren’t worth that much unless you can, if you find something funny, go see what was going on – for example see how that contended method was reached when under contention.

 

Aggregation

Another use case is when you simply don’t care about a specific use case. You just want to look at the big picture in your datacenter. You may perhaps want to see, on average, across all your hosts and for a certain time range, what the CPU profiling information looks like? This would be a great place to start if, for example, looking for ways to lower the CPU usage for Friday nights, 7 to 10 p.m.

Here, for example, is an aggregation flame graph for the profiling data collected for a certain service (prof-analyzer), where there is some load (I set it to a range to filter out the profiles with very little load).

aggregation

A specific method can be selected to show how that specific method ended up being called:
methodselect

Searching

What if you just want to get to an example of the worst possible examples of using a butt-load of CPU? Or if you want to find the worst example of a spike in allocation rate? Having indexed key performance metrics for the profiling data makes it possible to quickly search for profiling information matching certain criteria.

Here is an example of using the monitor enter wait time to filter out an atypically high lock contention:

atypicallock

 

Association by Context

Of course, if we can associate the profiling data with individual traces, it would be possible to see what went on for an individual long lasting span. If using information from the runtime, even things that are normally hidden from user applications (including profilers purely written in Java), like stop-the-world pauses, would be visible.

breakdown

 

Analysis

When having access to all that yummy, per thread and time, detailed, profiling data, it would be a shame to not go looking for some interesting patterns to highlight. The result of that analysis can provide a means to focus on the most important parts of the profiling data.

analysis1

So, nothing terribly interesting going on in our services right now. The one below is from a silly demo app.
analysis2

That said, if you’re interested in the kind of patterns we can detect, check out the JDK Mission Control rules. The ones at Datadog are a superset, and work similarly.

 

Summary

Profiling these days is no longer limited to high overhead development profilers. The capabilities of the production time profilers are steadily increasing and their value is becoming less controversial, some preferring them for complex applications even during development. Today, having a continuous production profiler enabled in production will offer unparalleled performance insights into your production environment, at an impressively low performance overhead. Data will always be at your fingertips when you need it.

Additional Reading

https://www.datadoghq.com/blog/datadog-continuous-profiler/
https://www.datadoghq.com/blog/engineering/how-we-wrote-a-python-profiler/

Many thanks to Alex Ciminian, Matt Perpick and Dan Benamy for feedback on this blog.


[1]: Deep Distributed Tracing blog: http://hirt.se/blog/?p=1081

Unrelated links regarding the very interesting and important de-carbonization debate:

[2]: https://theness.com/neurologicablog/index.php/there-is-no-one-energy-solution/

[3]: https://mediasite.engr.wisc.edu/Mediasite/Play/f77cfe80cdea45079cee72ac7e04469f1d

 

 

 

The “Best of the JDK” Tournament

Over the last few weeks, there has been a knock-out tournament raging on Twitter, where various Java technologies have battled out which JDK technology is the best. It’s all part of the activities taking place around the celebration of Java turning 25 years. And boy, have those years been interesting.

Like many languages in use today, Java started out with a simple interpreter. That is, by the way, how Java got a reputation for being slow. Today, Java peak performance can surpass that of statically compiled languages, owing to optimizations only possible when runtime information is available. But I digress

As many of you know, I started out co-founding a company named Appeal – the company that created the JRockit JVM. We did quite a few cool things during that time; some of them relevant to the knock-out competition. We built the world’s first JVM management console, mostly since the application to become a Java licensee (so that JRockit could become a Sun certified JVM) required us to state a value-add. Our original application stated “better performance”, and was summarily turned down. 😉 With the work on the management console we eventually consolidated an API to monitor and manage the JVM – JMAPI (the JRockit Management API), which later inspired – and was superseded by – JSR-174 (java.lang.management)[1].

We also built a tool we called JRA (JRockit Runtime Analyzer). It really started out as a tool for finding out how the JVM was performing at customer installations – we needed information to better understand how to improve the JVM for real world usage. Customers, quite understandably, refused to let us borrow their applications to run them in our labs. To make it easy for them to understand and verify the data they were sharing, it was all emitted as text (XML). It didn’t take long for customers to see us use the tool and the (accidental) value it brought for optimizing their applications – was the tool perhaps for sale? As a startup, we of course said yes, and made it into a product. When we later introduced the JRockit DetGC (deterministic GC), there was a need to be able to prove that the GC was keeping the latency contract, and show where in the customer code any thread halts were caused (e.g. due to bad synchronization). So the JRockit Runtime Analyzer was extended with LAT (the Latency Analysis Tool), which now introduced a binary artifact for the latency data for better data density and less serialization cost. In the end the JRA and LAT was unified into a single model – JFR (JRockit Flight Recorder, later Java Flight Recorder, and finally re-dubbed into JDK Flight Recorder when it was open sourced). We also created an impossibly cool on-line memory analysis tool (which was sadly never ported to hotspot), together with a slew of other little tools and utilities.

The good old JMC memleak tool

Some of these tools converged into Java Mission Control, which became the hub for the cool tools we were developing.

JMC Logo

I was happily surprised to see JDK Mission Control included in the “Best of the JDK” feature face off. I was doing little dad-dances (to the embarrassment of my kids) in total astonishment when JDK Mission Control got up against the runtime and language features and ultimately won the whole thing.

Competition Results

Tech Poetry Throw-Down

One of the best parts of this whole competition was when Erik Costlow wrote some poetry in support of JDK Mission Control. This sparked an epic tech-poetry throw-down with little poems in favour of various Java technologies.

Here are a few of my favourites entries for JMC & JFR (in no particular order):

Of JDK Mission Control

whose benefits I will extol:

It watches performance

while still in conformance

So therefore it should win this poll.

  – @costlow

(The one which started the it all)

2 am in the morning, my mobile chimed,

The war room conf call had to be primed.

JVM’s are down, the helpdesk said,

Touch troubleshooting road ahead.

CPU? GC? Bad Code?, the questions abound,

The root cause was far from being found.

Tumultuous voiced from Dev to Ops, each one declaring the were clean

No path to the solution was to be seen.

With a prayer, I fired up the Java Flight Recorder,

Hoping this would restore some war room order.

Lo! And behold, the histogram revealed

‘Twas a code deadlock, the system could yet be healed!

Helpful NullPointer messages, I hear you say,

Who will alert you whilst you are away?

  – @perfclarity

To see or not to see (perf data)

That is the question (mission control answers).

Whether ‘tis nobler in the code

To suffer the zings and harrows of outrageous finger pointing

Or to stream events and by analyzing, end it

  – @costlow

I have never

had to deal

with NullPointer

Exceptions

and which

many people want

to have

better messages

Forgive me

but my vote goes to JMC

it is so sweet

and so cold

  – @stuartmarks

To think that I could ever see

A tool so lovely: JMC

A tool that streams events all day

Yet still performs without delay.

  – @costlow

If you need to control a mission

OpenJDK had an omission

And then JMC

Was suddenly free

Without even rights of rescission

  – @stuartmarks

So much value inside JMC

Yet usage was low, tis it wasn’t free

But low and behold

Oracle open sourced it in whole

And now productivity is as easy can be

  – @Sharat_Chander

As I stream through the events of my workload perf pain

I take a look post 8 life and realize this tool should reign

‘cause that’s just perfect for a coder like me

You know we love fancy things like JDK MC

Been spendin’ most our lives livin’ in a coder’s paradise

@costlow

Here are a few of my favourites for the other technologies:

Null pointer exception

Is a old familiar friend

And she wants to be

more helpful again

With deep information

I can only begin to extol

Love for NPE

For she should win

this Java poll

  – @manicode

There was a NullPointerException

Whose message needs amplification

To the VM some hacks

Add the relevant facts

And no longer is it an obsession

  – @stuartmarks

As I try to decipher my NPE in grails

The Greater Sage-Grouse wanders the sage brush

The grouse and I are one

For I can’t decipher less helpful NPE’s in grails

Any more than the sage-grouse knows why it wanders the sagebrush

  – @manicode

I’m on a boat motherf$%^r take a look at me

Straight floatin’ on a boat debugging NPE

Busting five knots, wind whipping out my coat

You can’t stop me motherf$%^r cause I’m debugging on a boat

  – @manicode

The usability of NullPointerExceptions

have historically been an issue

by adding static code to dynamic exceptions

our problems we can diffuse

Let go of your stack trace debugging hate

And vote for JEP Three Fifty Eight!

  – @manicode

Many thanks to @costlow, @manicode, @stuartmarks, @perfclarity and @Sharat_Chander for all the laughs! 🙂

Thanks!

Yes, I know this is a silly little Twitter competition. But, if nothing else, this silly little competition provides an excellent opportunity for me to give some overdue thanks:

  • Plenty of thanks and love to all of the users of JMC out there, using JMC to solve tricky problems in production systems on a daily basis.
  • Many thanks to everyone who voted for JMC. I didn’t think a tool would stand a chance against language and runtime features.
  • Huge thanks to all the developers on the JDK Mission Control team, and to all the developers on the JDK serviceability team. You’re a really awesome bunch, and it’s a privilege for me to be working with you.
  • Major kudos to Oracle for open sourcing JDK Mission Control and JDK Flight Recorder.
  • Many thanks to the main sponsors of the development of JDK Mission Control:

JRockit and Duke hanging

[1]: Sadly, not all of the features in JMAPI got rolled into the standardized API. JMAPI could, for example, change the CPU affinity of the JVM process on the fly, dynamically change the heap size target, and independently (and dynamically) switch the GC to use a nursery or not as well as switch between concurrent and parallel mark and/or sweep phases. Of course differences in GC capabilities etc required the standardized API to be limited to what made sense to most runtimes. That said, I’m still kinda bummed that it became a JMX API (java.lang.management depending on the javax.management specification), instead of a pure local Java API, which could also have been exposed through JMX. See, for example, the JFR APIs, where there is a local API and also a JMX API.

Fetching and Building Mission Control 8+

As described in a previous post, Mission Control is now on GitHub. Since this alters how to fetch and build OpenJDK Mission Control, this is an updated version of my old post on how to fetch and build JMC from version 8 and up.

Getting Git

First step is to get Git, the SCM used for OpenJDK Mission Control. Installing Git is different for different platforms, but here is a link to how to get started:

https://git-scm.com/book/en/v2/Getting-Started-Installing-Git

Installing the Skara Tooling (Optional)

This is an optional step, making it easier if you want to contribute to Mission Control:

http://hirt.se/blog/?p=1186

Cloning the Source

Once Git is installed properly, getting the source is as easy as cloning the jmc repo. First change into the directory where you want to check out jmc. Then run:

git clone https://github.com/openjdk/jmc.git

Getting Maven

Since you probably have some Java experience, you probably already have Maven installed on your system. If you do not, you now need to install it. Simply follow the instructions here:

https://maven.apache.org/install.html

Building Mission Control

First we need to ensure that Java 8 is on our path. Some of the build components still use JDK 8, so this is important.

java –version

This will show the Java version in use. If this is not a Java 8 JDK, change your path. Once done, we are now ready to build Mission Control. Open up two terminals. Yep, two!

In the first one, go to where your cloned JMC resides and type in and execute the following commands (for Windows, replace the dash (/) with a backslash (\)):

cd releng/third-party
mvn p2:site
mvn jetty:run

Now, leave that terminal open with the jetty running. Do not touch.

In the second terminal, go to your cloned jmc directory. First we will need to build and install the core libraries:

cd core
mvn install

Next run maven in the jmc root:

mvn clean package

JMC should now be building. The first time you build Maven will download all of the third party dependencies. This will take some time. Subsequent builds will be less painful. On my system, the first build took 6:01 min. The subsequent clean package build took 2:38.

Running Mission Control

To start your recently built Mission Control, run:

Windows

target\products\org.openjdk.jmc\win32\win32\x86_64\jmc.exe -vm %JAVA_HOME%\bin

Mac OS X

target/products/org.openjdk.jmc/macosx/cocoa/x86_64/JDK\ Mission\ Control.app/Contents/MacOS/jmc -vm $JAVA_HOME/bin

Contributing to JDK Mission Control

To contribute to JDK Mission Control, you need to have signed an Oracle Contributor Agreement. More information can be found here:

http://openjdk.java.net/contribute/

Don’t forget to join the dev list:

http://mail.openjdk.java.net/mailman/listinfo/jmc-dev

We also have a Slack (for contributors), which you can join here:

https://join.slack.com/t/jdkmissioncontrol/signup

More Info

For more information on how to run tests, use APIs etc, there is a README.md file in the root of the repo. Let me know in the comments section if there is something you think I should add to this blog post and/or the README!

Mission Control is Now Officially on GitHub!

Since this morning, the JDK Mission Control (JMC) project has gone full Skara! mc_512x512This means that the next version (JMC 8.0) will be developed over at GitHub.

To contribute to JDK Mission Control, you (or the company you work for) need to have signed an OCA, like for any other OpenJDK-project. If you already have an OpenJDK username, you can associate your GitHub account with it.

Just after we open sourced JMC, I created a temporary mirror on GitHub to experiment with working with JMC at GitHub. That mirror is now closed for business. Please use the official OpenJDK one from now on:

https://github.com/openjdk/jmc

If you forked or stared the old repo, please feel free to fork and/or star the new one!

Compressing Flight Recordings

Flight recordings are nifty binary recordings of what is going on in the runtime and the application running on it. A flight recording contains a wide variety of information, such as various kinds of profiling information, threat stall information and a whole host of other information. All adhering to a common event model and with the ability to dynamically add new event types.

In the versions of JFR since JDK 9, some care was taken to reduce the memory footprint by LEB 128 encoding integers, noting that many things, like constant pool indices, usually occupy relatively low numbers. The memory footprint was cut in about half, compared to previous versions of JFR.

Now, sometimes you may want to compress the JFR data even further. The question then is – how much can you save if you compress the recordings further, and what algorithms would be best suited for doing the compression? What if you want the compression activity to use as little CPU as possible?

My friend and colleague at Datadog, Jaroslav Bachorik, set out to answer that question for some typical recording shapes that we see at Datadog, using a set of compression algorithms from Apache Commons Compress (bzip2, LZMA, LZ4), the built in GZip, a dedicated LZ4 library, XZ, and Snappy.

Below is a table of his findings for “small” (~1.5 MiB) and “large” (~5 MiB) recordings from one of our services. The benchmark was run on a MacBook Pro 2019. Now, you’d have to test on your own recordings to truly know, but I suspect that these results will hold up pretty well with other kinds of loads as well.

Algorithm Recording Size Throughput Compression Ratio Utility
Gzip small 24.299 3.28 79.647
Gzip large 5.762 3.54 20.436
BZip2 small 6.616 3.51 23.198
BZip2 large 1.518 3.84 5.826
LZ4 small 133.115 2.40 319.394
LZ4 large 38.901 2.57 100.009
LZ4 (Apache) small 0.055 2.74 0.152
LZ4 (Apache) large 0.013 3.00 0.039
LZMA small 1.828 4.31 7.882
LZMA large 0.351 4.37 1.533
Snappy small 134.598 2.27 305.494
Snappy large 35.986 2.49 89.692
XZ small 1.847 4.31 7.964
XZ large 0.349 4.37 1.523

Throughput is recordings/s. Utility is throughput * compression ratio, and meant to capture the combination of compression strength and performance. Note that the numbers are not normalized – only compare numbers in the same size category.

Summary / TL;DR

  • The built-in GZip is doing a fairly good/balanced job of compressing flight recordings
  • You can get the best utility out of LZ4, closely followed by Snappy, but you sacrifice some compression
  • If you’re prepared to pay for it, LZMA and XZ give a good compression ratio
  • All credz to Jaroslav for his JMH-benchmark and all the data

JFR is Coming to OpenJDK 8!

I recently realized that this isn’t common knowledge, so I thought I’d take the opportunity to talk about the JDK Flight Recorder coming to OpenJDK 8! The backport is a collaboration between Red Hat, Alibaba, Azul and Datadog. These are exciting times for production time profiling nerds like me. Smile

The repository for the backport is available here:

http://hg.openjdk.java.net/jdk8u/jdk8u-jfr-incubator/

The proposed CSR is available here:

https://bugs.openjdk.java.net/browse/JDK-8230764

The backport is keeping the same interfaces and pretty much the same implementation as is available in OpenJDK 11, and is fully compatible. There were a few security fixes, due to there not being any module system to rely upon for isolation of the internals, also, some events will not be available (e.g. the Module related events) but other than that the API and tools work exactly the same.

JDK Mission Control will, of course, be updated to work flawlessly with the OpenJDK 8 version of JFR as well. The changes will be minute and are only necessary since Mission Control has some built-in assumptions that no longer hold true.

You can already build and try out OpenJDK 8 with JFR simply by building the JDK available in the repository mentioned above. Also, Aleksey Shipilev provide binaries – see here for details.

Have fun! Smile

Flight Recorder & Mission Control at Code One 2019

Code One is rapidly approaching (September 16-19). For fans of JDK Flight Recorder and JDK Mission Control, there will be a lot of relevant activities at Code One. This is an attempt to list them. If I missed something, please let me know!

Sessions

Here are the regular sessions:

Session Name

Presenters Day Time

Location

JDK Mission Control: Where We Are, Where We Are Going [DEV4284]

David Buck Monday 9:00 Moscone South
Room 301

Introduction to JDK Mission Control and JDK Flight Recorder [DEV2316]

Marcus Hirt
Klara Ward
Monday 16:00 Moscone South
Room 202
Improving Observability in Your Application with JFR and JMC [DEV3460] Marcus Hirt
Mario Torre
Tuesday 11:30 Moscone South
Room 201
Java Flight Recorder: Black Box of Java Applications[DEV3957] Poonam Parhar Wednesday 12:30

Moscone South
Room 203

Robotics on JDK 11? With Modules? Are You… [DEV2329] Marcus Hirt
Miro Wengner
Robert Savage
Wednesday 16:00

Moscone South
Room 313

Four Productive Ways to Use Open Source JFR and JMC Revisited [DEV3118] Sven Reimers
Martin Klähn
Thursday 11:15 Moscone South
Room 304
Enhanced Java Flight Recorder at Alibaba [DEV3667] Sanhong Li
Fangxi Yin
Guangyu Zhu
Thursday 12:15 Moscone South
Room 203

Performance Monitoring with Java Flight Recorder on OpenJDK [DEV2406]

Hirofumi Iwasaki
Hiroaki Nakada
Thursday 13:15 Moscone South
Room 201

Again, if I’ve missed one, please let me know!

Other Activities

  • There is going to be a hackergarten session around JMC and JFR, Wednesday at 14:30-16:00, inside of the Groundbreakers booth in the Exhibition Area.
  • On Friday a few JMC project members are planning to meet up for some coding between 10:00 and 12:00, and then have lunch together at 12:00. Ping me (Marcus) for an invite.
  • On Wednesday at 18:00 a few JMC project members are planning to go for dinner. Ping me (Marcus) for an invite.

Summary

  • Lots to do at Code One 2019 for fans of JFR and JMC.
  • Helpful links above. Winking smile

Deep Distributed Tracing with OpenTracing and the JDK Flight Recorder

Recently I had a talk at Code One about using OpenTracing together with the JDK Flight Recorder to do deep tracing. Since the session wasn’t recorded, I though I’d do a blog about it instead. Here we go…

Distributed tracing has been of interest for a very long time. Multiple companies have sprung up around the idea over the years, and most APM (Application Performance Management) solutions are built around the idea. Google released a paper around their large scale distributed systems tracing infrastructure in 2010 – Dapper, and there are now several open source alternatives for distributed tracing available inspired by the paper, such as Jaeger and Zipkin.

In Java land, pretty much all of the APMs are doing pretty much the same thing: they use BCI (byte code instrumentation) for getting the data, and then they present that data to the end-user in various ways, oftentimes using some kind of analysis to recognize common problems and suggesting solutions to the end users of the APM. The real differentiation is knowing what data to get, and what to do with the data once captured.

Since there was no standard, one problem was for vendors to inject helpful, vendor specific, information into the distributed traces. The vendor of a software component may have a quite good idea about what information would be helpful to solve problems. Some vendors support APM specific APIs for contributing the data, but more often than not the instrumentation is done using BCI by scores of developers working for the various APM companies. The same is true for maintainers of open source components – either skip the problem entirely and let the APM vendors come up with good instrumentations points (if your component is popular enough), or pick a popular APM and integrate with it. That is, until OpenTracing came along…

Introduction to OpenTracing

OpenTracing is an open source, vendor neutral, distributed tracing API. In other words, library developers can interact with one API to support multiple APM/Tracer vendors. Also, customers can add contextual information to distributed traces without worrying about vendor lock-in. Contributors to OpenTracing include LightStep, Jaeger, Skywalking and Datadog, and the specification is available on GitHub:

https://github.com/opentracing

The core API concepts in OpenTracing are (from the slides of my talk, DEV5435):


Trace


– A distributed operation, potentially spanning multiple processes


– Implicitly defined by the individual Spans in the trace (more soon)


– Can be thought of as a directed acyclic graph (DAG) of Spans


– The span in the root of the DAG is called the root Span


– The edges between the Spans are called References


Span


– Has an operation name


– Has a start timestamp


– Has a finish timestamp


– Has a SpanContext


• Has Baggage Items (key/value pairs which cross process boundaries)


• Implementation specific state used to identify the span across process boundaries)


– Zero or more key/value Span Tags


– Zero or more Span Logs (key/value + timestamp)


Reference


– Defines a direct casual relationship between two spans


– ChildOf


• Parent depends on the child in some way


• Note that it is legal for a finish timestamp of a child to be after that of any parent


– FollowFrom


• Parent does not depend on the result of the child in any way


• Note that it is legal for a FollowsFrom child to be started after the end of any ancestor

Also worth noting is that a Scope is a thread local activation of a span.

The Example

As an example, we’ll be using a simple application consisting of three microservices. It is part of the back-end of a fictional robot store. Robots can be ordered at the Orders service, and they will be produced in a Factory. There is also a Customers service keeping track of the customers. Finally there is a load generator that can be used to exercise the services.

image 

The code is available under https://github.com/thegreystone/problematic-microservices. (Yes, as the name indicates, the services come pre-packaged with built-in problems. :))

The services, as well as the load generator, have built-in tracing support, so for a full systems run with the load generator, you would get a trace (a DAG of spans), looking something along the lines of:

image

Or, in Jaeger, where you have time on the X axis:

tracing

In this case I have scrolled down a bit to focus on the factory. As can be seen, there is great variability in the time it takes to create a chassis and/or paint a robot. We have multiple production lanes, and we’d expect times across the factory lanes to be more even, not to mention much faster. So what gives?

Well, we can expand the operation to see if there was some additional information:

tracing_details

Now, sometimes the tags may include crucial pieces information that may help you solve the problem without needing any additional information. In this particular case, though, knowing that we were building a pink BB-8 isn’t really doing the trick.

What would be the next step? All too often the next step would be to look at the code around the instrumentation point, trying to figure out what was going on at the time simply from analyzing the code. Sometimes that may be quite hard. The problem may be in third party code not expected to behave badly. There may even be some other piece of code not directly in the code path causing the problems, perhaps an agent misbehaving and causing long lasting safe points in the JVM.

So, we’re screwed then? Nah. What if you had a magic tool that could record what was going on in the JVM and the application at the time of the incident? Something providing not only method profiling information, but a deeper view, including information about vm operations, memory allocation profiling, events for the usual application caused thread halts and much, much more. Something that could be always on, with very low overhead. And let’s say you ran with a tracer that added some contextual information, such as information that could be used to identify traces, spans and thread local span activations in the recorded data, and which allowed you to use your favourite tracer too? Then things would get interesting indeed…

Running with the JFR Tracer

For Code One I wrote a little delegating JFR tracer, which allows you to record contextual information into the flight recorder. It was meant as an example on how to do deep distributed tracing. Deep enough to solve entire classes of problems that are hard to solve without more detailed knowledge.

The tracer works with Oracle JDK 7+ and OpenJDK 11+ (it is a multi-release jar, a.k.a. mrjar), and the source is available on GitHub here:

https://github.com/thegreystone/jfr-tracer

The bundle is available from Maven Central, and here is the dependency you need to add:

<dependency>
<groupId>se.hirt.jmc</groupId>
<artifactId>jfr-tracer</artifactId>
<version>0.0.3</version>
</dependency>

Next you need to initiate your tracer and pass it to the constructor of the DelegatingJfrTracer, like so:

GlobalTracer.register(new DelegatingJfrTracer(yourFavTracer));

That’s it. When the tracer is running you will get contextual information recorded into the flight recorder.

Looking at the Recording

Dumping the flight recorder for the factory, and looking at the dump in the Threads view, might look something like this:

image

We can see that we have these long lasting monitor enter (Java Blocking) events, and looking at the stack traces directly by selecting individual events, or at the Lock Instances page, it is fairly obvious where the contention is:

image

We can, of course, create a custom OpenTracing view to make it easier to directly finding and homing in on long lasting traces (I’ll create a repo for a ready made one with some more flair at some point). Simply go the the Event Browser, and right click on the Open Tracing folder. Select “Create a new page using the selected event types”. You will now have a new page in the Outline. You can right click on the title on the page to rename it and switch icon.

Next select an arbitrary event, and right click on it. Select Group-By->Trace Id. In the new Group By table that appeared, select Visible Columns to enable (at least) the attribute showing the longest duration (the total duration of (wall clock) time the trace spent in the process that the recording came from). Next sort on the Longest Duration column.

In this case I’ve ran a few more (press enter in the single step load generator a few times, or let it just continuously add load):

image

You can, of course add additional tables with groupings that can be useful, for example, per thread. To quickly home in the entire user interface on a trace id of interest, just select a trace and choose “Store and Set as Focused Selection”:

SNAGHTML38aee12

Now you can go back to, for example, the Threads view, and click the Time Range: Set button in the upper right corner. Voila, you are in exactly the right place. You may also want to view concurrently occurring events in the same threads (see check boxes on top), and enable additional thread lanes:

SNAGHTML38f17fd

Summary

  • Distributed tracing is great, especially in today’s world of (very µ and plenty) µ-services.
  • For the Java platform, injecting trace/span-identifying information as contextual information into the JDK Flight Recorder is dynamite.
  • A simple example on how to do this automagically is available on my GitHub as a delegating Tracer, in an mrjar, supporting Oracle JDK 7+ and OpenJDK 11+:
        https://github.com/thegreystone/jfr-tracer
  • The slides for my Code One presentations can be found here:
        https://oracle.rainfocus.com/widget/oracle/oow18/catalogcodeone18?search=hirt
    (The relevant session for this blog is DEV5435.)
  • The JDK Flight Recorder r0xx0rz.
  • JDK Mission Control r0xx0rz.

Note that since the article was written, I have donated the tracer to OpenTracing.
See https://github.com/opentracing-contrib/java-jfr-tracer.

Solving Memory Leaks without Heap Dumps

Sometimes you may not want to do a heap dump. You may be running in an environment which is sensitive to latencies. Or you may be forbidden to create heap dumps, since the content will contain all your customer information and all of your organization’s account numbers, and if the dump ended up in the wrong hands, your entire business would be done for. Or you may have an 800+GB heap (yes, some customers run Java with enormous heaps with great success). And even worse, you may have a huge heap, with a relatively small ephemeral disk storage, not even able to store your huge heap dump. And, quite frankly, even if you get your 800+GB heap dump to your puny laptop, how will you open it? How much time will it take to calculate a dominator tree over that dump?

No matter the reason for you not wanting to do a heap dump, there is now (well, since JDK 10 really), a new JFR event allowing you to solve memory leaks without having to do full heap dumps with very little overhead. Black magic you say? Yes, awesome, yummy, black magic.

The Old Object Sample Event

At the heart of the red pentagram (with a black wax candle on each point and encircled with salt) is the Old Object Sample event. It was introduced in JDK 10. It basically tracks a fixed number of objects on the heap, for as long as they are live. To not incur massive overhead, they are selected in a similar way that the allocation event samples are picked – upon retiring a TLAB, or when allocating outside of TLABs. So, a sampled subset of the allocations get tracked.

When a sample is chosen, the allocation time gets stored together with the allocation stack trace, the thread id, the type of object being allocated, and the memory address of the object. If it’s an array, we also record the array size,

The samples are then stored in a fixed size (256 by default) combined priority queue/linked list, with weak references to the samples. If sampled objects are garbage collected, they are removed and the priority redistributed to the neighbours. The priority is called span, and is currently the size of the allocation, giving more weight to larger (therefore more severe) leaks.

Once the recording is dumped, the paths back to the GC roots can be calculated. I write can, since this is optional – it is something that must be enabled in the recording, or as a parameter to e.g. jcmd when dumping the recording. If the reference chain is very deep (>256 object references), the reference chain will be truncated. It is also possible to specify a time budget, so that the time searching references can be limited. For example, imagine a linked list occupying most of the heap, and the sampled object being the tail of that list. The reference chain for that tail sample would span almost the entirety of the heap. With a large time budget, you would still get a truncated sample. If you don’t want to spend so much time searching the heap, you could limit the time budget.

In other words, the Old Object Sample event contains a lot of exciting information:

  • Time of allocation
  • The thread doing the allocation
  • The last known heap usage at the time of allocation
    (Which can be used to plot the live set, even if we don’t have data from the time of allocation anymore.)
  • The allocation stack trace
    (In other words, where was this object allocated?)
  • The reference chain back to the GC root at the time of dumping the recording
    (In other words, who is still holding on to this object?)
  • The address of the object

There is some additional information. You can check out IMCOldObject in the OpenJDK JMC project source for more details.

Here is an Old Object Sample event shown in the JMC 7 Properties view:

image

Using the Old Object Sample Event

The best way to use the Old Object Sample event is to use it in a long running application. The longer the better. Statistically speaking, you want to offer as many chances as possible for a leaked object to end up being sampled. You’d also want to be well beyond the loading of all your code. Also, you would want to have been running long enough to be sure that transients have been cleared out. For example, if you have a session time-out of some kind set to 2 hours, and a ginormous application server and even larger application taking 15 minutes to start, then the first 2 hours and 15 minutes of runtime will not be that exciting from a memory leak hunting perspective.

A simple way of using the event is to simply go look for events still around after the warmup phase, but before transient objects could reasonably still be around. An even simpler rule of thumb – look at the ones allocated in the middle of the time span. Winking smile

image

Since there is currently a bug open on JMC 7 (JMC 7 has not been released yet; we hope to fix it before we release), “picking the middle” is not yet possible. That said, in the picture above we can see that most live objects being tracked are actually held on to by the Leak$DemoThread, which has a Hashtable (what can I say, it’s a really old example program), having an entry array, containing an entry holding on to a Leak$DemoObject which in turn holds on to a leaked char[].

Now, JMC has a more sophisticated algorithm for selecting good candidates than “go for the ones in the middle”. It first check if we have an increasing live set. If so, and if we have Old Object Sample information, we will try to find good candidates using a combination of the distance from the root, the ratio of how many objects this candidate keeps alive to how many objects its root keeps alive and the ratio of how many objects the candidate keeps alive to how many objects are alive globally. For more information, check out the ReferenceTreeModel in the JMC project.

This has already become a much longer post than I was planning on. Anyways, if you want to experiment a bit with the Old Object Sample event, I have an upcoming JMC and JFR Tutorial that I am planning on “releasing” when JMC 7 is out. That said, you can already beta test it. There is some more information in the blog entry prior to this one.

The Practical Guide to the Old Object Sample Event

If you use the continuous template, this is recorded:

  • Timestamp
  • Thread
  • Object Type

If you use the profile template, this is recorded:

  • Timestamp
  • Thread
  • Object Type
  • Allocation stack trace

If you ask for paths-to-gc-roots you also get the reference chains. This can be done by:

  • Adding it as a parameter on the command line:
    -XX:StartFlightRecording=path-to-gc-roots=true
  • By asking for it when dumping the flight recorder, for example using jcmd:
    jcmd <pid> JFR.dump path-to-gc-roots=true

You can also configure the number of objects to track by setting the old-object-queue-size in the flight recording options, for example:

-XX:FlightRecordingOptions=old-object-queue-size=256

If you want to configure the cutoff for how long to search for references, that can be done in the template file, for example, these are the default settings in the profile template (JDK_HOME/lib/jfr/profile.jfc):

    <event name="jdk.OldObjectSample">
      <setting name="enabled" control="memory-leak-detection-enabled">true</setting>
      <setting name="stackTrace" control="memory-leak-detection-stack-trace">true</setting>
      <setting name="cutoff" control="memory-leak-detection-cutoff">0 ns</setting>
    </event>

Summary

  • The Old Object Sample event is awesome
  • It can, among other things, be used to hunt down memory leaks without doing hprof heap dumps
  • It will also bring you luck, good fortune, not to mention smells good

Sneak Peek of JDK Mission Control 7 Tutorial

Even though JMC 7 is not GA yet, I thought I’d make the upcoming JMC Tutorial available on my GitHub. Hopefully this will be a good resource to help to learn more about using Mission Control 7 and Flight Recorder in OpenJDK 11.

It does takes a bit of preparation to run it for now:

  • JDK Mission Control will need to be built from source, since there are no update sites available yet
  • JOverflow will not work until JMC-6121 is solved
  • Exercise 5 will be better once JMC-6127 is solved

That said, all the preparations needed are listed in the README.md file in the GitHub repo:

https://github.com/thegreystone/jmc-tutorial

Please let me know if something is missing from the instructions!