Cloud Native Computing Foundation KubeCon + CloudNativeCon North America 2021, 30 Oct 2021

Previous Meeting Next Meeting

⏯

youtube image

►

From YouTube: Correlating Signals in Opentelemetry: Benefits, Stories, and the Road... Morgan McLean & Jaana Dogan

Description

Don’t miss out! Join us at our next event: KubeCon + CloudNativeCon Europe 2022 in Valencia, Spain from May 17-20. Learn more at https://kubecon.io The conference features presentations from developers and end users of Kubernetes, Prometheus, Envoy, and all of the other CNCF-hosted projects.

Correlating Signals in Opentelemetry: Benefits, Stories, and the Road Ahead - Morgan McLean, Splunk & Jaana Dogan, Amazon

OpenTelemetry is used across the industry to capture distributed traces, however this is just a sliver of the value that the project provides. OpenTelemetry also gathers metrics (launched earlier this year) and logs (beta) from your applications and infrastructure, allowing you to capture all telemetry through a single pipeline and powerful analysis in whatever tools you choose! In this session we will discuss: - How OpenTelemetry correlates these signals, which allows your investigations to jump flow seamlessly between all of your services and underlying infrastructure - The deep functionality that OpenTelemetry provides for metrics and logs, including metric formats and aggregations, tailing logs from flat files, and the a high-performance strongly-typed logging pipeline for new applications - Real stories about how large well-known organizations use OpenTelemetry and the improvements that they’ve gained - What’s next for OpenTelemetry: new data sources, signals, and more

A

Hi, everyone welcome to our talk about correlating signals in open telemetry. My name is morgan mclean, I'm a director of product management at splunk. Specifically, I work on splunk observability cloud, I'm also one of the co-founders of open telemetry.

B

Hi, I'm jana dogen, I'm a principal engineer at aws and I'm working on containers and observability.

A

So we're going to assume that this is a more advanced talk for people who are fairly familiar with open telemetry for those who aren't I'll, give you a quick one-minute rundown, so open telemetry is a set of tools, uh protocols and other components that you can use on your services and on your infrastructure to capture machine generated or custom data from them, and you can then send that information to a back end for processing.

A

There's a number of different backend supported. It's a big multi-vendor industry project. So there's a number of different places. You can send that information, but specifically open telemetry includes the following: a collector which can be deployed as an agent on a host or as a network service that will capture data from any host operating system.

A

If one is present and can also capture data from other sources, both sources from open telemetry like the sdks and agents that I'll describe in a second it can also capture information from prometheus endpoints and zip code generators and various other locations.

A

Next open telemetry also includes sdks and language automatic, instrumentation agents. These are designed to capture signals like distributed traces and metrics from your application, whereas the collector, in addition to collecting these, also captures those host, metrics and host uh host logs that I described earlier. Open telemetry also includes a protocol that defines these different data types and allows them to be transmitted from different, open, telemetry components to each other or indeed, even to back ends that support the native, open, telemetry protocol and finally, open telemetry has a specification and semantic conventions for various use cases.

A

So open telemetry is fairly well opinionated, which means that if you want to say capture a trace or metric of http traffic, open telemetry is standard conventions for how to do that. This means that then, when you process that data, no matter how it was captured, as long as it was through open telemetry, the data will be consistent and correlatable with other pieces of information, which is a big part of our topic. Today, specifically opensummary captures distributed traces. That was the first data type that we started.

A

The project with that's now considered ga across almost every single component of the project, something we're really proud of open telemetry also captures metrics. uh In most cases, this is already beta, hopefully much of it, or some of it will be ga by the time that you're watching this we're recording this video a bit in advance of of kubecon, but there's a possibility. It's still in in beta at that time and finally, we have logs logs are in alpha effectively.

A

