Day 5 - A Gentle Introduction to X-Trace

Written By: TR Jordan (@_tr)
Edited By: Adam Compton (@comptona)

In the world of SaaS applications, good monitoring can be the difference between a successful product and a failure. There's a lot of ink spilled on what to do with your monitoring data, but somewhat less on what that data actually is. Etsy's Measure Everything is a great place to start. Capture points of interest everywhere in your application, and aggregate them up as counters, gauges, and the like. You don't have to stop with series of single numbers, though. Let's talk about gathering structured performance data via X-Trace, starting with a definition:

X-Trace is a network diagnostic tool designed to provide users and network operators with better visibility into increasingly complex Internet applications. It does this by annotating network requests with metadata that can be used to reconstruct requests, even those that make use of multiple network layers. X-Trace "enabled" Internet sites make use of these identifiers to record the path that requests take through their network.

The key bit about X-Trace is right there at the end. X-Trace isn't just a tool to collect metrics; it actually records the path that requests take through your system. This means that the end result isn't just a graph over time of some quantity. It's actually a full view of what happened to that particular request.

The other core feature of X-Trace is something that's left out of the definition. Because X-Trace annotates network calls, it's fundamentally distributed. As it traces requests, those requests aren't limited to a single machine, like a code profiler would be. Each piece of metadata is generated on a separate machine (typically by processes called agents), but a typical implementation also employs a collector which stitches all that information back together into a distributed trace.

The result is that X-Trace data is a much richer data source than something like graphs of machine load, host memory, or the number of signups. It's a full description of how your system responded to a particular request.

Building a Simple Trace

Let's get specific. The underlying data structure X-Trace uses to represent this complex data is a simple Directed Acyclic Graph (DAG). The nodes in the graph are entry and exit events for each layer. Layers are just names for something we want to measure: TCP connection lifetimes, RPCs, or application touchpoints. For a typical web application, it's easy to talk about layers as software packages which use the library in some way, so we'll do that. The first place a request touches a web app is the webserver, so a dirt-simple trace may only have 2 nodes in the graph: Apache Entry and Apache Exit. The edges in this graph point "backwards" -- exit events know about their preceeding entry events. This can be confusing, so let's actually flip them around so the arrows point in causal order. Our simple trace could be drawn (using GraphViz) like this:

Apache serving a static file. It's frequently easier to flip the edges in visualization, even though the underlying data is reversed.

So the forward arrow makes sense--then why did you say the edges point backwards? From an implementation standpoint, they have to! Each node is represented by a metadata string, which is just a bytestring. The high-order bits of this bytestring form the trace ID, a unique identifier which all nodes in this request's trace graph share. The lower-order bits are unique to each node, and typically also randomly generated. These are known as the event ID. Each edge is specified with this event ID. For the trace above, the two events would look like this:

Entry:
  Trace ID: BA84
  Event ID: FEED
  Edges: []
Exit
  Trace ID: BA84
  Event ID: DEEF
  Edges: [FEED]

