Transcript
Oli Lane: A few years back, I have this really vivid memory of a customer complaint coming in. It was late on a Friday, of course, they always are. I was just letting my mind wander towards the pub, and this message comes through. It's a big customer, it's a customer we need to keep happy. They said, my backup job ran like an hour late, what's going on? They were pretty annoyed, rightly so, they need to trust that our backup product works, and it's solid and it's dependable. Of course, we dug in. We had our dashboards. We had our metrics. We had our logs. We had our alerts. We did some rooting around, we came up with some plausible theories. We put in a few fixes, a few improvements to make sure that any of the things that we suspected it was wouldn't happen again. I got to the pub a bit late, end of story.
There was this thing that didn't sit right with me and it was that we never really figured out the most important question, which was, why did that job run late and why was it late that time? It was like a murder mystery with the last chapter ripped out. It really annoyed me. This talk is the story of getting from there, where we're squinting at graphs and making a good guess, but mostly shrugging to being able to point and explain the exact bottleneck in a distributed asynchronous system.
Background
I'm Oli. I'm an engineering team lead at Gearset. I've worn many hats, but recently I've been focused on levelling up our observability and our incident response and our team culture as well so that we can build reliable, dependable software, especially as we scale.
Julian Wreford: I'm Julian. I've been part of Oli's team for the last three years as we've built out those observability tools and recently stepped into the team lead role for the team that Oli's been leading.
Oli Lane: From this talk, we're hoping you'll take away a practical knowledge of how to better understand the performance characteristics of your queues in particular, and we'll go through the foundations of OpenTelemetry and build on that to explain practical strategies that we've used to turn our queues from that point of confusion within our teams to something that we really feel confident running in production. We'll discuss different strategies to measure queue health, and then we'll finish off with some tips and tricks that we really wish someone had told us when we were getting started. You should go away better equipped to understand why metrics and logs aren't enough to truly understand your async workflows and how OpenTelemetry might help, how to know when your queue is healthy or unhealthy. How to empower your teams to measure and debug how customers are experiencing your system, and how to take that next step and get your teams adopting this stuff.
Why Queues?
Let's take a step back for a minute. Why do we need queues in the first place? Your system probably doesn't start with a queue right from day one. If you've got queues, you probably added them after hitting either a pain point or to resolve some architectural problem. For us, we started with all our code in a single monolith, looked a bit like that. We had multiple replicas of that monolith but only one image that actually shipped. At some point, we needed to organize that better and we decided to split off a few things to handle different responsibilities. Specifically, we wanted our scheduling code, so that was the code that was responsible for kicking off user jobs at specific times. We wanted that to run separately from our core application code. We did that in the simplest way possible. We spun up a new service, it had its own database.
To begin with, it would just poke a HTTP endpoint on the core app and it would kick off a job. Simple enough. That was a good start, but it had some immediate problems and some of these might feel familiar. We had no ability to smooth the load. We had a whole load of customer workloads configured on the scheduler, and one of those workloads was backups, and we let people pick when they wanted to run their backup. I don't know if you've ever given people a date, time picker for their backups but almost everyone picks midnight. Unfortunately, that meant that at midnight, our scheduler would suddenly DoS our application code with hundreds of requests to start some really heavy jobs in parallel. We could work around this in some ways. We could scale the application code or we could put bodges in the producer code and try and throttle it.
We could take the choice away from the users. Ultimately, these spikes were causing problems and we had no real way of dealing with them properly. Then, also, the workloads weren't truly decoupled. When you synchronously call via HTTP from one service to another and you expect a response, you still, in some ways, have a hard dependency between those services. One has to be up for the other one to work properly. We wanted to be able to take the app down without worrying whether the scheduler was up and what it was doing. Queues could solve both of those problems. Queues smoothed the load without the producer needing to know anything about the consumer. The scheduler could just dump a few hundred jobs on the queue and those consumers could pick them up at their leisure with sensible concurrency limits. Queues meant that if the consumers went down, we could build up a backlog and we could just let the app catch up when it got back online. These are not the only reasons you might introduce queues, but they were the main drivers for us. Of course, once we had one queue, everything looked like a nail and we had plenty of other sensible places to add our queues.
The next problem, as soon as you've got queues, is how to figure out if your queues are happy. We all know that software will always go wrong if it has a chance to. Whatever queuing technology you're using, whether it's SQS, Kafka, Rabbit, something else, you'll get some metrics emitted out of the box. These are some of the most common ones you'll have to work with. Queue size, the number of items currently on the queue. The enqueue rate, so how many items are being queued per time period. Dequeue rate, how many are being taken off per time period. Then the in-flight count, which is just how many are currently being processed. The basic idea here is if your enqueue rate is consistently higher than your dequeue rate, you're putting more into the bucket than you're taking out, and the queue size is going to grow. That could happen for loads of reasons.
Maybe half of your consumers blow up. Maybe you had got a big spike of traffic. Maybe the average time to process a message has gone up. When queue size is growing, messages are probably getting delayed, workloads are probably waiting, things are probably bad. That seemed like a good place to start, and we started monitoring those metrics. That went ok for a while. We ended up with tens of queues across multiple regions, and our monitoring was getting a little bit unwieldy, so we built these Grafana dashboards that grew and grew and grew, and some of them were more usable than others might be familiar.
Metrics Limits
One thing we noticed was that all of these queues weren't created equal. There were some queues where we were fine with the delay. They were the jobs which, ultimately, they ran in the background, and a few minutes of delay, not a problem, as long as they get done. There are some queues where delays would be noticeable for users. To keep track of what was healthy and what wasn't, we added alerting to the metrics that we had, but we had to tune each one of those based on the number of consumers that we expected and how large we were happy with that queue growing. Along the way, we did add one small improvement to the default metrics that we got out of the box. We created our own metric that measured how long the message had been on the queue, so when a message was received, we'd look at when that message was sent, and we'd calculate how long has that message been on the queue, and we'd track that, too.
You might get that out of the box, but we didn't. That meant we had the high-level view at any given time of what state the queue was in. We knew if it was backing up, and we knew if it was delaying workloads. That was good, but when something did start going wrong, our alerts are firing, metrics would tell us roughly where to look, but they wouldn't tell us much more. For more detail, we had to look in our logs, and that ended up meaning a lot of manual work. We'd sometimes burn hours chasing a phantom spike, and we'd never be particularly confident about any conclusion that we really came to. In a simple system, that manual work is probably tractable, but in a distributed system with lots of interconnected parts as it grows, it can quickly become an impossible task as your product scales.
OpenTelemetry Tracing Fundamentals
Julian Wreford: This was the point where we realized we needed to probably do something different. Our metrics were giving us the big picture, but they weren't giving us a whole lot more than that. If we had to follow up on questions, we couldn't ask them in hindsight without adding in more metrics and waiting for the issue to happen again. Metrics would give us the forest, but not the trees. Equally, our logs gave us plenty of detail at the level of each component of our system, but they were hard to connect to the wider picture. They were also very hard to follow through multiple components for complex requests, so they gave us the trees without the forest. We needed something that would do a bit different and go somewhere in the middle. Of course, we aren't the only people having these problems. A whole community sprung up around the idea of observability and how to inspect, debug, and operate complex systems.
The technology most people land on is OpenTelemetry. It's an open-source protocol, which allows you to do a lot of things, but for the purpose of this talk, we're going to focus on its support for distributed tracing. Distributed tracing, you can think of it a little like structured logs. We all know what a log is, and structured logs do what they say on the tin. They let you pass not just a string, but a structured set of keys and values, which allows you to query and filter the events a bit more easily. Traces are very similar, in that they are also made of a bunch of structured events with arbitrary keys and values. What traces have over structured logs is the ability to assign a hierarchy to those events, even when the events are produced by different parts of your system. The hierarchy allows you to group all of the events that stem from a single operation or customer request.
Logging this would probably be called like a correlation ID, but it also allows you to get a sense of the cause and effect relationship between events. What was the full sequence of events that led to an error or a delay? Which systems did the request pass through before this one? Of course, it's called distributed tracing, because this hierarchy can be preserved and reconstructed, even when different components are omitting different parts of the trace.
This is what a very simple trace might look like. You have a route span, which represents some interaction with an entry point to your system. This might be a customer hitting your API, and a number of child spans, which represent the activities that the system has to do to respond to the request. These spans might represent things like database requests, calls to other systems, or specific functions developers are interested in, and have added their own telemetry for. There are two interesting things here. One is the arrows representing the hierarchy of cause and effect, and the other is the horizontal axis, which represents the time, so we can see how long each duration lasted. Each of these spans has a name, which we've written in each box, but they can also have any other arbitrary attributes attached to them for analysis or querying purposes, and we want to make those as wide as possible.
The spans are connected by three special attributes defined by the OTel standard. There's the trace ID, which means that we can associate the span with the trace it belongs to, the span ID, which uniquely identifies the span itself, and the parent ID, which identifies which span preceded this one. All spans have a parent, apart from the route, which is defined by having no parent at all. This simple association of spans allows you to build up these tree-like structures that can be paired with a query engine, which allows us to query not just across spans, but also their relationships. As I'm sure many of you all know, OpenTelemetry support has grown rapidly across our ecosystems, and for us in the world of C#, there was good support straight out of the box. It didn't take us long to start seeing the value of how lots of operations connected to form a single customer request.
We even saw the traces automatically carrying on over HTTP boundaries. The trace above shows a parent span in our data service in the U.S. data residency region, which has a child on a completely different service, on a completely different region, because it's made a HTTP call out to that service. This is a screenshot from our query engine specifically. We use Honeycomb to analyze our trace data. You'll be seeing a bunch of screenshots from it in the rest of the talk. We're big fans of Honeycomb as a product, but there are other providers that offer similar things and they'll ingest OTel in similar ways.
That was HTTP calls, but when it came to following traces through queues, things weren't quite so plug and play. In the early days, it wouldn't be uncommon for us to have to jump through three or four traces to find the full context of what was happening, and that made it really hard for us to understand the full flow of information around our systems. We were in a better position than we were with logs, because we could track a request per system, but we couldn't easily get one big picture of the request as a whole. Helpfully, this is the exact problem that OpenTelemetry was designed to deal with. It defines a standard to allow context propagation to happen, so that traces can be rebuilt from spans that are created across a number of different systems, while being language-independent. This is built into the SDKs and library in most cases, which is why it works across HTTP boundaries in the last slide.
In the case of our queues, we need a little bit of work ourselves, because the libraries we had didn't speak OTel natively. For that to work, we had to propagate two things between systems. One is the traceparent, which is a simple string which combines four different things in a hyphenated format. The version of the OpenTelemetry being used, this is just 01 for us at the moment. The trace ID, which is what the span should be a part of, so that the trace can be continued on the customer side. The parent span ID, which is the span that's active on the sending system before the message was sent. This then becomes the parent span ID of the first span on the consumer side, so that you can connect the things up. Finally, the trace flags. These are the communication of defined flags across systems. Right now, the only trace flag defined in the spec is whether a span should be recorded, and that means that you're going to find whether a whole trace should or shouldn't be recorded, and you don't get partial results.
You can sample at the top level, and that will come through all of your systems. That's the traceparent. The second part is the tracestate. This is a simple key-value list, which comes in handy in a few contexts we'll talk about later. In our case, to propagate these two things, we wrote a small middleware layer for our queuing clients on both producer and receiver sides. Before sending a message, we generate the trace context, attach it as metadata to the message, and then when we're picking that message up again, we'd pass that metadata out, plug that back into the native C# library. Jobs are good.
While we're at it in the middleware, we also added a bunch of useful attributes, which would help our system become more useful for querying. The OTel specs, just a few, like messaging.destination.name, the operation name, and the system. We also added a few of our own as well. Created, sent, and received timestamps mean that we can do calculations on the Honeycomb side to calculate the amount of time it took between the message being sent and received, meaning that we can replicate that message delay metric we talked about earlier. The subgroup ID, which we use for SQS FIFO queues, that mean we can see concurrency at the subgroup ID level and understand blockages caused by the FIFO part of the queue rather than the overall queue concurrency. Immediately after that, immediately after we put this in the middleware, we're able to see the full lifetime of requests bouncing around our system.
The image here shows three hops that we make. Right at the top, the webhook proxy enqueue service receives a POST request from the outside world. It does some simple validation of our database and pops the message onto our first queue, the webhook proxy pipeline. Then the dequeue service picks up that message and proxies it onto the pipeline service via a POST request. The pipeline service does some initial processing, and after that, puts the message onto another queue, which is then processed by a different pipeline service pod. Being able to visualize this whole operation meant we could understand the complex sequence of events that were going on in our system for any given request. Another nice outcome was that we could have a high-level visualization of the interconnectivity of all of our services. This is a simplified diagram that's based off our actual trace data. It shows the number of spans between two services, but also allows us to visualize the average latency between any given services.
One of our biggest surprises with the introduction of tracing was just how much waste it exposed in our systems. When we were able to graph every single connection between services and every single database query, we realized there were a bunch of unknowns we'd never even quantified before. For example, we looked at one of our busiest queues, one which had caused us pain for multiple years at this point, which regularly needed its capacity in peak hours. With the tooling we now had, we realized that the source for almost all of our longest-running messages was for a legacy piece of code, which we didn't really need any more. We were able to ship a small fix that removed a dependency we didn't realize we had, and suddenly that queue had ample capacity at all hours of day, and we stopped needing to worry about scaling on that side of the world.
It was shocking how much insight we gained into systems which we thought we were already the experts in. We had no idea how many unknown unknowns had been lurking in our production systems' behavior. Once the fog had lifted, we were really able to dig in and fully bottom out the edge cases and make much more informed decisions about how we wanted our systems to work.
Is My Queue Healthy?
Oli Lane: The telemetry was invaluable to help us diagnose issues when they were reported to us, but we firmly believe our aim should be to detect problems before customers notice them. We don't want to be reactive to customer issues. We want to be proactive. How do you know when a customer's experiencing pain? How do you know when it's serious enough to investigate? We'd been doing ok with our alerts based on those initial CloudWatch metrics, but now we've got all this extra trace data, how can we level up our alerting with all of that data, especially for our queues? We want to know whether a queue is healthy or not, but what healthy actually means will differ from use case to use case, like I mentioned earlier. There are loads of things you can measure. Here's a selection of the most important ones. Error rates, how many messages are successfully or unsuccessfully handled?
Processing time, how long does it take to process one message? Throughput, how many messages are being processed in a given time period? Latency, how long are we waiting on each message? Queue size. We've talked about queue size. The thing to notice here is that they're all interrelated. For example, if processing time for each message goes up, but you didn't add any extra consumers, you'd expect throughput to go down, and then you'd expect the queue size to go up. Once the queue size goes up, you'd expect that to increase the latency. It's a fairly complex but intuitive link, but there's counterintuitive links here as well. For example, if you ship a bug that causes loads of errors, you might actually see all of the other metrics improve because maybe it takes less time to process a failure than to properly run a job. There's dragons here.
What do we alert on? Error rates seem pretty obvious. We basically always want to know if suddenly all of our messages are failing to process. The rest of these are a little harder to pin down. Most queue providers make it very easy to monitor the queue size. A lot of people start with that, us included. If the queue size gets too big, something's wrong. It works, but it's got some drawbacks. Firstly, it's really hard to tune. What counts as too many messages on the queue is very context dependent. You could have a thousand items on your queue that all get processed really quickly, or you could have five that get processed really slowly. Each time your system characteristics change, for example, you acquire new customers and you scale your infrastructure and move things around a little bit, you might have to retune all of your alerts.
Secondly, it's not particularly well tied to customer experience. The customer doesn't care that there's a thousand other items in the queue. What they probably care about is when their item's going to be processed. Thinking about that probably gets us to a better thing to measure. Funnily enough, a great analogy here is Google Maps. When there's traffic on your route, Google Maps is essentially alerting you to an unhealthy queue, but notice what metric it uses to tell you how bad it is. It uses the latency. How many extra minutes is this going to add to your journey? Google probably has the data to tell you how many cars per minute are passing through that traffic jam, how many cars are waiting on that particular stretch of road, how many lanes are open. Some of those are probably interesting, but the most interesting thing is how long you're going to wait.
We switched over from alerting mainly on queue size to alerting mainly on latency, and we found that much easier to make our alerts useful but also actionable. That's for two main reasons. An alert means that a customer genuinely had a bad time. They waited longer than what we have defined as the acceptable maximum wait. Secondly, we don't have to retune that alert when the system changes, because the acceptable delay is still the same. The customer expectation is still the same. Actually, this reasoning applies to pretty much everything you're going to alert on, not just queues. Measuring something as close as possible to a real aspect of the user experience is always going to give you a more actionable alert. We've decided we're going to alert mostly on latency. The next problem we run into is that almost all of these measures are distributions. Treating them as one number by taking an average loses information.
Let's say our metric is saying the latency is 3 seconds. That could be either of these situations. It could mean that every message is delayed exactly 3 seconds, or that most are faster but some subset are much slower, or a hundred in between. Aggregating to a single number is lossy. Why does that matter? It's important to us for a few reasons. We run our services across multiple regions, but ideally, we want a single alert per queue type because the customer experience shouldn't change between regions. It shouldn't matter which region you're hitting if it has thousands of customers or hundreds of customers. Those different parts of that distribution do matter to us. We run a multi-tenant architecture, and as Julian mentioned, we use subgroups to create fairness across our queues. That means that sometimes we do expect some customers to have an extra delay if they introduce a big spike of workload.
The rest of our customers should be protected from that spike, but also, we need to keep a track of how much that fairness algorithm is affecting the customer that's put on a big spike of workload. We do care about every customer. It's not enough for us if 80% of our customers are having a great time at the expense of 20% who aren't. At the same time, we do have to be careful. Our systems are never going to be perfect and we don't really want to alert if one single customer goes one millisecond over our latency limit. We want to take into account the full distribution, but perhaps we want some soft edges to avoid noisy alerts.
How do we square the circle? We landed on service level objectives, SLOs. The good news is that we've got all of that underlying distribution data, not just an aggregate or a coarse histogram. We can build more nuance into our strategy. We could do a whole talk on SLOs, but we'll just cover the basics here and how they help us to solve that distribution problem. Essentially, the idea here is that we define a bar between this is a good event and this is a bad event. Then, we can define targets and budgets for how many good and bad events we want to see. Let's imagine we have this whole bucket of events coming through, they're all different shapes and sizes. The first thing we're going to do is to define an SLI or a service level indicator. The job of the SLI is to bucket our events into the acceptable or not acceptable buckets.
For our queuing example, we might say that a message on a particular queue is a good event if it's processed within 2 seconds and a bad event if it's taken more than 2 seconds. Easy enough. We can define that as a simple formula, and that gets calculated as our events roll in. The nice thing about working with all the data here is that we can be as simple or as complex as we want with that definition. It can be as simple as slow is bad, or it can loop in extra conditions around different customer types, different workloads. For example, if you want to define a single SLI that has different latency expectations for different types of HTTP endpoints, you can do that. If you want a different expectation on a different day of the week, you can do that for a different region, whatever. It's really flexible. Now that we've bucketed our events, we can move on to defining the actual alert.
Generally, we think of these in terms of an error budget. We've got our SLI, and we want to set our SLO, our objective. What proportion of those spans do we expect to be good? Therefore, how many can be bad before we run out of an error budget? We might decide to be really strict and expect to have 99.99% good, or we might say 95% is fine. Either way, we're able to work with our product teams to help define what good means for this customer use case, and then we can work backwards and codify that within our alerts. Once you have that budget, we can define an alert that fires when the budget's exhausted, but also, we can define an alert when there's been a shift in the burn rate that would mean the SLO would be breached in some number of hours. That allows us to be sensitive and rapidly alerted to changes in behavior, while also making sure the alert doesn't fire too much for false positives and individual spikes.
The real superpower here is how it's integrated with the rest of the trace data. Once an alert fires, we immediately have visualizations of the distribution of events, and we can go straight from that macro view into specific examples of problem traces that failed the test, and we can see if we can work out what happened. Because the system already knows what we've defined as good and bad in terms of these events, we can quickly group by that definition and see what's different about the events that are slow, or returning errors, or whatever the problem is. That's the value of having these really wide, rich events which can be aggregated in an exploratory way on the fly.
Putting it All Together
Julian Wreford: This is a little abstract so far, so let's dig into a little bit of how this all fits together in practice. Imagine it's a Friday afternoon and your head started drifting towards the pub again, when suddenly an alert comes into Slack. We're seeing queue delays and customer experience is probably affected. Immediately on each message, we're able to see what the affected queue is, what the expected queue delay is. In this case it's one of our real-time queues which we expect to be almost instant, and how long we've got until the SLO budget will expire. This puts us in a good place and means we can jump into investigation mode. Immediately we can jump in and from the SLO we can see the amount of delay each message is experiencing. We clearly had a short spike at 5:15, and one a bit after 5:30. Note that the delay is in minutes on the axis and we're aiming for sub-1 second latency, so these delays are definitely going to be starting to feel painful for our customers.
We can also see the number of concurrent spans for that queue, that is the number of messages being processed at that point by our systems. We've got a couple of flat caps at the same time as the queue delays. This is when we've hit the system capacity and so there's a backlog of messages building up on the queue because we can't handle them as fast as they're coming in. Before we start diagnosing the problem, it's worth mentioning our guiding logic which is that stable systems stay stable until something changes. When we see our system becoming unstable, we need to figure out what changed. For us that tends to be three buckets. We could have broken something, could be that we've shipped a bug which has created more messages than normal, or we've changed the dequeue side to be too slow to process the messages, or even we might have slowed down a downstream dependency somewhere else which might be a completely different bit of code entirely.
Our users could be doing something different. Either an individual user might have suddenly produced a large spike, or we may have naturally acquired enough customers that the group as a whole pushed us to our infrastructure limits at our peak time. Or a third party could be causing problems. The nature of our product means that we're quite reliant on Salesforce and GitHub and a number of different version control providers. If one of those is running slowly, we can also have a downstream effect on our ability to process workloads and some will go slower. If we start with the first one, have we broken something? In queuing systems, the two causes of delay tend to be either we've produced something significant in our workload or the consumer isn't able to keep up. First off, we can visualize the duration of the consumer spans. That's what you see on the screen here.
There's clearly a couple of outliers which look strange. This way of tracing rather than metrics becomes a superpower. We can jump into any one of those spans and understand the context of what could be going on. It's not just the exemplars. We can go and jump into every trace in that heat map. When we did that, we couldn't see anything standing out. None of the individual traces looked particularly different to normal, and they were just in the context of normal for that queue. We zoom back out again. Now we want to go and look at our producer side to see if we can spot an increase in workload from that side. To do that we need to do something called a relational query which is something that Honeycomb have started doing very recently. That means that we can query not just based on the attributes of the span itself but also based on the rest of the trace.
In this case we would write the majority of the query looking at the span itself. Then we can also reference other spans in the trace as part of the query. We can look at the parent of the span that we're querying for or the route of the span. What that means in practice is that in the relational concept we can group the concurrency by the route span's name and service. You can see here these are different services which are producing workloads onto the queue. That's really powerful because it means that we're able to visualize what's coming in from wherever it's coming in, even if the consumer doesn't actually know what its source was. You might be looking at that and saying nothing's jumping out and that's where we got to as well. Nothing's jumping out there.
That's probably on the have we broken something side. There's nothing obviously on either consumer or producer. Now we're going to look, has a customer done something? To start looking for that we can group the concurrent messages by the team idea of the message being processed. Immediately the query jumps out with something. This team represented by the blue portion has generated enough messages to consume about a third of our capacity and then spent more than 30 minutes processing a large chunk of those messages. Remember these graphs are all generated by aggregating over individual spans. We're able to ask any question we want of the data in real time. This is because ahead of time we've populated the spans with as much breadth of detail as possible, creating really wide events. The principle we tell our developers is if you think you might want it, put it on the span.
Because it comes in handy in so many times in so many ways. The surprising attributes becomes the key to diagnosing a problem that we weren't necessarily expecting. Returning to this, we can zoom in on that specific customer and ask more questions about what they were doing, and what was happening with this workload. This graph shows us filtering to that specific team and querying against a number of different attributes which help us to refine the type of workload we're processing and maybe why it's running slowly. Here we're able to see that majority of the workloads are being driven by one specific type of request. Once we've understood that the spike in concurrent workloads was being driven by one customer's one specific type of request, we're able to step back and understand what could be driving that type of request. For us, this type of request was being driven by a webhook which we were getting from a VCS which we were triggering somewhere completely elsewhere in the code and which we couldn't have realized if we couldn't zoom in and understand that it was only this type of function that we were running.
Only this type of workload that was causing the blockage in our queue. That meant that we could zoom in on the right bit of problematic code rather than looking blindly across our logs hoping to find the right thing by an off chance. Where have we got to? We've spoken about the importance of alerting based on customer experience rather than infrastructure-based metrics. We've demonstrated the value from using wide events with discovery-based query iteration to allow us to ask questions of our system in a way that static metrics just don't allow. We've seen the value in being able to jump from an aggregate graph experience to individual traces and back again as part of the discovery cycle.
Secret Sauce - Tips and Tricks Nobody Told Us
Oli Lane: All that good stuff comes from that combination of properly integrating OpenTelemetry into our systems and then diligently providing that really rich event context on every possible span and the powerful query engine. There are a few extra conundrums we've come up against as we've tried to push this to the limits. We thought you'd be interested to hear a few quick-fire extra bits we've done here and there to take the power to the next level. Firstly, tracking total trace duration. Our product teams will often come to us and ask things like, how long did this entire operation take from start to finish? Because what they care about, again, is the customer experience at the top level, not individual bits of cleverness in our services. Honeycomb has loads of great ways of querying a trace, but one thing it doesn't do natively is let you query on the total length of the trace.
That's not actually a problem if you have a trace that looks like this, which is typical for a synchronous workload. As you can see, the route span at the top actually lasts for the entire duration of the trace because it's not finishing until the whole operation returns and we close the HTTP connection and return the response. In this case, there's not a problem. You can just query on the length of that route span and you have what you need. The problem comes when you have a trace with asynchronous calls, where a short-lived HTTP request might kick off a longer piece of async work in the background. As you can see in this case, our route span returns quite quickly, but work carries on in the background. If we just query the route duration, we're missing a whole chunk of the trace as shown by the red dotted line.
When you have this kind of structure, we found you can query really easily on each individual stage of the work, but you have much less ability to query the total time a request is spent in the system. That makes it harder to track and alert on cases where that total time gets too long, but the delays evenly spread through many stages of the task and no one really jumps out.
What do we do about this? This one stumped us for a little while and we came up with a few incomplete workarounds, but in the end we realized a little trick that gave us lots of power. OpenTelemetry has the concept of that tracestate, which allows you to attach small pieces of a state and those pieces of state get carried through the whole context for the trace, along with things like the trace ID. That allows us to pass an arbitrary value through the whole trace, even across systems, and we can piggyback on all of that lovely context propagation logic that we've built or that's built into the libraries that we were talking about earlier. The insight here is that if at the start of a trace, we take the timestamp from the start of the trace and we embed it into the tracestate, then we can propagate that information across as many steps as the trace takes.
Every single span we omit, we can just pull out of the tracestate and include it on that attribute, and we have the timestamp from the start of the trace. Then, finally, we can use a calculated field to calculate the time since the start of the trace for any given span on the trace. It works pretty well. It's not perfect, but it really gives us what we wanted. Now when our product teams come and ask, when the user presses this button, how long does the whole operation take? We can give them a definitive answer and a visualization across the whole of our customer base or just a subset of our customers. This graph is a heat map. It's across all of our customers showing the amount of time it takes for a particular operation to go from start to end. Just like before, we can slice and dice this in many different ways to be able to understand why some jobs took 40 minutes and others took 3.
It's worth saying here that our product teams often use other more product focused tools such as amplitude to measure customer usage. Being able to produce a similar view in OTel means that we can really marry up those two views of the world and let engineers investigate the technical details starting from a consistent view of the world. It means we can each use the best tool for the job that we need to do, but link between them to enable that seamless collaboration.
Julian Wreford: Another thing that took us a little while to realize was the power of the OpenTelemetry Collector. This is a self-contained component shipped as part of the OTel project, which helps us to collect, process, and export OTel data. We started off shipping data straight from each of our components to the querying backend, thinking that it would be one less moving part. Actually, once we did install the collector, we saw some immediate benefits. The real power of the collector is in its configurability. It has a reliable core, but then a huge array of plug-and-play components, which you can very easily plug into your telemetry pipeline. It can ingest almost any type of telemetry you can think of, transform it, and emit it as OTel or any other format you're choosing. The really powerful part of this is that you can fuse disparate telemetry signals and integrate them into the telemetry coming out of your main components.
For example, we have our collector set up to collect various information about the Kubernetes pods the telemetry is coming out of, such as pod names, image versions, IP addresses, and a whole host of other useful pieces of metadata that means we can correlate when we're doing the querying. This data is then attached to all of the trace data that our components generate, without any of our components having to collect and attach those attributes themselves. You can also arbitrarily transform the data coming through or filter it. We found this really useful for adding an extra redundant layer of defense that scans for any data we never want to see in our telemetry, such as tokens and secrets, and for sending subsets of our telemetry data to different backends for different purposes. For example, some of our workloads now make use of LLMs, and we were able to segregate the telemetry and send it to a different backend because it's useful to analyze it in different ways.
Having one place where we can make these changes rather than updating each of our components separately is absolutely fantastic for our workflows. Finally, from a security perspective, the collector can deal with things like API keys for your observability backend, batching, retries, leaving all of that complexity out of your components. We saw a real uptick in the reliability from offloading this job to the collectors rather than trying to do it in the components themselves.
Thirdly, on our tips and tricks, is another problem we came up against, which is, it turns out some of our traces are humongous, like so ridiculously big they can't really just be looked at manually. Some of our workloads are very large. Some of our longest jobs take days in duration and generate hundreds of thousands of spans. It's all very well generating beautifully connected traces that you can scroll through. If they're too large to work with, everything just becomes unwieldy again. You're back to square one. We did some work to optimize these traces and make sure we're actually omitting things that were useful. Ultimately, at some point, we realized that most of these spans were useful to understand it if we could have it in the right shape. We made use of a different feature that was part of OpenTelemetry, which is span links. Essentially, these are hyperlinks between spans, and they can cross traces.
Honeycomb renders them a bit like this. What we did was that we identified useful subtrees within the wider days-long job and split them up into multiple different traces. In the route trace, we had a single span that represents the whole subtask. Then there's a link to see the trace that represents what that subtask is. Then we can jump back in the opposite direction as well. In effect, it lets us zoom in and zoom out at the trace level, meaning that we have a high-level view of how well the operation took. Then we can jump into different chunks of the operation, even if it has thousands of spans that we need to look at and understand. This ended up working really well for us. It lets us tune out the noise when all we need is the high-level structure, while also being able to dive into the real nitty-gritty detail when we need that as well.
Oli Lane: Something else we've run up against when we've tried to drive adoption across our teams is, how can I jump between all of these tools we now have? Although we've got a lot of gains from pulling all of our observability into OpenTelemetry and Honeycomb, that doesn't mean our other tools went away. We still have logs. We still have time series metrics in Grafana. We still have separate error reporting. We still have some homegrown tools for inspecting product-specific data in a few places. In an ideal world, perhaps, everything would be on a single pane of glass, but in reality, different tools do a better job with different types of data, and different teams also have different requirements from that data that they need to work with. One thing we've really tried to do is link up those disparate data sources. For example, we added the current trace ID to all of our logs in place of a correlation ID.
Then we added links in both directions so that we can quickly switch between views of a trace and views of all the logs generated during that trace, even though we'd use different providers to store those telemetry signals. On the OTel side, that just required generating a hyperlink to attach to each span. In the other direction, it actually required us to write a little browser extension to inject a link into the log UI. We have similar affordances for jumping straight from a trace to the Grafana dashboard for the resources being used by the particular Kubernetes pod we're running on. Lots of other little examples like that where putting in a little bit of work upfront to reduce those frictions has really paid off in terms of the developer experience much more than you might have expected.
Meeting Teams Where They're At
That leads into my final point here. We built and integrated all this telemetry as a team. We knew the value that it brought in trying to debug production instance and keep track of our systems day-to-day. In getting other teams to adopt it, we had to meet them where they were at. We didn't come in and say that tracing was this panacea that solves all of your problems. Instead, we worked with them to make it as easy as possible to integrate their existing workflows with this new tech. We ran workshops. We found out their pain points, and we tried to address them. We made sure that when we saw people struggling with something that we thought our new tools could solve, we jumped in and showed them how they could save some time. We also made sure to spread good ideas between team to team, because lots of the teams thought of use cases that we would never have considered.
A lot of this felt like an endless task. People really like their comfort zones. Once folks started to see the value, then they started doing the work and they started adding more attributes, more spans, more data, and that flywheel got stronger and stronger, which got more people to see the value. Soon, most teams were using tracing as their primary source of debugging.
Takeaways
What should you take away from this talk? If you aren't using distributed tracing yet, why not? It's a game changer. It will change how you understand and maintain your service, especially in a distributed systems context. Secondly, when you're designing alerts, remember you're measuring a distribution, so you should alert on that whole distribution. When we talk about alerting, we want to be measuring as accurately as possible the actual user experience and not some internal metric or internal service. Then, finally, just an encouragement that making changes like these are as much a cultural problem as a technical problem. Demonstrating the value to those teams across your business is the best way to build buy-in and get those teams invested in supporting their services and build that flywheel.
Questions and Answers
Participant 1: I was intrigued, especially as I'm working in C# as well, which I think you mentioned that you were, when you were talking about what you actually had to do to get that trace in across your queues, have you built something custom or are you using what's come out of the box with OTel there?
Julian Wreford: For the queuing side, we've used the OTel specification, and the actual middleware we've put into our queuing layer is really quite small. It's like 100 lines. It's like add a couple of extra attributes to every message, read out those attributes on the other end, and that's where the magic is there. It wasn't super complex to do per instance, but we just needed to do it for each one so that our teams got that out of the box so they knew that it was there. For HTTP, it's already there and we're starting to see some queue providers start writing some of that, but the OTel native hasn't come to a bunch of queue providers quite yet.
Participant 2: Are you storing all your traces? If so, how long are you storing the traces? How many weeks are that?
Oli Lane: We have 60 days of retention, and we actually store almost all of our traces. There is a very good reason for that, and that is that we have a lot of very long-running traces and we really do care about almost all of them, which is unfortunate. You can do clever tail sampling. It's called tail sampling where you make a decision at the end of the trace whether this is a trace that you want to keep or not. We find it really hard to do that because our traces are so long, because you might have to wait four hours to even decide whether to send any of the trace data, and so then all of your telemetry is four hours behind and that's not really very useful. If you have much shorter traces, you can do much more intelligent sampling. For us, it's still a little bit difficult, so I think that's one place where we think OpenTelemetry has a bit of room to grow, but our workaround is just spend a bit more money because it's worth it for us.
See more presentations with transcripts