um I realized that I mistakenly wrote on the description of this session that they're in beta they're, not uh they're in alpha, uh ideally they'll, be beta early mid next year, uh but we're still working hard at those just because logs were only added to the project later on and finally open telemetry also captures resource metadata. So in summary, it captures everything that you need from your applications and provides the components to do so.

A

So I mentioned this in advanced session and I mentioned open telemetry and perhaps even ourselves are fairly opinionated about these things um and one of the sort of big benefits of open telemetry is the correlations between these types of data that it pulls in certainly capturing metrics from an application or infrastructure or capturing logs is not new. That's been done for many years very successfully in many cases, but whenever you capture these types of information as silo, you are completely setting yourself up for failure.

A

You know this is a scheme that may have worked in the past, where you can capture and process logs over here and metrics over here, and maybe, if you're doing traces, capture and process them over here, but there's so much value to be unlocked as service owners and service operators. By actually correlating this information, open telemetry allows you to do this in a way that realistically wasn't really possible before and we're going to give you some examples to demonstrate why this is powerful right.

A

This isn't just morgan and jana, telling you about theory, and wouldn't it be interesting if, if you could correlate this information, no, this is a thing that really large organizations do very successfully in production today of open telemetry and we're really excited to talk about how you can improve your own organization and improve your own responses to outages and other challenges by performing these correlations uh and and the the sort of succinct reason.

A

Why is that, if you have a highly distributed system, something with say like 100, different services or even larger, a failure that happens 10 levels down, the stack is going to manifest itself in very, very strange ways at the top of the stack ways that if you were only analyzing with logs or only with metrics or even using both but using them in isolation or even with just traces, you really won't be able to understand what is going on or it will take you a long time to do so.

A

You can also use these correlations to gain more general production insights about how your services work, which will speed up your development velocity.

A

So, as I mentioned, we're going to dive straight into examples, and so the first one we have uh is a mock e-commerce service for this demo, I'm actually using the services included in google's hipster shop demo and we've we've analyzed and visualized these in the tool and I'm going to walk you through, where the correlations drive its value and where the pitfalls would be if we don't perform any of these correlations.

A

So in this example, we have customers experiencing extremely high latency with certain actions in this ecommerce service. Specifically, as you can see here, the checkout service is incredibly slow. It's about 8.4 seconds is the like 90th percentile latency, which is ridiculously bad, particularly for a checkout action. E-Commerce at 8.4 8.4 seconds you're going to have customers who order things and close the window, then not realizing. The transaction went through you're going to have customers who have completely lost their faith in your e-commerce system. This is terrible, terrible terrible.

A

It's the worst possible time for it to happen in the stack already.

A

You can see that we're using some of these correlations to produce this visualization here, and so what we've done is just stack up all the different distributed traces as well as the service information and we've used that to build this service topology map, and so this map, that's based on all these aggregated traces, allows us to step a couple levels down into the stack of services and from here we can already start to form a few hypotheses about why the checkout service might be slow.

A

We can see that we've got about half a second of latency from the checkout service, to the cart service and to the payment service. Both of those alone by the way are probably unacceptable. That's really really high latency, but that doesn't add up to the 8.4 seconds that so many of our customers are experiencing.

A

So, there's still something going on here that we can't quite explain so we're going to take one step in and we're going to filter this information down to just show the service to service latency metrics for the front end card operation already we're on something that you can't do without these data correlations.

A

um These metrics here are from actual metrics captured between these services, but we've filtered them down for an operation that occurred between the front end service and the checkout service.

A

So when I look at the latency for say the cart service to the redis database, underneath it, this isn't all of those interactions, we're not just looking at the average latency there we're only looking at the latency that was as sort of a child event of a front-end to checkout uh event that took place and so already we're taking a correlation, uh we're doing a correlation between a metric and data from a distributed trace. That was actually keyed in several levels of the stack up.

A