With only that information, we have everything we need to draw that picture above. As long as we find some way to pass that edge ID between the beginning and the end of the request (and since they're on the same machine, local memory works fine), the events are easy to generate, and the collector can re-create the graph with no problems.

Getting More Complicated

If we were just interested in collecting simple timings, drawing a graph seems like overkill (because it is). The interesting thing about X-Trace is that it scales up to many events in a system, and we can still track them all in one place. Let's add a simple Ruby/Rails server behind Apache. We'll actually put the instrumentation points in basically the same place: at the very beginning of the Ruby request, and right at the end, after it returns the response body.

There's also an "info" event in this one, which can be used to add a bit more color to an entry/exit pair. More on that below!

There's one trick we have to play here to make this work. In Apache, it was easy to pass the event ID around, because it's all the same process. Between Apache and Ruby, they're different processes on different machines. Local memory won't work, so we have to get more creative. Fortunately, X-Trace is flexible; it doesn't matter how the metadata gets between events. In this case, an extra HTTP header (how about "X-Trace"?) on both the request and response works just fine. In general, any extensible protocol with optional parameters works well here: Thrift, Protocol Buffers, or even custom JSON over TCP, if you're rolling your own. If you can find room for a few additional bytes, your protocol can support X-Trace.

Adding these links gives us more than just the two timing measurements in one place; it allows us to start seeing mismatches between components. A frequent problem with multi-tier setups is queueing, particularly between the web server and the application servers. Monitoring just Apache or just Rails doesn't catch it, because the problem is the Apache is sitting around waiting for Rails to listen. There's no wasted work, but there is wasted time. With normal metrics, you have to go looking for it, but with X-Trace, it just shows up as a large time difference between two adjacent nodes.

Real Life Data

From here, we can scale this up to as many protocols and calls as we want. For protocols that don't easily support optional parameters in both directions (SQL, for instance), we can actually measure from the client side. This does have the disadvantage of convolving network latency and on-machine time at the database server, but in most cases, this isn't a big deal.

In these complex cases, this graph structure really starts to shine. A slow request might generate a trace with a slow SQL call. From a single-metrics viewpoint, speeding up this request means making this SQL call faster. With the entire trace, though, the problem might actually manifest as a cache miss immediately before the SQL call, or a strange-looking URL from the webserver because the client was asking for more data than a normal request. This context is crucial to debugging certain classes of problems, and it's simply not available in metrics-based monitoring solutions.

A moderately complex trace ... and it keeps going! This trace has 55 events in total.

Traversing a Trace

Once traces get big, the trick is to extract useful information out of them. There are a lot of tricks one can use on graphs, but there's actually more structure here we can exploit. Since X-Trace typically starts with entry/exit pairs of events, it's a good idea to build more structure around those pairs. For our simple Apache trace, it's easiest to think about that as a single Apache extent. That means just wrapping up the entry and exit in a single span of time. The (awesomely boring visualization) might look like this:

Just Apache.

The width is the full timeline of the request: 200us. Now that we have some grounding, we can start to build out more complicated traces below this. Adding rails is just adding a child extent to this top-level extent, and we can represent that with a bar below, on the same timeline:

Deepening the tree.

This looks pretty similar to the events graph, but instead of looking at moments in time, this visualization focuses on layers: the components of the system. It's not as detailed as a profiler at each layer--we're not capturing every function call--but the whole trace is effectively a profiler, ordered by calls, for a distributed system, including access to call structure, self times, and cumulative times.

If you've got a complex architecture, with services calling services, this might look like a bit hairy, but fortunately, many apps scale by adding specialized services, not 50-level-deep calling trees. So you can see a fair bit in one place and, due to the time scale, quickly identify the service that dominated the load time. For instance, that moderately complex trace above reduces down nicely:

In this one, the problem isn't a single layer. Every layer adds a bit of time, meaning that we'll either have to be happy with our 70ms page load time, or look at eliminating an entire service or three.

Using Trace Data

Once we have this structure, sometimes the easiest thing to do with it is go backwards. Because each trace captures a number of different metrics on different layers, we can actually traverse this graph and pull them out into normal-looking graphs. This high-level view is easy to consume, but graphs backed by traces instead of metrics open up another level of drilldown. Spike in memcache latency? It could be because of increased traffic, but looking at a few traces might reveal that it's actually because there are a few URLs that request 10,000 different keys at once (as has been seen before). Inspecting the structure of a request can often times reveal just as much as looking at the timings of the components.

There's a lot more that can be done with this data, but suffice it to say, analytics are only as powerful as their data source. A few people have written implementations of it:

• AppNeta TraceView - Instrumentation in PHP, Python, Ruby, Java, and .NET. I actually used the free version for most of the visualizations in this post.
• Google Dapper - Google's own implementation, on their RPC infrastructure.
• Twitter Zipkin - X-Trace instrumentation, with trace visualizations.

Good monitoring is not only about the quantity of data collected, but also the quality.

Day 4 - Make sense of Perfmon with PAL

This article was written by Sam Cogan (@samcogan)

You've got a performance problem: your Windows server or application isn't performing as well as it should. You need to find out why. When Task Manager isn't enough it's quite likely you'll reach for Perfmon.

If you don't know already, Perfmon is the Windows performance monitor. It can be found under administrative tools on all versions of Windows from Windows 2000 onwards. It provides a way to monitor counters - metrics of your system performance, such as %CPU use, Free Memory etc. Many Windows applications come with their own custom set of counters for their specific application. We can use perfmon to setup sets of counters (Data Collector Sets) to collect data and to allow easy re-use. Once we have created a collector set we can start logging. We can leave it running however long we like, then come back and review the data. Perfmon also provides some step by step wizards to help the beginner start using it quickly.

For more information on using Perfmon, see this article

Perfmon is an excellent tool for collecting data. The problem comes when trying to analyse this data. Often, when we're not sure what the problem is, we'll add a wide range of counters to make sure we've covered all areas. Very quickly we've collected a large amount of data about the performance of the problem machine or machines.

Chances are that if you open up these files in Perfmon, then you'll end up with a selection of lines on a graph, information that seems like it should be useful, but is often hard to decipher what it actually means and if you have a lot of counters you can end up with a mess of colour lines that make a nice picture, but has no meaning whatsoever!

What do we do? How do we get some useful information that will help us solve this tricky performance problem?

Yes, you could go through and filter out the lines you don't need. What you really need is a way to give meaning to these lines - to see what is normal or abnormal, or to simplify the data or change its presentation into something more digestable. This is where PAL comes in.

PAL

Perfromance Analyis of Logs or PAL is a tool written by Clint Huffman at Microsoft, to assist in analysing Perfmon logs and to produce an HTML report that will provide detailed graphs, and indications of where a problem may lie. It provides a simple GUI to a complex Powershell script that actually does most of the work.

To understand how to use PAL, we need to look at it's 4 main components

1. The Log file
2. The Threshold File
3. Questions
4. The End Result

So, let's download PAL, fire up the GUI, and get to work!

Log Files

The Perfmon log file is where all PAL looks for data. A key advantage to using PAL is that you do not need to consider log size when you look at collecting your data. You can include all the counters you might need, and then instruct PAL to only analyse the ones you want and only during a specific time period. The only caveat to this is that PAL will not work as well if you have multiple computers feeding a single log file, as it will assume that the configuration of the machine is the same for each counter.

So, tell PAL where you log file is, and specify a time range for the data you want to analyse if you don't want to look at the whole file (if you have multiple files, we can add them later).

Threshold file

The threshold file is what makes PAL a useful tool. In essence, it's just a simple XML file used to define what kind of analysis you want PAL to do on your log files.

The first thing this file does is to define what counters you want to analyse, meaning you can skip any counters that you're not interested in or don't apply to your current problem.

Next, and the reason it is called a threshold file, it lets you set thresholds on each of your counters. This allows us to add some meaning to the data we have collected. We can define what value for each counter defines a warning state and what defines a critical state and so bring potential problems to our attention.

Finally, the threshold file allows you to specify questions to ask. We will come on to these shortly.

This may sound like a lot of work, but it doesn't have to be. PAL has a number of threshold files included that cover many of the common server configurations, e.g. Exchange, OCS, SQL, and a catch all, systems overview file. Using these built in threshold files, or by downloading additional ones from the Internet you can make extensive use of PAL without ever needing to write any code.

If these threshold files do not meet your needs, or you need one that is tailored to your needs, then PAL includes a GUI that assists you in doing just that. Selection of counters is done via the user interface. However, the calculations used to determine threshold values are written in Powershell, so some ability to write Powershell code is required.

If you haven't yet collected your Perfmon data, you can also use PAL to generate a Perfmon template from a threshold file, so that you only collect the data that this threshold file will generate.

Questions

The questions section asks you for some extra information about the machine this Perfmon log is for, for example number of CPU's, amount of memory etc. These questions are important, because the values you give can be accessed in the Powershell code inside the threshold files. These values can be used to assist in calculating your threshold levels.

Questions are configured inside the threshold file, and can be edited and added through the PAL GUI when creating a threshold file. When you add a question you create a Powershell variable that is available for use later inside threshold calculations.

Running the Analysis

Once you have selected your log, your threshold file, and answered some questions, you are ready to go. At this point, you add your job to the queue. You can then choose to either run this queue now or queue up more jobs to run in a batch. PAL analysis jobs can take a number of hours to run, depending on how much data is contained in your logs, so it is often convenient to queue up jobs to run overnight.

Ok! So, you've run your analysis and PAL has spat out some HTML files, how are these useful?

First off, for those in a rush or who want a quick overview of what problems there may be, there is the alerts section. This looks at the threshold values we had in our threshold file, and gives a visual indication of what areas of this log are in a warning, or critical state. It's very easy to quickly see where the machine is struggling, and where you may want to focus your efforts on fixing the problem.

Once you've been through all your alerts, we then have detailed information on all your selected counters. Each counter is presented separately, with a graph, alert details and statistics. Threshold data is also presented on each graph, allowing us to quickly see at what point there was an issue and how severe it was.

As you can see from this graph, this job is making the CPU a little unhappy at times and might be something that needs to be looked at!

Summary

Perfmon is a great tool for collecting performance data, but it sucks when it comes to actually analysing this data and getting some meaning from it. What looks like a big spike in the Perfmon viewer could actually be normal operation for that counter - we're missing some helpful context. We can use PAL to give us information that is not only easier to read but also has some meaning to it. From this, we can determine which data is normal and can safely be ignored, and which data is anomalous and is something that we need to investigate.

PAL is by no means perfect; getting useful reports out of this tool relies on having a threshold file that covers the counters you need to analyse with meaningful threshold calculations. If one of the included files, or one found on the internet covers this then that's great, but if not you are stuck needing to write your own using Powershell, which can be quite a complex task if you have lots of counters you want to analyse.

Users who need to analyse perfmon data alot will invest the time in customising their threshold files to get out exactly what they need, however more casual users are going to rely heavily on the pre-constructed files.

That said, more and more product areas are seeing the value in PAL and providing threshold files for their products, Exchange and OCS are two examples of this. There's no magic pixie dust in these threshold files. If you can understand Powershell, then you can write your own to handle any Counter that Perfmon can use, including third party ones. So it's a great option for people who need to analyse uncommon data. It's also open source, so if you want to see how the Powershell code behind the analysis, you can.

It's also not a quick process; log analysis can take hours. If you're looking for an immediate answer to your problem then you are going to have to use other methods of getting your answers.

If, however, you've got the right threshold file, and the time to run the analysis, then this can prove an invaluable tool to help you get meaning, and ultimately solve your problems, from Perfmon data.

Further reading:

• PAL on Codeplex
• Clint Huffman's Windows Troubleshooting in the Field Blog
• Using the Performance Analysis of Logs (PAL) Tool