Intro to o11y Topic 14: Querying Spans within a Single Trace in Honeycomb

Jessica Kerr [Developer Advocate|Honeycomb]:

Here we are in this trace. It’s a trace of a call to /fib with an index of 9. And I’m looking at how many calls to index=5 are in it. And I can use the search to see how many spans are found and I can use my eyes to count them, but I want more. I want Honeycomb to count all the different indexes within this trace.

Okay. So I copy this tracer. I hit new query. Honeycomb queries operate on spans, and I can limit this to only the spans in a single trace. I add a filter on trace.trace_ID to the where clause and I hit paste to put the trace ID. Oh, there’s white space at the end. I take that off. Okay. Enter. And then I push run query.

Ah, it says you didn’t specify any visualizations. I add something to the visualize clause. When in doubt, count. Run query again. Huh? Now there’s no results in this time. Right, okay. Well, that’s fair. This trace, it’s been a little while. I widen the time range. Boom. Okay. There’s something on the graph.

That’s a good sign. Huh? 544 spans in this trace. Now let’s duplicate what that search was. It was looking for anything with index=five in it, and it found the URL. We can do that too. Control enter will run the query. Aha! Now we’re down to 10 spans. That’s how many it found in the search of the trace when I searched for index=5.

So that’s consistent. What spans are they? Let’s look at their names. Yep. There’s our familiar HTTP get and get/fib. These are the client and server sides of the same request. I expect that if we look at the span.kind, we’ll see 5 server and 5 client requests. To look at the values of a field, put it in the group_by. Sure enough, we have five clients in five service bands.

And the service bans should have their parameter.index populated. Let’s verify back. Sure enough, 5 server spans with index of 5. Now I see that I can simplify this query. I only want to count these spans. Hovering over the row, the three dots appear. When I click on the three dots, I get this little menu. I can choose to see only the event in this group.

5, it counts 5. Good! All the fields that were in the group_by are now in the where. Because I understand the meaning of this data. I know that most of these filters are unnecessary. I do want to limit it to this trace, but I can remove the URL_contains and the name and the kind, because all of these are covered by that parameter.index=five filter.

Only the spans I care about have that field. Run query. Sure enough, still 5. Okay. So there are 5 spans in this trace where parameter.index is 5. Well, what about other values? Let’s group by this field instead. Look at these numbers. These look important. Well, not this one with the three dots.

I can say show only where this index field exists. Better! Now let’s get them in order. Not by count. I want it by index descending. Yes, we have one call to 9, one call to 8, three calls to 6, five calls to 5. Ooh, I want to see those in the graph. You can see this one being called one time at the beginning and then eight.

Well, and then two calls to seven, spread out. Three calls to 6, 5, and 4, and oh my. 21 calls to fib of 2. No wonder this took so long. How long did it take? 478 milliseconds? Each of those 21 calls to fib of 2 took up to 112 milliseconds. Now that seems like a lot. I can check the minimum. Oh, okay. At a minimum 2.8 milliseconds for a call to index equals two. This is a really wide range. Does it get slower over time? I could tell if I heatmap it. Okay, stop Jess! I always find more questions. It’s always super interesting, but I need to stop somewhere.

Transcript