So this is a quite a complicated correlation, we're performing, but because we're using open telemetry and it propagates that information all the way down to metrics. We can perform it on our back end very very easily, so we've done we've done this and we're we we've also added in some external client latency. The external client latency isn't uh super relevant here, but from the front end service to the checkout service and the payment service and the cart service.

A

We can see that the the 90th percentile latency, compared to what we saw before is roughly consistent, obviously front end to checkout has gone down a bit, but we're still seeing about half a second to the payment service in the cart service and that still doesn't really account for what's going on inside of the the checkout service, then, additionally, though, we can start to perform a few hypotheses, or at least we can, we can continue them. We do see. There are a lot of errors in the payment service. That's interesting. What's probably more interesting.

A

Is that those errors that are happening? That's what the red indicates are not bubbling up to our clients uh via the front-end service. That is interesting that it's not actually correlated with the latency, but we're going to need to dig in even further to find out what's going on here.

A

So one of the other correlations we can perform is correlating a services application metrics with the metrics uh and and logs and other information that are coming back from the underlying host and so using open telemetry we've we've now pulled up uh cpu usage and memory usage and disk usage and network usage from the exact hosts that are running our payment service that is so slow and from here you know we can't draw any conclusions about the cause of our error, but we can at least rule a few things out.

A

We can see our cpu usage is fairly steady across these hosts between zero and fifty percent. That's probably nothing to be too concerned about memory. Usage appears to be around forty percent again, nothing to be particularly concerned about, and so through this correlation, we can uh immediately then rule out the uh any kind of host performance issue impacting our application, and if the issue had been here, we would have used this correlation to solve this problem.

A

Again, we needed to use correlations between different data types and open telemetry to even get this far in our investigation and to rule this out. So I filtered down the graph a little more about the different interactions between these services, and so we've just isolated this to the the ones we're really interested. In and again, we have a hypothesis that the payment service is being slowed down, so the checkout service rather is being slowed down by the payment service.

A

In the cart service, though, this certainly doesn't account for all of our latency, and indeed we can already perform a hypothesis into the cause of slowness of the cart service at 672 milliseconds to the postgres database. That's something we should be targeting, so it doesn't account for the massive latency that our customers are experiencing, but even once we fix that 672 milliseconds, uh 99th percentile latency to a particular database is unacceptable and needs to be fixed in this investigation.

A

We would certainly file a ticket for that, but now we're going to proceed with our investigation even further. Now, to get further in this, we really need to understand what's happening in these individual requests, and so what we're going to do is dive into some of the distributed traces that were used to generate this topology map. Technically, this isn't a correlation, because the topology map itself is generated from the trace data, but we're going to use further correlations from these traces to drive our analysis further.

A

So here's an example of one of these traces and we can now quickly start to see what was going on so when a customer calls from their browser to the checkout endpoint, there's a number of very short client interactions that take place nothing to be too worried about here, but we can see these errors on these requests between the checkout service and the payment service.

A

These are the errors that we saw in the topology graph earlier, the ones that we noted were not bubbling up to our clients, and now we can see why it appears that when the checkout service calls the payment service, it throws an error after a little bit of processing, and then the checkout service basically repeats this operation until it succeeds. This is why the errors are not making to the client, because we're continually repeating these calls until they succeed.

A

It's also the major source of our latency right and because, because these calls well individually or small, are being repeated with this six times or possibly more in other examples, that's causing the entire interaction to be slow, and so from these different correlations, we've driven ourselves both to application metrics to rule out a possible cause of this high latency, but from the distributed trace, we can see the air that there's effectively errors that are causing the high latency, and indeed, we can actually from this trace, because we've done the work to correlate these with logs, we can actually go and inspect the individual logs for this trace.

A

We could also perform this in aggregate if we wanted for a particular service, but because we already traced we're interested in I've now jumped using direct correlations because we stamped the trace and spanie into these logs to all of the logs that were generated as a result of this single customer interaction that was slow and we've seen some logs that have been flagged as errors.

