So, hi everyone, I'm Marcel, I'm the software engineer at Klyso, I work there on things
self and today I'm going to talk about understanding self, a journey from metrics to tracing
which is a bit of a conclusion from a running journey for myself on this topic.
So, to scope and set a bit of goals for this, this is a sequel to a Sephalo contact
from last year, but it's kind of stands on its own as well, but if you're interested
more into the metrics part or as it is in the Seth context mostly referred to performance
counters, there's Seth talk and every like puts a topic a bit on like the strangle between
two crafting understanding Seth and understanding the tools my goal is a bit to lean a bit
towards two crafting also like convey a bit of information about Seth and not too much
about the tools themselves.
At the end, I hope you get like me a good intuition of where things are useful and what
to use them for.
And the talk is roughly split into three parts, the first going to an intro bit of metrics
a bit self like tracing and what kind of tools I picked for this task and then I walks
with two examples.
The first one I start with counter metrics and see where we can add more knowledge with
event tracing and the second is with measure latency and then we use tracing to add even
more metrics to understand latency better.
So, some definitions but kind of distinguished stuff here.
So, a metric is a measurement of a service captured at runtime definition of open telemetry.
Some examples are the browser sense the right, we increment the right counter, the OST performs
some operation, we record the latency and update an average latency.
Tracing on the other hand refers to the process of capturing and recording information about
the execution of a software program.
So, this can be like a mixed bag, right?
We can record all Rados operations, we can ask the question like, what function is
used, all those watch operations we see in our metrics?
Or we can do swift system while tracing and capture all the open or exact calls.
Both things allow us to answer questions to the runtime behavior of our system.
But a bit differently, with metrics, they are usually defined during development time
but with tracing, we can have more options and freedom to ask things later.
All right, a bit about what kind of data types we are looking at, those mostly about metrics
and in the safe context we usually distinguish four types of metric data with gauges.
This is like free space left on an OST with weight, fill level, how many requests are
waiting in a request queue with counters?
These are just values that go up, they might go through zero if we restart the service,
but these are the things you take the derivative and have a rate from.
There's also histograms, they are kind of like counters but you got this bucket.
In this example, on the slide here, our buckets are latency ranges.
For example, if we observe, if we observe latency of 0.
milliseconds, we would increment a counter for the 1 to 3 millisecond bucket.
This is great to see how it's our latency for example, distributed.
They're not too common in the safe context, way more common are long running averages.
In these are, in this chart here, this is a green line and if we have this observation here,
T1 to T10, this bars, every time we have an observation, we update our running average.
So in tracing, it's not only events that we capture, but we can also use tracing to generate
most of these data as well.
We can use tracing to generate histograms or countings as well, there is an overlap here.
All right, when it comes to tracing, what are our options in this context here?
And there is a various type of range.
We have from the simplest U probes, which is basically, let's hook a function call and run our tracing call
whenever this function call is called in our code.
The simplest tracing points we probably can have in the user's base app.
On the complete other hand, we have open telemetry tracing or in the safe context,
you often find it called the agatraising.
This is like distributed tracing spans that across multiple nodes, like the more complicated stuff.
There is an older tracing implementation you find in the safe called block and zip can.
These are according to the doc's deprecated, so I created out a bit here.
And there is LTTNG, so this is trace points that have been in the safe code base for a while now.
They allow you to add some extra trace points here in the source code.
And the great thing about it, that I will show, like in two slides a bit more,
is that they are compatible with USDT trace points.
These are user statically defined tracing points that allows to use other traces on LTTNG on them.
So they are green by accident, these are the kind of trace points we will look at to understand more self.
And I also already mentioned EDPF, and it is because we are using EDPF tracing tools to go at the tracing.
And there is a kind of, again, from easy to hard to use, there are a couple of tools to choose from.
Well, I prefer to start always with BPF trace, this has a syntax that is like, orc,
and allows you to like, add hoc write some scripts and get the answers easily.
There is also BCC, the BPF compiler collection, this is like Python with inline C, more complex.
It is very common that your start with BPF trace scripts and then go to DCC for something more complex.
Later, if you need like argument parsing and making output nicer, there is also a BPF fully
feed thing, it has some additional features, that are like great if you want to ship stuff here and there.
But my favorite is BPF trace, and this is what we mostly look at.
So I said that CF has these LTTNG probes.
So in the source code, if you look around, you will find the lines like this above here, trace point,
then we have like a grouping name, in this case OSTC, and then we have a trace point name and some arguments.
And how can we use BPF on that?
So essentially, the trace point line here is the C macro, the translates into an SCT probe,
which is our usdt probe and plus something for LTTNG, and just as like a note on that,
these probes are actually kind of cool, if you compile it, you are software with those probes.
What they do is, at that point of the trace point, they are the knob operation as a placeholder,
and at some metadata to the binary.
So that if you go around with the trace, I'd use the metadata to find the place of the knob,
tell the kernel, please replace that with the code for our trace.
And the other cool thing is that I checked, I think, the last two recent
self-container images, and those trace points are actually baked in.
So you can do all the tracing stuff on your production environment.
And yeah, to summarize, we can BPF trace those trace points, cool, right?
And yeah, so what does it mean to trace the thing?
And what we can do when we run a thing like BPF trace on our code is, it runs our tracing code.
So we can generate output, event tracing, we can count events, we can also condense these measurements
into histograms and starts, and all these things.
And this all runs in the VM and the kernel, so it's pre-efficient at the end of the day.
But, has always some challenges, right?
So I ran through writing a couple of scripts.
And so especially if you don't have nice USTT probes available and have to stick to U probes
and you have function calls, especially in the self-context, you end up to have to trace all
this deeply nested C++ structs, and this can be hard to get the information you want out of that.
So having the back info on this helps, especially if you have a new ad BPF trace version,
that has support for that, but debug info on your servers might not be practical, it's
a thing that's like a gig or two in size, so it might be like problem and prod, right?
The alternative method you can start, like mocking those structs and having
exemplified versions in your tracing code, this okay, but has it's also its drawbacks, especially
if things change and stuff. I also ran a couple of times into EBPF stack limitations,
it's like not even the K you have available there, especially if you are tracing with large
strings, you kind of run out of space and to think, tell doesn't compile anymore, and this
work around for that, but just keep out for that, it's something to run into.
The nice of thing to have is USTT trace points that have extracted arguments that are directly
have arguments that point you to the interesting data, that's the best thing to have.
Also, like a small word of course, when I try to trace our GW first, I was confused by not
like seeing this like blip rattles, it's like hundreds of trace points or dozens for like
riots and reads, and they weren't hit and I was like, why is that? The turns out that some
clients like rattles gave way circumvent those code paths and have their own to package up
their own operations, and we actually see later what that means and how we can trace it anyway.
Okay, time for the first example. Okay, by doing counters to event tracing, yeah, and for that,
I picked like a really simple workload. So just a single four megabyte as we put to rattles
gateway. This rattles gateway greets us with this locked line and says like, okay, I saw it
it took, I don't know, 60s, 3 milliseconds, and how what can we do to learn what rattles does underneath that?
And there is a whole set of metrics. There is, say, you find some under the name object
turns and OST up or OMA. There's a whole lot of them and it's not very readable and also if he
takes all the zero values out, we end up at this. So our S3 put is essentially on the rattles
like 18 operations. There's some stats, there's a create, there's a write, there's makes sense,
I guess, like intuitively, but then there is set X after. It's our key value pairs attached to
self objects. And I don't know, this might be all this metadata that S3 has in this protocol,
but we don't know yet. There's also calls, these sound interesting, these are calls to
object classes. This is coded, lives on the OST and performs like complex operations for
like more complex client, like rattles gateway is. So what else can we learn from metrics here?
So we had 18 operations if we sum the ones I just showed up. As also metrics that count ops,
they say, S3, this is odd. And if we look at the messenger, the CRPC layer, we see that
three messages went out and why is S3 and 18? And there is different ways to answer this.
We can look at the code and find out what it means, but we can also run a tracer. And
those are the output of a tracer. I ran to find out what the rattles layer does. So there is this
airplane starting. It just rolled it last week and it's not in Seth yet, but there's an alternative
to that. If you, this is my work at another trace point to the rattles to get like this nice output,
but there's an alternative. If you look on GitHub for Seth trace, there is say that project
does it with libbps plus debug info. There's alternatives and you probes. So what can we learn
about our S3 put here? So we first see this in bold is the object we access, where there's two
deer things. And these are the trends, these to together form a transaction to the bucket index.
This is the data structures, it stores all the objects in the bucket with some of their metadata.
And we can also see right in the middle, this is the operation that really creates our object.
And we see all this set X actress here. And yeah, it's really metadata heavy. We have the content time
here's the e-tech. We also have my command-time arguments for some reason. And we have our right to cool.
But how does a script for that looks like? Seth like long complicated. And this is actually all
you need for if you have nice trace points to do a thing, to trace a thing like that. So as I said
it's like a odd style. So you have these trace point definitions here. In this case usdc dt,
you have to point it to a binary because the set is baked into a binary. And then we have this
group name, OSTC, and then the trace point name. And this calls our tracing code. In this case
it's just the print app. We're also recording the start time here. You see something with an
ad in front. And we're storing with our zero as a key, our zero is just our transaction ID.
In this case it in a map to later on the finish side retrieve it again.
So we also can't latency with things like that. All right. This is all, yeah. This is all you need to
trace things. And you can like extend this. For example if you're just interested in parts of
the operations or want to have a stack trace in this space you can also ask bpf to give your
stack trace to see where those operations originate. The best to quickly summarize what we've seen
with metrics it's great to find out what the operation mix is that we see for clients.
I also learned that tiny operations are put together into bigger operations. And it took three
messages and three big operations on the rattlesite to do our put. And two of those forms the bucket
index transaction and one is object plus metadata. All right. Second example.
All right. Where you look at latency and for latency we change our workload a bit.
Here I just ran short S3 benchmark. It has like a mixed
mixed operations where some delete gets put stops basically had request. And we get another
pie chart. This time also a lot of calls but also some reads and writes. And if we look at
like the simplest latency metric on an OCD we can find. This is OCD of latency. On my simple
test setup I saw 40 milliseconds. And is that actually meaningful? We have all these operations and
they must be different. They must have different characteristics. But they're all mesh together
in this 40 milliseconds. And so the question is how we can add more detail to understand
better what is going on in terms of latency. More detail means there's two options.
We can look at more averages. There is averages per reads, average is per writes.
But they still mesh together a lot of operations into averages.
The OCD also exports histograms and they have like latency plus size
so we can understand things better in terms of size there. These are parts of the previous talk.
Now we're looking at tracing to ask more dynamic questions on this topic. So first
what kind of trace points do we have? And if we look at the OCD we find I think it was around
70 trace points. And for this there is a nice family of trace points that we can use.
They are called do is the opt pre. There's post and there is a special pre for every rattle's
operations. There is. So the first and the last they are just the generic ones. And then there is
a specialized one that has parameters. For example for writes they tell you this is the offsets
of the write for an old map update. They tell you the keys and values. And what kind of questions can
we ask? Just with this there. Oh. There by the way there's surrounded around the operation process
in the OCD. So we can capture that. So what can we ask? We can ask for
example what is the most accessed object. And in this case turns out the bucket index is
pretty popular. So this is the Durr again. We also see that with my 3 OCD they are not one OCD
got lucky and got some more charts. So it's a shorted data structure. What else can we ask?
So I'm a big fan of histograms. You might notice and we can use these trace points to generate
our own histograms that are per operations. So I picked picked three operations here right
full read and call. And with that we already see okay. Even this operations compared to another
have a very different characteristics in terms of latencies. Where we had before the number
40 milliseconds. 40 milliseconds is somewhere here. Yeah. And the average isn't even reach really.
And we also see that reads and writes seem to be by model in their distribution. And we see
that calls are very very fast usually. This is just like under a 500 microseconds here. But
also some take like in this range of 30 milliseconds. This is odd right? This is but we can only
find it out with looking at things like that. And from that we could even drill down further.
We could build histograms that even have the size in them. And we don't have to pre-decide
what kind of things we want to measure. We can do that on the running system. And again how
does code for that looks like? On the left side there's the object s access counter. We just hook
the post-op trace point. And in a map record the name of the object this happens to be in
our zero and called count. And this count it does all the multi-threaded thing and it counts
just the operation. This is it. And the nice thing with the pf traces if you exit the software
we print out all the data structure you put stuff into. On the right side we have the thing that
generated the histograms. And there we again we just in pre we record under TID. This is the thread
ID. The start time and post the calculated duration and then call hist with this observation.
Okay cool. This is all we need to do. There's I haven't so far talked much about
U-propes and U-propes are as I said at the beginning. They're just hooking functions.
And so I just want to say yes we can also use them to find something useful out. And this
looks a bit weird. I mean if you look at these U-propes, what is that? For C++ developers
is probably obvious this is like a mangled function name. You can use wild cards there and all kinds
of stuff. But what I'm hooking here is in Rado's gateway the opt processing from in it. This one
to complete. And so I can get histograms with that over the operation process like for every get
for every put for every copy object in Rado's gateway. And what to do for this this needs
debug info. I have to cast pointers to something and then traverse them to some interesting
points. It's totally doable but a bit like unfriendly. The best thing you can always have with
tracing is nice U-STT trace points. All right with that time for recap. So we start with how to trace
what are languages, what are some good tools to start doing that. Then the first example from
counters to event tracing on how to learn things about theft. And at the end we learn that
we cannot only trace for events but also aggregates them into metrics. And where to go from here
always like to have things like that. There is like what I would find interesting to do next
is there is a tool called EDPFxPorter that allows you to convert the trace points directly into
things that promisius can consume. And this seems to be interesting to like prototype possible
metrics that would be interesting to have and theft just before doing the development work.
Would also love to have some error tracing tools. If errors occur that allow me to further
like find out what's there about or like what's up Tracer that you just say here's the process
and theft like tell me if anything sensible going on there. Or integrate it with a longer
act to have conditional log messages where you are just interested. I want these log messages
through the Tracer and not having them fill up my log thing somewhere. And like a tiny
call to action I already started collecting all the scripts I showed here to repository that
I would love to get like a BFF tracing toolkit reported to going on like you will find so many
of these tools for like system white tracing already. And with that the two links to first the
bit more like a notebook file for all the things you saw on the talk and this for the toolkit.
And then thank you.
Seeing I've five minutes time for questions.
Yeah.
Sorry.
The storage.
It depends. The thing is if you're collecting those histograms they're all collected in memory
in the kernel memory. Oh yeah. The question was how did I manage the storage of all the traces?
The two answers to that for event tracing. I don't. I just stored them on my artist now.
But I didn't do any high rates stuff. But for stuff that you are accumulating or condense into
histograms for example, this is all done in kernel memory and you only get the results back.
And this is so much data. So you don't have to like go from kernel to user space for every event
does that answer your question? Great.
Yeah. So if I want to tune this put object with things like 10 settings.
How would I find the actual source code for this? And the other question is how much of
access is going on in parallel as you can see?
Okay. The first one is how do I find the source code for these traces?
So you have shown in the put object. Yeah. There's like 8 or 9 set example.
If I want to make this asynchronous in parallel, I find the source code in whatever
RALOS is there a link somehow is it possible with vector traces?
Yeah, we can always serve in your trace points with quest back traces. There is a
called either trace or you trace. If you do a print back trace, you get the back trace.
When you hit that trace point, yeah. Can do that to find the source code?
Think if you have debug input kind of to tell you like more details about that.
What symbols and was that? Frame pointers are usually enough to get the good trace points.
And the second part was a synchronous.
I mean, how much of the tracing is a synchronous in parallel? I think all of it basically.
So if you have the trace point, it hits like on every thread and you even get the thread ID
and the nice thread name and things like that. This is why sometimes things like the counter
function is important because that handled the counter increment between threads.
So it has that all built in bpf trace.
I did write a skateway. Can this be useful for block device? It depends.
This is for I did most of the tracing for user space and Rados block device is I think
either user space or kernel space. For kernel space, you need kernel trace points.
I'm not aware that they are like nice kernel space trace points, but you can do function tracing
in the kernel as well. For the user space, I don't know if there's any USTT probes, but you can
resort to function tracing all the time.
Oh, yeah.
The question was about performance and application of tracing and stuff.
I know a couple of results that I didn't replicate so far.
So the ebpf exporter project has a benchmark section. They claim fancy USTT probes cost
around two microseconds. The conventional wisdom is, if it doesn't happen to often, it's
okay to trace it. If you're starting a trace model, you will see that it towards the terms of
performance. But this is something I really want to look into as well. What does it mean? Can I
really run it in production, right?
Sir, okay, question was, sir, circuit breaker for taking down my application was too many
trace. I don't think there is. You can build your own, I guess.
Yeah. Yeah. Okay, time is up. We can talk outside and anybody else wants to be stopped.