Java Flow Profiler (Jflop)

This document explains the idea of the flow-based profiling, and shows how JFlop can be used to find the performance bottlenecks in your application.

What do we expect from a profiler?

Performance and scalability are important characteristics of the "enterprise applications". When the application doesn't respond or scale as we expect, we need a profiler to find out what's going wrong.
Requirement No.1: The profiler must be useful in finding the real performance and scalability bottlenecks (and not just the most expesive methods)

Unfortunately the unit and functional testing cannot discover all the performance and scalability problems. These problems usually happen under real load - either in production or during the load testing, and are hardly reproducible in the development environment.
Requirement No.2:The profiler must be lightweight enough to be used under real load and not change the program behavior.

Sometimes the problems don't happen right away even under the load, and it takes from several hours to several days for the system to stuck. Or on the contrary the system can look stable, but have perfomance bursts (increased response time, or decreased throughput, or both) from time to time.
Requirement No.3:Ability to run the profiler in the "monitoring" mode when the snapshots are taken automatically and can be analyzed retrospectively.

Collecting the performance data per method is not always helpful. The same method can be used in different flows, and if you want to improve the response time of a specific flow, the statistics collected for such method can be misleading - you optimize the method, and it doesn't improve the response time.
Collecting the performance data per thread can be also inappropriate. In the application servers the same thread can be re-used for different requests. On the other hand under high load there can be tens of threads executing the same flow.
The semantics of flow can vary depending on the application - it can be serving a specific resource to the user, executing a specific user-initiated action (per action type or per unique parameter set), performing some maintenance job in the background, etc.
Requirement No.4:The profiler should collect the performance data per flow, because this is the best way to find and fix the performance problems.

Jflop: flow-oriented profiler

Jflop collects the performance statistics per flow. Flow is a chain of invocations of selected code blocks. These code blocks are demarcated via the code instrumentation at compile time, and recorded at runtime.

Jflop has two parts - instrumentation API used at compile time, and runtime components exposed as JMX MBeans. The instrumentation API includes four methods: flowBegin(), flowEnd(), blockBegin(), blockEnd(). These method calls should be inserted into the code similar to how the logging calls are inserted.

At runtime the user can take snapshots via the monitor MBean. During the snapshot JFlop records the instrumentation calls in each thread together with their stacktraces and current system time. The stacktrace serves as a unique identifier of the call, so that Jflop can distiguish between different flows leading to the same code block.
At the end of the snapshot Jflop aggregates the recorded sequences into flows and calculates the statistics for each flow and each block (min/max/average time and count). For each flow a new MBean is automatically created and registered, so that the flow statistics can be accessed by third-party monitoring tools (such as Ganglia or Zabbix).

Snapshot format

Below is a fragment of a snapshot generated by Jflop. The flow is represented as a chain of blocks, where you can see the sequence of calls leading to each block. Each block is shown as 3 lines:

BEGIN - shows the line of the block begin and optional text label
END - shows the line of the block end and optional text label
STAT - shows the block statistics including the minimum, maximum, and average time, count, and cumulative time.

The whole flow statistics is presented at the top of the snapshot text

snapshot

How to use Jflop

Current version of JFlop is API-based, which means that you have to put into your code the Jflop calls, just like you do for log4j calls. If you want to change the code instrumentation (add/remove block demarcations etc), you have to build and deploy the application. This is obviously a disadvantage, but if it helps to solve performance and scalability problems - it worth it.

When you have your code instrumented and deployed, you can use the Jflop MBeans to take snapshots and trun monitoring on/off. The flows detected during the profiling are also exposed as MBeans and can be accessed either manually or by third-party monitoring tools.

Code instrumentation

To instrument your code with Jflop you need to add the file jflop-1.0.jar to your compile time classpath. The only class you need for the instrumentation is org.jflop.Profiler. This class has the following static methods:

Profiler.flowBegin(String... flowName)

Use this method to mark the flow begin. Not that this method must be called on the current thread for the profiler to start collecting statistics on that thread. This is the way to ensure that only complete flows are recorded.
The calls to flowBegin should be called at the very beginning of your processing, for example from Servlet.service() method etc.

The method has optional string arguments which can be used for labeling the flow, for example "resource serving", "action execution", or "scheduled task". The label can be dynamic, for example the name of the served resource. Note that the labels are part of the flow unique identifier, i.e. two flows are different if they have different labels. This allows you to distinguish between the flows by runtime data, which is a strong advantage of the API-based instrumentation. However dynamic labels should be used carefully, as they can lead to flows duplication.

Profiler.flowEnd()

Use this method to mark the flow end. It's important to call this method even if an exception is thrown during the processing. The code pattern usually looks like that:

Profiler.flowBegin("Resource serving"); try { // do some processing } finally { Profiler.flowEnd(); }

Profiler.blockBegin(String... label)

Use this method to mark the block begin. The method has optional string arguments which can be used for the block labeling. The block labels are a part of the block unique identifier, so two blocks with different labels are different. Note that the block begin labels are added to the flow title.

Profiler.blockEnd(String... label)

Use this method to mark the block end. The method also has optional string arguments which can be used for the block labeling. Note that the block end labels are not added to the flow title.
It's important to call this method even if an exception is thrown during the block processing. The code pattern usually looks like that:

Profiler.blockBegin("Content generation"); try { // do some processing Profiler.blockEnd(); } catch (Exception e) { Profiler.blockEnd("failure"); // handle the exception }

Profiling

When you've compiled and deployed your instrumented application, you can start profiling. Jflop has no its own UI. Instead it exposes MBeans which can be accessed via different third party tools. Jflop defines two types of MBeans: single monitor MBean which must be deployed manually, and multiple flow MBeans which are created and registered automatically.

Monitor MBean

Manual deployment of MBeans to the application server varies from vendor to vendor. This distribution of Jflop contains JBoss service archive jflop.sar which should be saved to the server deploy folder. After the JBoss starts you can find the monitor MBean via the jmx console under the name jflop:service=monitor

The monitor MBean allows to set the snapshot interval, and provides two modes of profiling:

Take snapshot
Takes a single snapshot. The method blocks for the snapshot duration and returns a formatted snapshot text.
In addition to that for each detected flow a flow MBean is created and registered. The flow MBeans from the previous snapshot are unregistered and destroyed.
Start/Stop monitoring
When in monitoring mode takes snapshots continuously. For each detected flow an MBean is created/updated. The flow MBeans are not deleted during the monitoring session, but only when the monitoring is turned off.

Flow MBeans

The flow MBeans are automatically registered with the name pattern jflop.snapshot:flow=*, where "*" is replaced by a number. It's important that the flow MBeans are registered with the platform MBean Server, so that they can be accessed from JConsole and other monitoring tools. Note that JBoss MBeans are usually not visible from JConsole because JBoss uses its own MBean Server.

Flow MBeans are read-only and expose the flow statistics data, and the snapshot text.

Integration with monitoring tools

Since the flow MBeans have well-predictable names (jflop.snapshot:flow=*) and expose the response time, throughput, and snapshot text as attributes, they can be easily watched by any monitoring tool which can access JMX MBeans (like Ganglia or Zabbix). The monitoring tools store the attribute values (including the snapshots text) in their database which allows you to analyze the behavior of the application retrospectively. This is a very useful tool for the stress and stability testing.

Here is a link to Zabbix template file containing the configuration of items and graphs for 20 flows. Below is a fragment of Zabbix monitoring screen showing the label, response time and throughput graphs (defined in that template) for selected flows.

zabbix