A

Indeed, that's how we were flagging errors earlier on, and we can see that we failed payment processing through this payment api due to an invalid api token, and so from here we can form our conclusion about what happened. The service is slow, because the payment service is effectively repeating these operations, because one or more instances of the payment service have an invalid api token. Clearly, some of the instances have the correct api token.

A

Otherwise these requests would never succeed at all, but we can now identify our main cause of latency, with the secondary cause being that very slow database that we identified earlier the postgres database, so I've already talked a bit about how we did this uh while presenting it, but I'll talk about it more. So, to perform this scenario this example, we had to correlate application metrics with our services.

A

We had to correlate our host metrics with our services that in open telemetry just requires keying in a service name typically into the open telemetry collector for every instance of a service that's running on a particular host. We can immediately then correlate this information, regardless of whatever backend you're using next. We need to propagate request data all the way down the stack so that we can correlate it with metrics further down open telemetry provides the tools that you need to do this, and these are techniques that have been.

A

You know, honed and perfected at many sort of large internet companies uh over the years, if only so that they could um reduce things like disk hot spots. If, if similar queries are hitting the same disk spindles in their data centers and perform other operations where they need to do performance, optimizations now with open telemetry, you can actually do this yourself and finally, we also correlated logs of traces and services. This is a little more straightforward.

A

This just involves stamping, trace and span ids into your logs and also stamping a service name into your logs, so you can filter those later with open telemetry. This was always already.

A

This becomes fairly simple and straightforward, which is something it hasn't been before, and it really unlocks this power for you for the back ends that support it or, if you're, using open source backends, where you can add your own analytics or programming to them. This uh open telemetry really opens a lot of doors for you, because of this, uh and and uh like I said this is all done directly with the open telemetry sdk is in collector. I described that before, but for those of you following along who want to pause the presentation.

A

This describes with a little more detail where to make these changes.

A

So yana has another example for you so janet. Do you want to pick this up.

B

Yeah sure, um as morgan's experience like we have, you know a lot of like difficulties when it comes to navigating data and like understanding actually like where we can use the telemetry data. For uh one example is this: like once we have the service that was causing latency, but you know when we look at in the traces or logs we didn't see anything particularly new.

B

We had some elevated cpu usage from the nodes breaking down the cpu usage in our monitoring dashboards reveals that a particular service. In that case it was a simulations engine was impacted. uh We haven't seen any other services in that cluster being impacted, so we kind of like decided to focus on that service. um We, as I mentioned that, like you, know, searching for traces and logs involving that service revealed nothing new. uh We saw some, maybe slight, you know increase in the rpcs, but you know nothing particularly wrong with the you know.

B

The um networking, or you know, retries or like there's, been nothing quite new, so this made us like start to think what else might be out there in terms of telemetry data. We are collecting when we're talking about like correlations. We sometimes talk too much about like metrics, traces and logs and like that you know three type of signals, but we actually collect a lot more um and when um you can collect all these like additional, you know signals telemetries, uh telemetry types with you know correlations. You can actually start utilizing them.

B

We realize that you know in our crash dump storage. um There is, like you know, crash dumps related to the nodes um where this problem was originated at so we started to take a look at the crash dumps. We started to realize that, like actually a server was the simulations engine was crashing after a particular rpc. So for each incoming request comes in uh this, you know, service was sort of like crashing and then it was causing. You know, scheduler to reschedule it and like in a fork, a new process.

B

It was causing this like cold start um and since you know the it was adding a little bit latency, because this rpc was already a kind of like an expensive call. So we couldn't really quite see from the you know the latency dashboards that, like you know, there was uh additional latency and it didn't really alert because it was still reasonable uh for us.

B

But then uh taking a look at you know the debugging like taking a look at the codes locally debugging it uh made us realize that, like oh actual service was crashing because of uh some sort of like you know, misusage of a device each time that request is being handled which caused all this, like, you know, rescheduling reforking of the process, additional latency and some additional cost. um So it was not quite possible to see it from everything else.

