From Symptom to Root Cause: Tracking Issues with io.Insights Traces

Hello, everyone, and thank you for joining. I'm Martin, the product manager overseeing the io.Insights product, and I'm delighted to welcome you to our second webinar in this four-part series that we have created. We created this series to give you a deeper look at how our io.Insights product can fit into your observability system, along with some practical ideas for getting started, applying it to a variety of use cases that you may have. In today's session, our engineering lead, Velko, will dive into one of the most complex OTel signals, at least for me, and that is traces. He will show you how you can use them to break down whole processes and pinpoint specific issues with them. So with that, please welcome Velko Nikolov. Velko. Thank you, Martin. Hi, everyone. As Martin said, I'm Velko from interop.io and I'm the project lead for io.Insights, which is the observability layer of io.Connect. And since this session is tracking issues with traces, I'm going to talk to you about the tracing capabilities of io.Insights and show you how traces can give you a much more powerful view into your io.Connect system than you have today. Feel free to put your questions in the chat as we go along. We'll answer them at the end. Also, we will share this presentation with the interactive demos included after the webinar so you can play with the data and the examples yourselves. As you know, this is the second of four sessions. Martin gave a product overview, and then there will be another session on building the final dashboards up and running. And finally, in December, there will be a deep dive with some of the more advanced features of io.Insights. And today, we'll talk about what traces are, what you get out of the box and how you can use them to find the cause of various performance problems and errors, and to talk a little about custom implementations as well. So let's begin by talking a little about what traces are and how they relate to other kinds of telemetry. The goal is to build an awareness of what use cases each kind of observability is suited for, how they work together, what we can expect in tracing. So the three pillars of observability are metrics, logs, and traces. You're already familiar with metrics and logs. Metrics are numerical statistics and logs are timelines of events. And together, they give you, on one hand, a very broad and on the other hand, a very deep view into your system. Metrics are the basis of dashboards and alerts, and they give you an overview of your users' applications so you can measure their performance and detect issues. But mostly, they tell you that something happened and how often it happened, not why it happened. In order to actually understand the reason for what's happening, you often need to use more targeted tools. And, historically, this mostly meant logs, user reports, and screen-share sessions where users tried to reproduce the issues they were having. However, each of these has its issues. Logs are hard to work with and to debug. User reports are incomplete and often misleading, and screen shares are just painful and time-consuming for everyone. This is the reason why traces exist, and it's why io.Insights provides tracing, which is, to put it shortly, a distributed, structured causal log that makes diagnostics quicker and simpler. So what are traces, actually? A trace is a sequence of events that is recorded by applications that include the logical connections between them. We can follow the whole flow of operations one after the other across applications and machines. Let's look at one in more detail. In this scenario that we have visualized, we have two applications that are talking to each other, with the first one invoking an interop method registered by the second. The second application responds by invoking two methods registered by the first application with the second invocation following an error. It's a little contrived, but it's a simple way to show a multi-step workflow without introducing several at once. And here's what it looks like in detail. This is what is known as the waterfall view, which shows events as they happen over time. And we have two applications in two different colors, and each line is one recorded operation. And each operation is known as a span. We start with the user action, which is the click on a button, followed by the first application making an interop call, which is handled by the second application here, and the two calls it makes in return, one of which has an error, and the error message is recorded there. So this waterfall view shows the trace as a tree of events, but we can also represent this as a time sequence diagram, which gives you more interaction based view. So each swim lane here represents one entity. For example, this is the user that clicks the button and kicks off the whole process. The two applications, and you can see who called whom, when, and how the error was reached. You can see how clear all the relationships are when the structure of the operations is actually part of the observability data. And you can imagine how much harder it would be to reconstruct this whole scenario starting from a user report, then working through the logs of the two applications and trying to reconstruct the context of the error and how the user got there. Traces are meant to save you from that. Since each application records its own part in the flow, the backend combines the pieces into one whole tree automatically. Traces also contain metadata. Each operation span has a name, parent, a timestamp, a duration, and the so-called attributes, which are key-value pairs, which describe the operation in detail. This makes querying and correlating easier and also just analyzing the issue because you have any required information recorded as part of the case. You can even use these attributes to derive metrics and build dashboards based on this information. So, for example, you can build the dashboard. It counts how many times an operation occurred, how often it caused an error, and how long it took. Traces can also be correlated to logs, so you can use the structured trace to find when or where something happened. Then you can drill down into the respective log to get more information. And in the other direction, they can also be correlated to metrics. So you can have a metric dashboard, and you can see an interesting sample. For example, a spike, and you can drill from the metric into the trace that was being recorded when this sample was taken. So the trace with the operation that was interesting. This gives us an integrated framework for monitoring and analyzing systems where traces, logs, and metrics work together. And this is why traces are the third pillar of observability and why they are the newest addition to io.Insights and why we hope they can improve your support workflow and the analysis of your systems and operations, freeing you from having to dig through logs or schedule screen shares with users hoping that they can reproduce the issues that they have. A few quick words about the io.Insights implementation of traces. Like the rest of io.Insights, traces are implemented using OpenTelemetry, also known as OTel, which means it can integrate all sorts of backend systems as well as other applications that publish telemetry. In addition to that, we also bring many features to your applications. First of all, the so called propagation, which is the sharing of causal relationships between spans. As you saw, traces maintain the relationship of what happened before and what happened after. So this information is recorded automatically between your io.Connect applications and this is called propagation. So io.Insights performs the propagation between your applications transparently as soon as they call an API. The calling point is recorded, and you don't need to do anything in order to have a full view of the cooperation. We also ship a lot of instrumentations out of the box, all sorts of APIs. For example, the interop API, the context API, the startup of the platform of the workspaces, and so on. We also have instrumentations for what applications are doing inside the code, such as web requests, fetching resources, opening WebSockets, handlers, performance, and several others together with clickstream user journeys so you can see what the user was doing during their session. So this means that you can start getting useful information without needing to do anything other than just enabling io.Insights. We also give you a powerful configuration that controls what gets recorded and how, and an API for adding your own instrumentation, which will also get correlated automatically with the instrumentation that comes out of the box. So here's an example for more involved trace between multiple applications just to get a better feel for how trace will be before we start analyzing them. This example is called one click, four processes. And it's an application that calls another frontend app, which calls the backend service and puts the result into shared context that a third application is watching. The root of the trace is the user's click in the clickstream trace of the client portfolio application. And the element that was clicked is recorded here. The application's wall data button, and we have the moment that it happened. And everything that happens afterward is recorded as a span underneath the span. So the button click causes an interop method to be invoked, which is called position.get, which is handled by another application that is the position service application, which makes a fetch request, and the backend service traces its own operations, which are verifying the authentication token, looking up in the cache, then querying the database, and finally sending your data back. Then the original application, which has received the data, proceeds to put it into a context with core portfolio positions, which receives 186 kilobytes and has three keys. And then the update is delivered to another application, which is the other entry app that finally does another fetch request. Then the interaction between the four processes is visible immediately, with timing and semantic data. Looking at it as time sequence diagram, it's also pretty easy to see who talked to whom. One line per process and one arrow between them for each interaction. If If we were working with logs, we'd have just four files with a couple of lines in each. But in the trace, we have everything in the same structure. Each step connects to what calls it with IDs and metadata, then the time is accounted to all the way down to the query on the database that happened on another machine. And we can, in fact, check the cache lookup before it was a miss, which is what caused this one query operation. This is what caused the delay in the entire workflow. Next, here's a quick example of what we mentioned before using traces and logs together. If the trace doesn't contain enough information. You can still use this structure to drill to the relevant log files or vice versa. Here, we have a longer session that has been traced, and we have the session's log loaded. So every span gets a count next to it, which is the number of log lines that were written. And Amber indicates that there were errors, Amber indicates warnings, and red indicates errors. So if we click on the span and click on Jump to Logs, we can see what was logged when the span was executed. So we can use it to gather more information about the creation, and we can also do it in the other direction. We can scroll through the logs and click on a log entry to see what span was running when the log entry was written. So in this way, you get the best of both worlds. We get the structured, distributed nature of traces, while you still can drill down to the arbitrary level of detail that comes from the logs that you already have. This is what we'll be analyzing in this session. A quick rundown of the examples that we've been going through. We'll look at analyzing performance across the platform as a call, individual applications and workspaces, also startup and runtime performance. And we'll also look at analyzing errors and how you can add custom instrumentation to your traces to make analysis easier. In this demo, we're using our in-house trace viewer against recorded traces, but techniques that we will use transfer to anything else, Grafana, Datadog, or whatever else you're using. And starting with performance, we have two types of performance that we're usually interested in. We have startup performance and runtime performance. Startup is a big frequent concern because the users are impatient to start working, and we have several kinds of startup instrumentation in place. Before we continue, a quick disclaimer. In the case of an application, the only one who really knows when an application is ready to be used is the application itself. I can guess, but the best data requires that the app to use our API to indicate that it is ready. And this also affects the timing for the workspaces and layouts since they consist of applications. We'll be talking about custom implementations at the end. Without further ado, let's look at some examples of performance diagnostics using tracing. The first example is analyzing what time spent during platform startup. We have an example here, a startup which was delayed by a problem with io.Connect Gateway, which, as some of you know, is the main communication component in the platform. And here we have a recording of a platform startup. That took five seconds longer than it usually does. With the same startup from healthy session also loaded as a baseline, and we can find the cause for the slowdown in two ways by comparing against the health baseline and just working with the problem run. So in these days, each span is an operation that the platform was performing during initialization, the early setup, then the steps after Electron started. The connection to the gateway is here. I will have the kicking off of the auto-start applications. We have a lot of auto-start applications being started in this journey. And there are all sorts of housekeeping tasks. So suppose you received a support ticket about the platform being slow to start or you've seen the platform startup metrics spike on the dashboard, and you've pulled the trace from the user's machine, and this is what you see. If you have a baseline trace, what we have here, the problem is easy to narrow down. We can compare and line up the two traces and see how the various operations compare the timing. In this view, we actually have the option to sort them by largest change. And we see that we have this five second slowdown in a bunch of spans. The bootstrapper, which is the root span of the whole trace, the host panel, the core trace. This is the span that connects to the gateway component, and this is the part which after the gateway component has been started, the span that waits for the port to be opened. And each of them is delayed by about five seconds. And because they're nested within each other, this indicates that probably the bottom one is where the delay happened. And if you click on this span that is trying to connect to the gateway, we see that we have in the recording that we're working at, we have actually 22 attempts to connect to the gateway, where in the... the healthy recording, we only had four, which indicates that there was something wrong with the gateway. It started with this trace. Maybe there was a locked file or it was slowed down by Windows Defender or something. And if we want to examine this further, we could drill down the logs. Here is also the span, which represents the actual start of the gateway process, which is delayed by the same amount, which also supports the thesis that the gateway startup was delayed. However, you don't always have a baseline to compare with. For instance, you may be optimizing a process beyond the current best state, or maybe you have trace from another environment where the comparison is harder. Maybe you just don't have a baseline trace. So if we go back to the problem trace alone, we can look at the so called critical path spans, which is which is a sequence of spans that finished last. So this is the sequence of operations that determine how long the whole operation took. And that's a useful concept because just by scrolling through the trace, there might be a number of operations that are happening concurrently. Some of them might be fire and forget. Some of them may be just concurrent operations. So you can't tell which ones actually delay the startup just by looking at them. So looking at the critical path, we get the spans that actually delay the startup phase, and each one of them... And if there is a slowdown, then one of them has to be the culprit. So let's filter only to show the spans on the critical path in this call tree. In this case, we quickly see this nice slowdown here, which shows gateway startup span. We can see that the application that was started was actually the gateway. So this is also the same result as before. We know there was an issue with the gateway. So we can continue analysis based on the attributes that are in the spans or the logs. So we follow two methods and arrive at the same answer. If you have a baseline trace, just compare it. And if you don't have, follow the critical path and look for the possible culprits there. The next kind of startup performance that we look at is the startup of an individual application. So a web application, as again, we have the disclaimer from before that only the application clearly knows when it's ready. However, as a fallback, you can measure up to a DOM event. And in this example, we're going to look at a case that measures the application startup to the page's load event. And in this case, the app startup took ten seconds longer than normal. So in this case, it's due to blocking execution, but it could have been any number of things, a slow resource load, initial dependency, maybe the machine was still busy. And this is how the startup looks as a trace. We have two parts. One is... The first part is the initialization that's happening on the platform side, which is the creation of the window and the kickoff of the page load. And on the other side, we have the browser side, which traces the request and response for the page itself, parsing the DOM, the DOMContentLoaded event, and load handlers. The page, the various resources that the page fetched. So we have what resources it was downloading. The io.Connect client initialization is here. We have some API calls, and then the application itself is doing some requests, and we have a bunch of unhandled errors. So you have a pretty good view into what the application is doing during the startup. And we could use the same methods as before, finding the slowdown. We could compare with the best run or just look at the critical path. But in this case, the issue is pretty easy to spot. We have those huge spans that took nine seconds while the page was parsed in under one second. And so this is likely the reason why things got delayed. And right next to this span, we have this event loop delay, which indicates that the function was executing during the same time. And we can, in fact, see what the function name was. We have the function buildSearchIndex, which took nine seconds, which delayed the whole startup. So the page wasn't waiting for a resource. It was busy, and we can use the trace to talk to the application team and show them the bug where it was and prove that they need to fix something on their side in order to fix the issue. Finally, we have workspace startup. And as a reminder, a workspace is a set of applications that launch together and live in the same window and interoperate with each other. We're going to look at one slow workspace startup. It's a workspace that took about four seconds longer than it usually does. Opening a workspace consists of several actions. The platform creating the frame window, which is the window that hosts the workspace applications, then the frame window loading, then the application starting up. So there are several places where the delay could have happened. If we look at the time sequence diagram, we can get a better idea of the whole process. We have a swim lane for the platform, which performs its own initialization and create empty frame. We have a lane for the frame window and its initialization. And we have a lane for each of the three applications. And we have arrows indicating the calls between the applications and the platform. So we see that the platform creates the frame, then the frame spends four and a half seconds initializing. And only then do the actual application start loading. They start concurrently, it went only about a second each. So the delay is probably in the frame startup. And, again, we could use a baseline comparison, or we could walk the critical path. But in both cases, we'd reach this span, which is traced in the application startup... In the frame startup. Because the frame is an application. I will trace the same things as we saw in the previous example, the page load, the resource fetches, and the various operations during startup. And in this case, we have this four-and-a-half-second resource fetch, which indicates that the page was trying to fetch this script bundle. And we have cache miss, and we have the size. So four and a half seconds of trying to fetch a script after a cache miss, that indicates that either there was a slow connection or there's something slowing the web server. Whatever it was, you know where the issue occurred, and you know how to proceed. And layout restore is pretty similar to workspace startup to have the platform doing initialization, then multiple applications starting up, and we won't work with it right now. So much for startup performance. Runtime performance, we have two examples. One of them is a janky web app, and then we have an application that performs a long operation involving a large data transfer. For the unresponsive web application case, it's a complaint that probably everyone recognizes. The user just complains that an application is slow. And for this kind of issues, we ship performance instrumentation that keeps, for every web application, one trace for the application's lifetime with running totals of performance events, such as how many times the application thread was blocked, how... Which is how often the page is lagging for how long, and also the same for user inputs. That is how often the user was forced to wait in order for something else to happen. So we see 41 long frames and 19 seconds of blocking in one minute and eight times that the user was forced to wait for the page to respond. Under the trace, we have span for every long operation that delays the application thread. And each span carries details about what function was executing and what script it lives in and recorded. And we can actually look at statistics. So if we open the statistics screen here, we can look at a breakdown with the function name, and we see that in all cases, it's the same function. You know, 41 delays, and it's the function renderGrid. We also have data about the user experience. So we have eight times that the user's actions were delayed, and the worst one was this buy button click that took 640 milliseconds. So you know what the user was experiencing in this session. And if you look at the place as a whole, you can see a rhythm, a one long frame every 800 milliseconds. And it seems to have a timer function that is just rebuilding the whole grid on every price tick. So we have such a general issue report. The application is slow, but by opening the performance trace, you immediately can see the pattern and the fix is in one function. And you can see all of this remotely without needing to open a profiler or have a screen share. And since this performance data is just plain numbers, you can also build the dashboard with metrics so you can observe the responsiveness of your applications across the user base, not just wait for people to complain. And the final performance example is what happens when an application performs a long operation. And, for instance, users are complaining of waiting for something to complete, and we've seen this scenario several times before. It turns out that the application was abusing an API, by pushing huge amounts of data. So suppose you have a ticket that user clicks a button, and then the action takes too long. Since we can analyze user actions, again, we'll start with the clickstream trace, which records user actions during an application's lifetime. Here is the click on the update context button, which triggers the operation. Then we have the listeners for the button handler, and one of them performs a context update that took... Almost two seconds. Here is the API span, which has attributes that indicate the size of the data. So the application is pushing 18 megabytes and 20,000 keys in the context. And this is the reason why the application was frozen for two seconds, and now we can have a conversation with the application team with proof that they're doing something that they shouldn't and numbers and ask them to change their data sharing strategy. Now moving on from performance and into an error analysis. We already saw that errors are recorded in the traces. So when an error occurs, it's pretty straightforward to navigate through them and figure out the reproduction scenario in the context. We're going to look at one case in detail, a complex business workflow that broke, and the same approach is useful for anything that runs across several processes, from the workflow start to layers of the backend and anything else. This business workflow is traced here. We have a call that comes in and, again, a clickstream entry where the user clicks accept on the softphone application, which kicks off process. Through several operations, the user is identified, then the user's workspace is opened, and their identity is verified. And all of that is recorded across the six processes. For a quick overview, here is the timeline diagram. This is the user's click, which makes an interop call to the desktop bridge, which publishes the call the call accepted event to the call service, which then pulls the client ID and impersonates the user, the client. Then there's a token check and starting of the workspace. And finally, raise the verification intent so that user... Client verification can start. And every step of this whole thing is nested in the... Whatever caused it. And if you wanted to diagnose the timing to optimize it, again, we could look at the critical path. And you would see that workspace opening takes two point seven seconds, and kicking off the verification takes one point nine seconds. So while the impersonation is just a couple milliseconds. So that's a baseline for how long should this workflow take in a healthy case, and you can use to optimize or to analyze it as slow down. Now in case there is an error, here is a recording of a call where the workflow broke. We have the trace that stops at the invocation of the verify customer intent, and we have an error that indicates that the verification intent was not available. And the workflow waited for ten seconds and could not find the handler for this intent. You see that the error has been bubbled up for the various applications, and so the user's click ended in an error. In the same case, we have an error reported by the verification application, which was started in the workspace, but it had failed to load. So it never registered the handler, and we see that the issue is in the verification application. Whereas the user might just report that they click the button and got an error, and then support would be forced to try to manually gather the data and reason about the workflow, trying to correlate where the original error was. Instead, you find the whole procedure reconstructed, and the error is visible in its context. Finally, so far, we've been talking about things that come out of the box with io.Insights. And all of the traces that you saw so far were actual recordings of telemetry that we publish out of the box, but we also support adding custom instrumentation. That is extending your telemetry, publishing your own telemetry, and adding more value to what you already get. We have... We give you the ability to create your own spans and traces through our APIs, which will get combined with the out-of-the-box telemetry. So, for example, you will see in the clickstream trace what workflow was kicked off, and then inside it, automatically, you will see what APIs they called with no effort on your part. And this allows you to annotate the events with your own business logic and make the trace more meaningful for the people who'll be working at them. You can also inject additional information into the Clickstream and user journey traces, add attributes, and also, a quick call out to the clickstream trace will be... That we've been looking at several times. It's based on the DOM structure of your applications. So it's part of the instrumentation. It's actually making sure that your DOM elements have meaningful IDs because that will end up in the trace, and that's what you'll be using to actually reproduce the issues. Each of those things raises the ceiling of what you can achieve with telemetry, but none of them is required. So as soon as you enable tracing, you'll start getting diagnostic data. But starting from there, you can build based on your requirements and get to a really high level of fidelity of your process and your analytical needs. And as an example, here is the same workflow that we saw previously. However, this time it's annotated with business specific spans. So here, all of those highlighted spans were not present in the original recording. They're created by the applications themselves, while the previous ones were automatically created by APIs. And we have spans that indicate the various steps of the workflow, the impersonating of the user, the verification intent, the opening of the client workspace. And each of them can have any additional attributes that could be useful for debugging. And it gets correlated to the API calls that it makes. And adding those business logic spans with their data, for example, the ID of the client and the ID of the call, transforms the trace from a record of the APIs to a record of the call process, which will help you support teams and your analysts reason about your process. So this is the end of the examples, and here's a quick recap of what we covered. The potential use cases of traces and telemetry in general are unlimited, but the goal here was to give you enough context and examples to carry over into your own needs and think about what value it can bring to your own organization. We looked at what traces are, how they relate to logs and metrics, what instrumentations you get out of the box, and several use cases of extracting value from the information, although, again, they're very far from exhaustive. Once again, thank you for your time. We will send the slides with interactive examples soon, and it's time for questions. Thank you, Velko. Yes. We have some questions already written by the audience. So I think we can start with them. Let me read this to you. But first, great examples. And I'm always amazed by how much data is being captured and properly structured in a trace. And yeah, I'm sure the use cases are a lot more than what you have showed us. Okay, so first question is about how much data is published for the traces, considering that we saw so much metadata and if everything is being captured for a lot of applications, a big platform, is this a lot of data? Well, it's not heavy compared to the amount of information. So a typical user publishing the default traces would publish tens of megabytes per day. If you start doing an extreme amount of operations, the tracing data will scale accordingly. We have guidelines for how to manage your bandwidth, and it's something that you can work when you're piloting, but it's not likely to be a big issue. If it does turn into an issue. We also allow you to publish tracing data locally. So together with the application logs, you can publish the traces as as local files and retrieve them as as needed. So in this case, you avoid the issue of bandwidth immediately. Okay. Next question is, is there a risk to expose PII through the tracing, especially the ones that we are doing out of the box, we are capturing out of the box information? The risk is low. It's not nonexistent. We... By default, we make sure to not publish any data other than things like context names, workspace names, and things like that, which are more identifiers of applications, not data. For example, no client names and usernames, actual telephone numbers, emails, and so on. You can increase the amount of data that you're publishing, but each of those decisions needs to be vetted. So the same way that you vet your logs to make sure you're not surfacing sensitive information in error messages and log files. The same applies to telemetry. So it's part of the defense-in-depth strategy. We do our best to be conservative in what we publish, and we're working on tools that will help you filter out any information that gets captured inadvertently, but there's still a measure of responsibility on your side to check the data. Okay. So if I'm doing some custom implementation of the tracing or the metrics, it's possible that something I don't want to be captured to be captured, but this is on the user side. Right? With custom implementation. You can go ahead and create a trace and put any data in it. Just like you can log any kind of data in it. So the same discipline regarding sanitizing logs applies to trace as well. Okay. Thank you. One more question we have is related to what is the performance hit with tracing? I guess what the person means is application performance or platform performance considering that there are background processes of tracing, capturing, and sending the data. At runtime, it's a couple of percent unless you're pushing a lot of data into custom traces. So it's not something that you're likely to notice unless you're doing something really strange, like you have an operation that is performed thousands of times per second and you trace all of those, then it can become a problem, especially when it comes to publishing it. But in the case of just tracing events that correlate user actions, it will not be a noticeable delay. It's pretty cheap. Okay. I hope this answers the question. And I don't see any other questions in our Q&A. So we think we can conclude the webinar. We also have two more sessions, especially the last one that Velko again is going to present. I think it's going to be very interesting because then it's about custom implementations, about more advanced use cases. So look forward to the other sessions as well. Thank you, Martin. Thank you everyone for your time. See you. Thank you. Bye. Have a good one.