How to Trace Transactions Across Every Layer of Your Distributed Software Stack

APM solutions give you great visibility into any code you have control over; however, today’s systems are largely a combination of code you write along with off-the-shelf components, sitting on top of VMs/containers, and cloud-based services. Thus, full system-wide visibility requires an ability to look into your APM tool as well as log data produced from the components that you may not be able to instrument.

This post offers an outline of how APM solutions work and how you can combine them with your system logs to finally get an end-to-end and top-to-bottom view of your system behavior and performance.

How APM Tools Work – Hello APM

APM tools give you insight deep into your code and often work using cool techniques like dynamic instrumentation. Dynamic instrumentation essentially allows you to instrument your apps on the fly without any need to modify your application source code.

Such techniques have become widely been supported by mainstream programming languages to make it possible for even mere mortals to build their own APM tools.

For example, since Java version 5, any Java applications can be instrumented using java.lang.instrument, which allows for the instrumentation of any programs running on the JVM through modification of the byte code of methods.

It works by letting you alter the corresponding byte code of a class when it is being loaded, such that you can introduce monitoring capabilities such as execution profiling or event tracing.

There’e a great beginner tutorial here by Julien Paoletti on how to write your first APM tool in java. It essentially shows you how you can intercept classes at class load time and then inject code into methods of your choice to record how long it takes for given methods to execute.

While building a full APM solution is not for the faint hearted, you can easily begin to build your first ‘Hello APM’ tool, and play around with JVM internals following Julien’s post above.

Transaction Tracing

For those interested in moving beyond simply recording method execution time, you can begin to trace full transactions using some simple techniques. To do so, you essentially need a unique identifier to be passed along to any methods executed in that transaction. Continuing on from our hello world profiler above, you could do this by injecting a unique ID into the thread at any entry point in the system (e.g. new incoming requests). Java provides ThreadLocal storage that allows you to do just this. Using ThreadLocal you can embed a unique ID that gets recorded as each method executes.

Reconstructing a Transaction  

On every invocation of a method along the transaction data is logged. An example of what might be logged by an APM tool is as follows:

• unique transaction id
• sequence number
• call depth
• method details
• performance data

You can then easily piece together full transaction traces by ordering all method calls by sequence number. Further analysis can be applied to this information for a number of purposes. For example, by analysing the transactions, developers can easily construct design diagrams that can help quickly deduce overall system structure. Relationships between system components can help understand interdependencies enabling developers to anticipate potential conflicts and to debug problems as well as allowing them to reason about their system design (which in turn can have a major impact of system performance).

Tracing Transactions Across the Network

The real challenge with transaction tracing can come when you are dealing with distributed components.

In such scenarios you need to be able to trace transactions across the network. One approach here is to piggy-back the necessary correlation data (unique transaction ID) onto the request from a client to the remote server.

RPC (remote procedure call) systems generally employ a standard mechanism, known as ‘stubs and skeletons‘, to hide the complexities of the network from the client making any remote calls.

Stubs and skeletons work as follows:

• The stub masks the low level networking issues from the client and forwards the request on to a server side proxy object (the skeleton).
• The skeleton masks the low level networking issues from the distributed component. It also delegates the remote request to the distributed component.
• The distributed component then handles the request and returns control to the skeleton, which in turn returns control to the stub.
• The stub, in turn, hands back to the client.

One approach to the issue of tracing transactions across the network can be achieved by taking advantage of the stubs and skeletons model. Essentially the stub and skeletons can be modified such that the unique transaction ID piggy backs on the communication and is sent as part of the request to the stub and response from the skeleton. The implementation may differ from platform to platform, but the principles can generally be applied.

For example, Remote Method Invocation is used for distributed communication on java platforms and details on how this can be achieved for RMI can be found in one of my older research papers here.

RMI with Custom Stub Wrapper and Server Side Interception Point

Going Beyond APM

The above transaction tracing will give you visibility at a method call level across your distributed application. However sometimes external factors outside your application code (server resource, SAAS components your app communicates with, network speed etc.) will have an impact on your overall system performance.

One way of enhancing the information provided by your APM solution is to collect and analyze your log data. Logs provide a very flexible way of gathering information on your system behavior without any requirement for deep instrumentation and any of the complex techniques described above. Furthermore you may not be able to instrument every software component or cloud service that makes up your overall system – yet almost all of these will produce valuable log data containing system usage and performance information.

In such scenarios, combining APM and log data will give you the complete picture. Below are some tips that will allow you to map logs to APM transactions or to enhance them with data from additional components such as OS, middleware or network level components:

• Logging the Transaction ID: Any log data produced by your apps can be easily mapped to transactions produced by your APM tool by logging the transaction ID used to trace the transaction.
• Client Side Logging & Logging User/Session/Account ID: Logging other unique identifiers such as session ID, user ID or account ID, can also help you assist with tracing transactions across log events, where the transaction ID used by the APM tool is unavailable. This can be particularly useful if you are logging events from the client side as well as from back end components where you want to be able to view the sequence of log events related to a give user action or session for example.
• Same Time Frame For System Logs: Where unique identifiers have not been logged as part of your log events, viewing logs within the same time frame window as your APM tool will help you narrow down related log events and will give you a view into system behavior during the transaction time frame.
• Correlating with Other KPIs: Logs will contain key performance and resource usage metrics that can be rolled up into trend lines and charts. Correlating APM transaction traces with performance metrics and server resource usage information can help with investigation can result in quicker root cause than investigating transaction traces in isolation.

Build It Yourself?

Naturally anybody in their right mind would not actually go about building their own APM solution, it’s almost as hair-brained as rolling your own logging solution

The good news is you don’t have to do either – simply take advantage of the new Logentries and New Relic integration such that you can trace transactions from end to end and from top to bottom of your entire distributed software stack.