B

But you know: we've been quickly been able to navigate the data and rule out some of the you know. The hypothesis we had and we've been able to focus on the right type of telemetry to be able to you know, gather actually like what actually has been going on. So um we've been able to, you know, fix the issue. um Pushed a new release and we've been able to you know, fix the uh improve the impact uh very fastly.

B

The other example I want to give is like very similar.

B

um It is still not quite in a case where you wouldn't be able to gather too much by just looking at the data itself, like correlations made it much much easier for us to be able to rule out uh in this case that um a service was, you know, beginning to experience some latency in elevated cpu usage, so we, you know, make releases once a while, sometimes there's a large number of changes going in the same release when I think it's small, it's easier for us to be able to roll back and we use rollbacks all the time.

B

You know we have like automated pipelines. If something goes wrong, just rolling back is so easy. We trigger a roll back and you know just try to figure out what's going on, but since this was in a cannery and we were trying to figure out what was going on, we decided to take a look at like the data coming in. So um first thing that we looked at was like hey. Is there any other service in the same cluster impacted the same way?

B

If you know there's something related to the cluster or there's something related to the nodes in that cluster, it might be, you know revealing, but we've seen like nothing else other than the service being impacted. um We, you know very naturally started to take a look at the traces and logs to see. If we can capture anything- and uh we see you know, we saw no like retries or any issues with the outbound requests.

B

So you know we've been able to rule out that, like it's not related to networking, which is most of the time actually like the cause of the problems that we have um so uh we've been able to. You know just rule them out very very quickly in in a couple of minutes, and then um we decided to take a look at the diffs like what actually went into the new release, because that might kind of like sometimes give us um some ideas uh in the source code. There hasn't been like much.

B

You know, differences in terms of um one particular case that we we've been curious about. There is there's a new uh library dependency that we, you know on boarded a couple of you know days ago, which included a new version of a compression library. So we we were kind of like curious that maybe that's that's sort of the case and uh we decided to enable um the profiling on the cannery and being able to retrieve some profiles.

B

So just because we can collect profiles per our pc by labeling them.

B

It was easy to like make the correlation between you know the the latency and, like the the specific we've been able to you, know, break down the profiles coming originated at a particular rpc to be able to verify that, like cpu is actually elevated for that particular rpc and um reading the code again like the rpc handler revealed that, like you know, there's nothing has been going on in that particular rpc handler, but the new compression library was causing slightly more cpu usage, which was impacting our service.

B

So you know the service was like actually causing. You know some 50 percent, more cpu usage was very cp incentive.

B

Intensive to to the point that, like not rolling back, would be a capacity problem for us in the future, so we decided to roll back and we decided to uh bring back the old version and try to mitigate the performance regression in the new um library. So a couple of years ago, like in the this, is very interesting because you know we when we think about like telemetry and correlations between telemetry. We are sometimes restricted in ourselves, but I think it's it's much broader than what we think about them.

B

Right now, one example: I gave an example from the profiles, but the other example is, you know: runtime execution tracers in go. 1.1 we've been working on this interesting thing where you can actually get runtime traces. A content by you know your custom labels, so you can do like correlations between your distributed traces, and you know your runtime events in this particular case that you know we have a simple hello world uh grpc uh server and you can see how much time is spent on execution.

B

How much time is you know, spent in network uh system calls like you know, block-ins uh calls and other scheduler and so on. It requires some, maybe instrumentation, but you get this type of like level of insights, and you know there are more and more tools and like language, runtimes and everyone else is interested in. You know building these correlations because they are very useful.

B

So to recap we talked about like morgan, and I talked you know briefly mentioned a couple of different correlations. uh To recap, we talked about correlations among metrics, logs and traces and other telometer types such as you know we mentioned about like some uh crash dumps or profiles, or you know execution tracers way to build correlations. Is the resource inferences, so you can easily query.

B

You know what um give me all the data from this particular virtual machine or give me all the data for this particular kubernetes, name, space and pod to be able to you know, focus and navigate. The other um area is, is the custom annotations that you have like? They can be local or, as morgan mentioned, they could be propagated. If you have downstream services like storage systems, it's super useful to sometimes produce some of these annotations in the upstream services propagate them all the way down.

B

So the telemetry can be collected by applying those annotations, and you know in your dashboards or querying systems. You can, you know, take a look at the data breakdown by you know upstream services, services usage, so it kind of gives you an easier way to understand, like what is the impact of my you know, upstream service on these storage systems or any other like downstream service.

B

So you know correlations are just so helpful to make the navigation of the data you know just becoming more easily easier, but also they are so useful to be able to rule out. You know what is a non-issue we've been able to quickly say like hey, you know some something is wrong here, but it's not about networking. It's not about like this particular like cluster uh we've been able to. You know like see the same data from different perspectives. To be able to.

B

You know just rule out uh non-issues very quickly, so we have a bunch of like interesting things actually coming in is featuring their endeavors, and I want to return back to morrigan. So morgan can give us um what's coming up next yeah.

A

Thanks jana, um so there's a number of new things coming in this space. Probably one of the next that will come in open, telemetry eventually would be. Profiles like ianna was talking about the go profiling tools and there's certainly a number of of distributed profiling tools that become quite popular in the last few years, and so I would anticipate eventually profiling will become another data type with an open telemetry alongside trace's, metrics and logs. I don't think we're going to jump on this immediately.

A

We need to finish our work on metrics and also finish our work on logs. I think, before we sort of risk spreading the project too thin by bringing in other data types, but it does seem like a natural next step to me as someone who's inside of the community, and it would be great to bring this in because of profiles.

A

Of course, you can correlate performance information on the same host or even on different hosts all the way down to code via traces and metrics and logs that are correlated with those profiles, so it'd be very, very powerful and would honestly lead to. I think, like the next generation of sort of development, analysis tools, which would be really neat um also perhaps things that could come to open, plum tree would be native support for core dumps uh crashes and exception.

A

Call stacks, uh you know call stacks would would be somewhat duplicative of profiles perhaps, but I think there's a lot that we could do there with those uh something that's coming in right now is is open. Telemetry is gaining support for ebpf instrumentation, with a focus initially at least on capturing network information, and so that should open up a number of possibilities of also correlating uh core sort of kernel. Network data and network request response data.

A

Things like dns queries, even possibly like dhcp, with specific requests that are part of an application, and so one imagines you could have a visualization of say a distributed trace or if a span is taking a long, a large amount of time and with extra annotations or visualizations, or something on that span that show how much of this was the application being slow versus? How much was the network being slow or even different sort of network handshakes or network events?

A

That may have impacted that uh and finally, as yana alluded to correlations with language, uh runtime traces would also be really really powerful and so that wraps up our presentation and and description of different scenarios today uh this is a topic we're super excited. I know a number of people in the community are super excited to discuss uh again.

A

I think my biggest takeaway for everyone else from this is various tools in the industry already take advantage of the correlations that open, telemetry provides, and indeed much of this work was pioneered at various large internet companies over the last you know decade where they're performing this internally open telemetry makes us available to everyone in a very easy way and, as all of our own services grow more and more distributed, and as we break out functionality across more and more of these services that are interconnected.

A

If you don't rely on these correlations, you are setting yourself up for failure. Honestly, um we are. We we deal with more and more layers of abstraction every year. Certainly, projects like open telemetry provide the performance data. We need to make sense of those layers of abstraction, but that's only so valuable until we actually perform and use these correlations for analysis, as we showed you in our examples today. So thank you again very much. um We hope you got a lot out of this session uh and have a great day.