foreign
[Music]
thank you very much good afternoon
so today I want to talk about uh
some of the tools that I use in in
solving problems
and there are kind of two kinds of
problems that I'm going to talk about
solving or at least uh
trying to diagnose on the way to solving
the solving Parts usually the hard part
but but we'd like to figure out exactly
what's going on and and so the kind of
tools I use for this the first category
I would put as performance analysis and
so those are tools that are maybe giving
us some kind of information about
latency or operations per second or you
know bytes per second uh that that kind
of thing
and the second kind of category is what
I sort of call Behavior Analysis and
that's more looking at exactly what a
program is doing what steps is it taking
maybe trying to figure out rather than
it being too slow maybe it's doing the
complete wrong thing
and in in my day-to-day role I've been
some
administrator or SRE for uh for more
than 15 years but currently I work in
the Ubuntu support team and we support a
right away of customer problems so it's
not just one product there's kind of
could be anything that runs on Ubuntu
spend quite a bit of time on openstack
and ceph which themselves have lots and
lots of
components but really someone can open a
case about anything and so we don't
always have built-in the best tools or
best metrics for finding out what we
want to know because the problems are
kind of of always different and I need
to do this at runtime and in production
and uh not crash or slow down the system
in the process
so that's kind of what we're going to
talk about today and my hope is that
I'll introduce this new tool that you
may be either a little bit familiar with
or maybe give you some ideas about what
you can do with it to maybe help solve
your problems
so in the performance analysis kind of
bucket we have some traditional tools
that you might be familiar with
these are things like iostat or top
vmstat NFS stat bwng all these kinds of
tools and what most of these tools are
doing is they're kind of they're very
fast they don't typically impact our
system performance because they're
looking at some kind of performance
counter that usually the kernel is
already kind of taken care of and
Counting for us you know how many
transactions going through a network
card or a disk or or something to do
with the process
these are super great for a top-down
view but some of the limitations number
one is they they really make heavy use
of averages and averages are really good
at hiding outlayers and we'll talk in a
minute about why that can be a problem
and they often have a predefined and
limited kind of breakdown so often we
might be able to see disk statistics for
a disk but without correlation to a
process or we may even be able to see i
o information for a process but without
correlation to which disk that I O
information is from
another kind of uh subcategory these
tools and top and Nets that are really
good examples of this is they'll take an
instant snapshot of the system every
second and if something happened in like
point one of a second in between the
last snapshot and this snapshot it might
miss that completely
so in the case of top if you're
launching lots and lots of processes
that take a very short time to execute
those may not show up in in top at all
and you might miss the CPU usage from
those
and netstat will show you all the live
TCP and EDP connections on a system but
only at the instant you run the tool and
you won't see all the ones that were
short-lived in between those executions
so look at some examples of what
averages can hurt us so this is a tool
that I really like to use called iostat
and it gives us a breakdown of i o
performance statistics for each disk on
the system and so here we can see uh
we've got like multiple discs and some
hard drives and nvme device and some
Columns of data so we're seeing reads
per second and writes per second that's
iops the read kilobytes and right
kilobytes a second that's the bandwidth
going for the disk and also the average
latency so the ra weight and the right a
weight is the average latency of those
operations
this is kind of good as an overall but
latency and latency can be a really
important thing to look at is is an
average over all 27 000 these operations
that happened in in that second
and so it could be that all 27 000 of
those took 0.03 of a second
it could also be that you know almost
all of them except for one took 0.01 of
a second and one of them took three
seconds and if you've got a disco
operation that's taking three seconds
that's really interesting but you can
entirely miss that in in tools uh like
this
if you've been around Iowa storage you
might understand this but if if this is
confusing I think one that we can all
relate to uh is any kind of computer
Enthusiast is CPU usage
and so in this example of top output I'm
running the fio Benchmark tool and I've
I've set it to only use one thread to
kind of stress a a point in this case
but we can see top is telling us that
our our CPU usage is is like only six
percent and 93 of our CPU is Idle but at
the same time it's telling us that that
FAO is using 100 of our CPU and these
numbers kind of like don't add up
and if you haven't used this tool before
it might surprise you the percentage of
CPU it doesn't go to 100 actually goes
to however many CPUs you have times 100
so if this was using my whole system
let's say 3200 percent
but we can ask top to break it down so
if you hit the number one key on top it
will actually show us all the CPUs on
the system and the utilization of each
one and in this view we can see that
actually one CPU is running it at Full
Steam because FAO is single threaded it
can only run on a single CPU but the
other seven CPUs are idle
and so if we only looked at that average
we had here at six percent 93 idle we
might think our CPU is not a problem
when in reality one CPU is a problem and
there is a bottleneck that we were
missing with that average
and these are more simple ones but these
kind of problems show up everywhere in
any kind of latency or utilization of
any kind of system resource these
outliers and averages hide stuff from us
all the time that end up making it
difficult to solve problems that I hit
quite often
another category of tools uh which is my
behavior analysis kind of category these
tools rather than looking at very fast
performance counters are trying to like
look at everything a program is doing
s-trace is probably my favorite and S
Trace will attach to every system call a
program makes and Report exactly what
that system core was how much data was
written can even tell you what data was
written
but this tool transfers every one of
those operations from the other process
into user space to s-trace to then print
out and that's very heavyweight
if you're doing a very small program
that might be a small amount of data but
if you're trying to analyze something
doing gigabits a second or gigabytes a
second of disk or Network
number one it won't be able to keep up
with processing that amount of data but
it'll also slow down that application
uh block Trace is a pretty awesome tool
it's kind of a kernel facility it'll
dump out every block operation that
happens on the whole system every every
request queued when it comes out of the
queue when it goes to the disk when it
comes back but again it's going to queue
all of that information out into user
space and into a file and that's very
heavyweight
uh IP traffic looks quite innocent if
you run IP traffic the first mode will
tell you like every connection and like
the number of bytes that are coming
through all those connections but to do
that it's actually a packet dumping the
entire network card into IP traffic to
like find like all those values
and a few megabits not a problem if
you're doing 10 or 20 gigabits a second
uh that can be a problem
and even just debug logging if you've
ever turned up a debug in something to
like level one five or Twenty the amount
of stuff coming out usually will slow it
down
so those are the kinds of problems we
have with these behavioral analysis
tools but often they can tell us things
that those performance counters can't
because there's only only so many of
those performance counters and
if one of those doesn't cover the
situation we're looking for if we kind
of look at this detailed output we might
be able to find what we're looking for
at a cost of a big Slowdown
to demonstrate how big that slowdown is
I've got here an example case of running
DD and that's just a disc copying tool
we're probably all used with at least a
Raspberry Pi or something I'm reading
from Dev zero which is like a string of
null bytes and I'm writing to Dev null
so I'm reading a bunch of zeros and
throwing them away straight away
to make the example a little contrived
and stand out I'm doing that one byte at
a time I'm not batching it into like
four kilobytes or a megabyte and we're
gonna do it 500 000 times
and so if I do that just with DD on its
own it takes 0.2 of a second which is
pretty fast
if I use S trace and I don't even ask S
Trace I wanna I ask it with except they
say I only want to look at the accept
system call that's to accept a
connection for the network and Diddy
doesn't even make network connections it
might ask you to do that that same task
will now take 18 seconds that's nearly
100 times slow down
in a production system that's very busy
that's a penalty we we may not be able
to incur on a developmental test system
it might be reasonable or on a quiet
system I've used it a lot but there are
cases that's not going to work for us
and the reason why it's 100 times slower
is because the way this Tracer works it
uses a function called in a kernel
called P Trace which is the debugger
interface it's the same interface GDB
users
and it's remote controlling DD it's
literally like little remote control it
says the kernel work Petra Sysco I want
you to run this program until the next
system call the kernel says okay it runs
and it does the right system call
and then uh it goes into the kernel to
do that system call and goes oh I've got
to talk to S trace it wanted to know so
it's pause DD Diddy is doing nothing we
go to S trace it goes cool we had a
system call I want to know what the
system call was to find that out it
needs to know the CPU registers in the
context of DD sort of ask the kernel
what were the registers goes back to the
kernel kernel sends it back to P Trace
Petro says great now we need to actually
run the system call so it goes back to
the kernel it actually finishes the the
work of that right system call but then
we go back to S Trace again
why do we do that well at the start we
we have the registers we're telling us
the parameters to the system calls so I
want to write this data to this file or
this many bytes but we didn't know the
result yet and so after it runs we have
to then get the registers to get the
result but at that point we can no
longer see
all the parameters that were passed in
so we have to interrupt it twice once at
the start once at the end so it gets
those registers then it goes back to the
kernel uh gets those registers of the
ancestor kernel okay you can continue to
send the data back to the process and so
that's context switched from DB back to
West Trace through the kernel eight
times
and that's why it's 100 times slower
and DD has to wait in all the time all
the time here we've spent uh
in s-trace land deity is doing nothing
and so that that's why it slowed down
so it'd be really great if we could
write something a custom tool to gather
performance metrics on anything we
wanted
you'll be also super great if we could
group those in some way we wanted that
wasn't predetermined you might want to
group those by device network card or
disk by which process by which C group
anything we can kind of think of it'll
be awesome if we could do that or even
just get the same information we had
before but with a much smaller impact on
system performance
and the good news is we can do that and
there there are a number of ways we can
do that now so here are a few quick
demos
so these are BPF Choice tools and I'll
explain how they work in a minute but
they can do some really interesting
things so here's one called get host
latency
and it will actually Trace not just one
process as Trace only attaches to one
process at a time we can actually trace
the entire system with every process and
we're going to hook into the get host by
name system call in libc and say every
time that happens I want to collect that
and then print out which process of
looking at which hostname and how long
it took and that latency is kind of one
of the cool things we can get from uh
from BPF Trace that other tools often
won't show us a per request latency
and I've solved real problems like this
uh when I was doing
um web hosting before before now your
customer applications would be written
in WordPress and the wonderful thing
about WordPress is there's like 100
million plugins written by 100 million
people who kind of know how to write
plugins and then people install like 100
of them and so you get all these bad
decisions 100 times Amplified
and often these are written by people
maybe that live in the US and they have
a like maybe 20 millisecond or 30 second
millisecond latency to the entire
internet uh most of us in Australia
would know that our latency is 10 times
that like 300 milliseconds to most
things and so if you make like 20
Network calls or 20 DNS calls at 0.3 of
a second each that really adds up and
suddenly it takes 10 seconds to load
your web page
and so this is an example of a tool we
can see well how many of those requests
did we make and how long did they take
another tool that we have and these are
all kind of in in the BPF Trace toolkit
that we can we can do custom ones is UDP
life and it will show us all the
connections not just TCP but UDP
connections that happened on the system
and how long they took how long was
traffic going back and forward
uh in this case it's kind of a more
generic version of the last one and the
last one we're looking at only DNS
requests now we're kind of looking at
latency by program of all UDP
connections and how long they took and
where they were going
and so in this case we can actually see
the DNS uh same DNS requests and their
latency the latencies here in the
millisecond column uh and
uh Port 53 is DNS we can also see an ntp
request here that had a 15 millisecond
latency
and unlike Nets that this is going to
show every connection in real time as
they happen
and again for the entire system another
tool is open Snoop it's going to show us
every program what path they opened and
uh whether there was an error for that
and so far those kind of three tools
I've shown are in the category still
where they're transferring a lot of data
user space it's kind of every operation
one of the other uh nice things we can
do with with BBF Trace is we can start
to summarize information so instead of
transferring out of the kernel into the
into the user space analysis tool every
operation we can send only a summary and
here's an example of that we're looking
at the i o latency of every i o request
to a disk on the entire system for every
process but rather than just an average
we're now bucketing it with a histogram
and so in this example
uh
the vast majority 8 000 operations took
8 to 16 microseconds another eight
thousand took 16 to 32 and you can see
this is kind of like a bar graph of like
what uh proportion of the total requests
were in that bucket most of them are
very fast a few uh you know few tens of
microseconds for some reason we had one
request out of 30 000 plus requests that
took one million microseconds that's one
to two seconds
and these are those outlines I was
talking about if your program if you had
one program made all these requests
sequentially it doesn't matter that all
the every single one except for one took
like 10 microseconds one of them took
one second so that entire process is
going to take a second to complete
and those are the outliers that we need
to understand when we're trying to uh
solve some of these weird problems
so what's unique here is that we're
getting a histogram
not just an average
is another kind of tool that's doing
some summary analysis called sys count
and it's just showing the top system
caused by ID uh this tool unfortunately
doesn't print the friendly text name but
it is possible to do that and also the
top 10 processes by process names so
which processors will make in the most
system calls
and we can customize all of these things
these are just example programs whatever
problem you're trying to solve you can
change that summary or analysis to be uh
what you want it to be
so what makes this possible so I've kind
of that's a little taster about what we
can do with this tool well let's
understand how it's doing it
so the First Technology that's making
use of uh it comes from the F Trace
subsystem which was merged way back in
2008 so it's really not that new of a
technology
and the kind of
um
first part that kind of f Trace brought
in was this ability to have these events
in the kernel that we could attach to or
or record in some way and there are a
few different types of those there are
more I'll explain in a minute but a
couple of the main ones the first are
these static Trace points and they're
kind of like the kernel developer of
that disk subsystem or net subsystem has
defined some Trace points that aren't
going to change along with some
predetermined information that's going
to record about them it might be the
network device name it might be the file
name that kind of thing
and those are ABI Stables so we can rely
on the Kernel even if the internals of
the kernel change that Trace point is
always going to have the same name and
output the same information
we also have the ability to attach onto
any function in the kernel if you go
looking through the kernel source and
there's something that interests you you
can attach to any one of those functions
and we can also Trace those but in those
cases on different kernel versions those
functions might change and then you also
have to figure out how to get that extra
context yourself you want the file name
or the uh the disk score or something
like that you have to start poking
around in the data structures that's
great when you get kind of really good
at it but for you know the more typical
case it's nice to have these predefined
Trace points that know are already kind
of what information to get
this infrastructure is also super high
performance and the way that works is is
when the Kernel's compiled uh and
there's a couple of different mechanisms
different places but basically it it
puts out a string of knot but no op
codes for the CPU to execute and CPUs
are really fast at doing nothing that's
been optimized to death by the CPU
vendors and so it's just like these five
bytes in memory that do nothing and only
when we turn on tracing for a certain
kind of function does that in memory get
overwritten with instructions to
actually jump out to the code to handle
this performance analysis
and so every function in the kernel is
ready to be kind of traced like this but
there's no performance impact until you
turn it on
this incidentally is similar to how live
patching also works uh it'll actually
patch the start of the function to like
go off to the new version with live
patch rather than the existing one
they're kind of related
the second technology that uh kind of
brings this together makes it really
work was we moved in the s-trace case it
was like a remote control for the
process and and the kernel would send
control to S trace it would tell the
kernel like what it wanted to do back
and Boards back and forth
now with the F train system you have
this ring buffer in memory in the kernel
and the kernel itself handles the trace
event so it doesn't break out to that
user space analysis application at all
and it writes that Trace event into a
ring bar for in-memory all internal
context then the user space tool reads
out from that buffer asynchronously at
the same time there's no lock between
them
and what that allows is now a
recording's entirely in kernel space so
we're not wasting all that time context
switching back and forth
and our process isn't paused either we
that little bit of recording work it's
just like you know poking a few bits in
memory that's very fast to do compared
to to all that that jumping back and
forth
one of the disadvantages of that however
is uh if we have those predefined static
Trace points the kernel knows how to get
that context and it knows how to put it
into that buffer in memory so the user
space application can read it
if we don't have a predefined trace
point and this happens we want to just
trace a random kernel function instead
which doesn't know how to get its
context then the only thing we can
record is that that function was called
and we can't really store
you know the context about the disk
score the length of the operation and
that kind of thing
this has some safety elements built in
as well if if the buffer fills up they
just those events just get lost and so
rather than the kernel stalling and
maybe making applications slow if for
some reason the user space side can't
read fast enough it just drops those
events
and if the actual processing of these
events take too much to climb that the
kernel also has mechanisms for
throttling that time back to make sure
that it it maybe is a few percent of
your your system timer most
and so if we look at the effect of this
so here's uh before we we showed uh you
know that same DD operation it took 0.2
of a second if we s traced it and didn't
even do any work as Trace was interested
in it now took 18 seconds well if we use
perf Trace instead which takes advantage
of that kernel infrastructure to trace
the event and also uses that ring buffer
so that the the applications are not
waiting on each other now we can trace
the same information in three seconds
that's still 15 times slower than our
Baseline but that's a huge improvement
over 18 seconds and we can improve that
again if we if this was tracing every
system called reads writes connects
everything if we narrow that down again
to only the right system call and
remember here it's taking us 18 seconds
to observe nothing here we can observe
half of the work the entire process did
because it's reading 500 000 bytes and
writing 500 000 bytes so half the work
is reading it half the work is writing
if we only look at the writing of it we
can now get that down to one second
that's only five times slower than our
Baseline case
but we're still copying a lot of data to
use the space so every one of those
operations is going to this ring buffer
and user spaces reading out all 500 000
of those operations
so we're way faster but we're still
wasting resources that maybe could still
be improved
and so that's where BPF comes in
and so the origins of BPF were were in
packet capture so when you ran TCP dump
and you were filtering on Port 22
without BPF every single packet would
have to be sent in the same same way
we've just been discussing sent out of
the kernel into tsp dump it would then
parse the packet and only print it if it
matched
and at gigabits a second that's that's
going to be a problem and so the BPF was
this little virtual machine that was put
into the kernel where we could Define a
tiny little program and send it to the
kernel for how to filter the packets
that's another kernel would take a
program that tested up wrote it would
verify that that was safe it wasn't
going to corrupt memory it wasn't going
to take too long to run it has all these
safety checks that make it safe to
actually put user code into the kernel
which sounds a little crazy and uses
that to filter the packets and so now
only the packets we're interested in are
actually sent out to T speed dump which
had a huge performance win but it was
very specific to to packet capture
and this was in 1992 so very long time
ago
in about 2013 uh some developers took
that BPF and they enhanced it they added
that little virtual machine they've
added more registers more storage space
they made it jit compiled so rather than
kind of interpreting that virtual
machine that's now converted to machine
code kind of like JavaScript might do
and they added the ability to drive
these programs not just from packets but
from all sorts of different event
sources
and one of those event sources is these
same events that we're tracing so those
those static Trace points those K probes
all these event sources can now be
connected to a BBF program
and we have all that same safety the
kernel is going to verify there's
actually reads and parcels and
understands the entire program before it
loads it to make sure it won't crash
that it won't take too long to run but
it can't access unsafe memory in that
and that kind of thing
that does put some limits on the program
and so to get a lot of the work done we
need to do the kernel has little helper
programs the BPF program basically make
some function calls out to certain
kernel programs that will maybe make
sure that whatever you're getting back
is safe
the win this gives us is now we can take
any tracing event and instead of just
putting the full output of that into the
ring buffer and sending it to user space
and now we can process that in kernel
and we can actually use code just like
the packet dump to summarize or extract
data in the kernel
and then put the results of that in the
ring buffer that's sent out to user
space
and now we're only transmitting a very
small amount of data out to user space
and so we're even faster again
and so if we look here I've written a
tool in BPF Trace using this technology
to do the same thing we did here so
before it took us one second to trace
every right call because we're
transferring every right call out to
user space but I might have just wanted
to know how many there were and so I
wrote a program which counted how many
right calls there were but it counted
all of that in the kernel and the only
thing it said to user space was the
number 512 000. and now that takes 0.3
of a second which is only 50 slower than
our Baseline case
and this is a really contrived example
because we're doing a purely system call
uh kind of load work uh if if in reality
this program spent a lot of CPU time
doing actual kind of work programs do
and not just sending data back and forth
that that uh performance impact would be
would be even less often maybe five or
ten percent at most
and so as an example of that if I use
fio this is a really good disk
benchmarking tool with an actual kind of
uh benchmark
I can do 35 or a thousand iops a second
with no analysis running and if I turn
on a tool to analyze the latency of
every eye operation on the system so
sorry I get 37 000 without it but it
only drops to thirty four thousand when
I start analyzing the latency of every
requesting the system so that's a a much
much smaller drop than we have with all
those other methods
incidentally BPF was first added to
kennel ebpf was first added to the
kernel for s-trace while not just for
ashtrays for uh but uh for a thing
called set comp BBF and so this was a
little program we sent to the colonel
and when we used that p-trace mechanism
and said intercept every system call we
could send a little program to the
kernel to filter out which system calls
we wanted to trace and so I wouldn't
actually wake up S trays for all the
unrelated system calls only the ones we
wanted
um and this is used for for a few things
but when we use it in s-trace we can
halve the amount of time we take but it
still takes 10 seconds uh you know
versus the like one or point three of a
second that we've managed to to take
using
uh this internal uh collection of the
data and internal analysis because this
this is only just cutting out all the
events we didn't care about it still
transfers all the events we care about
to user space with s Trace
so let's have a quick look at the
language of BPF trace the the nice thing
about BPF race is uh you can actually
write BPF programs in python or in C or
in go but doing that is quite of a boost
and if you're a software engineer that's
quite possible but as more of a sys
admin or SRE type person who's maybe uh
knows not to be dangerous uh when it
comes to coding or how the kernel Works
uh that's quite
um
a forbidden kind of kind of task BPF
traces are much nicer Uh custom language
lets us write these programs in a much
more friendly way so here's an example
of what the language looks like
uh sorry
uh yes so the BPF Trace language is
inspired by the d-trace language which
is a tool on Solaris from 2005 which did
very much the same thing in the same way
it was inspired by orc so the reason it
looks like August because it was heavily
inspired by orc
um
and so that's why we have a begin and an
end so we can run some code at the start
and end of our script in this case we
just print out a nice little string so
the person knows we're actually doing
something and we've started our work we
can specify a probe type and so an
example of a probe we might do is a
system call system call right but
there's there's a lot of different
probes and we'll look at all them in a
second we then have a predicate so we
can actually have a condition again like
orc we can say I only want to match on
this probe if the process is a python
process
and then we can run some actual code and
so in this case we're going to store a
global array called start we're going to
index it by the thread ID and we're
going to store the system time when that
probe was called
here's an example of another probe we've
got a more complicated uh predicate
first we're going to check that we
actually had a non-error return value
we're also going to check that we're
Python and we're going to check that
initially we kind of match this other
other probe first we'll make sure we
match that first and then we'll do some
other logic and in this case we're
summing the latency the time it took
from the first function to the second
function
and so we calculate that latency we we
sum up that latency per process ID so
for whatever we're probing we're going
to add up the total time spent uh in in
that time period and then every 30
second we're going to print out all that
data we've stored and at the end we'll
print it and so that a bit like a lot of
iostat and top and stuff do it can print
out kind of like intervals and then kind
of print out the result at the end
specifically some magic variables in
there like count so the question is uh
there seems to be some magic variables
like count so yes so there are a bunch
of
um it's actually not a variable it's
kind of a function but it
yeah it basically just says uh count up
that um
oh you're saying I've uh oh I've
actually made a mistake when I was
making this line I see what you're
saying my mistake I did account that
should probably be uh at time that was
just an error in my slide preparation so
uh yeah that should just be at time this
is not a real program I was kind of just
trying to show this in text but thank
you for catching that
and so here are a bunch of one-liner
examples of BPF programs that actually
do things uh these come straight from
the BPF Trace manual and uh so here's an
example that we're going to check all
the files open by a process so we get
the open system call and we want to
print out the file name and com which is
a special variable BPF Trace knows it's
just the the process name
we can count system calls by program so
we we match this probe and we're just
going to count indexed on whatever the
program name is so even if you have
multiple copies of python running all of
them are going to kind of count together
uh this is a case of we're summing so
rather than just counting we might want
to sum the number of bytes that are
being read uh that's an example of that
here's our histogram we talked about
let's say you create a histogram all
these kind of different things that we
can put together we can do printf uh we
can do multi-dimensional arrays all
sorts of stuff
[Music]
I mentioned before there are a bunch of
these different probe events we can
attach to and so uh the two we talked
about so far one was Trace Point these
are these predefined ones in the kernel
that
um that they've kind of given us as a
convenience and it already knows how to
extract some some context we can also do
a k-probe and that attaches to any
kernel function
and uh the cape probe has a k probe and
a k rep probe so as I described earlier
in the S Trace example at the start of a
function we need to intercept then to
capture the arguments of the function
and then we need to intercept that at
the end to get the return value or
perhaps collect um the results of that
function running so we we kind of probe
those separately we can also probe uh
user space programs so a u-probe will
actually probe a function not in the
kernel but in a program or in a shared
library and I'll show in a bit for
example we can probe the SSL library on
every process in the system and kind of
capture information from that
use based programs can also much like
Trace points in the kernel there are
statically defined user space Trace
points called usdt a bunch of bits of
software have some of those and we can
also do
um
a bunch of periodical things we can do
things on an interval
um we can do things
um based on performance candles from the
CPU those ones get a little bit more
advanced something we're going to talk
about those today but there's a whole
range of them that you can look at the
user space probes the kernel probes and
the trace points are kind of the most
interesting uh most interesting ones
so I promised five recipes so I'm going
to go through and talk about kind of
five Solutions I've actually used when
solving problems and kind of show the
program and what that looks like
uh the first one is uh I was trying to
profile some python applications uh now
BPF Trace actually has the ability to
get the kernel stack and the user space
stack the actual call stack like a
debugger would but it can only do that
from programs with like traditional like
frame pointers and debug info uh that
doesn't work with python right now that
might get fixed because there's some
ability to add like some some magic so
that it can kind of understand from
python what's going on but I was using a
different python tool called Austin
which will profile the python
application but I wasn't launching
python something else was and so what I
wanted to do was capture every time
python was started and then immediately
launched the Austin profiler to profile
that python process
and so this is a simple program which
where we're going to capture every time
we execute something this isn't called
it's called X exactly if it was
successful and if we're a Python 3
process then we're going to Output the
process ID and then I I process that to
launch the process
I was using this because I wanted to
profile uh we at canonical we deploy
software with a bunch of python code
basically that's orchestrated by a tool
called Juju and it it was launching them
and so I just wanted to profile
everything it launched without having to
modify Juju so that was a super easy way
to do that
uh here's another example uh a version
of this tool ships with BPF Trace but it
doesn't tell you the offset uh into the
disk that it was reading from and the
link that was reading so I was debugging
a ceph case and I wanted to understand
uh
where from the disk we're reading it and
at what length and then what the latency
was and so I customized that tool and
enhanced it to understand the disk
offset and unless down the disk length
and kind of output that
yeah
uh in doing so I discovered that uh the
reason Trace points are great is because
kernel developers who know much more
about that kernel subsystem have
predefined all that information and how
to get it I was using kprobe so I had to
uh
look through the data structures and
follow several structures myself to find
things like the link and the offset
um and it turns that I did that wrong in
such a way that the length and offset
looked right most of the time but
sometimes it was wrong entirely and so I
I do advise some caution if you're a
kernel developer that knows enough to be
dangerous that's me
um to maybe verify the output of of
things you've come up with if it's a
k-probe or rely on someone that maybe
knows uh some more but I've only made
that mistake once so
another tool I used in a real case
um I did a whole talk on this at LCA in
2020 uh called uh fixing Windows guests
on Seth uh
uh and a whole story on that uh in that
case what was happening is uh Linux
machines
do all their i o in four kilobyte blocks
Windows machines do it in five four five
blocks
most modern storage devices like all
their IO to be done in five tour byte
blocks sorry four kilobyte blocks not
five tour byte blocks and what was
happening was uh Windows was sending a
fire truck bike right and internally
Seth was sending that to the kernel as a
buffered i o request and the kernel only
got 512 bytes but it needed four
kilobytes because it can't send any less
than that back to the disk so in line
when it made the right call to the
kernel that you expected the kernel to
buffer in memory it wasn't even going to
wait to send it to the disk normally it
would then have to go out to the disk
read the rest of the four kilobytes pull
that in change only that 512 bytes and
then go back to the to the program it's
called a read modified write penalty
and uh we didn't realize that was
happening at the time but
what I did with this program was I'd
already narrowed down that this the P
right V system call was taking a long
time and I didn't know why
so I then went and broke down with this
program the latency of each pirate
vehicle and by which process did it and
so from that I determined that the the
tpf store op process which is like an
internal ceph thread I found that it had
these bad latencies and that was the
process that I was though I was
interested in
I had another case it was a murder
mystery there was uh something that was
randomly killing processes on the system
and I didn't know what and that's a
really hard problem to debug uh
traditionally there's no super easy way
to find out who killed what and so in
this case I attached onto every time I
generate a signal in the kernel I would
print out which process sent which
signal to which other process
and from that I was able to figure out
uh it was actually systemd killing my
process for a very complicated reason to
do with session scope management but
that's another excellent BPF Trace
example I had
and this was kind of a fun one uh that I
like
uh all that stuff before was kind of
looking at kernel stuff this is uh is
using uprobes and so what we're doing
here is we're probing the SSL library
and again on the entire system and we're
hooking into the SSL read and the SSL
right call
and when there's a call we actually read
the buffer that was passed into a cell
read and write and we actually print out
the data that the program is sending
if you've ever tried to debug like an a
https connection and you use TCP dump
all you get is the encrypted data and
sometimes you can give into your program
to like write the encryption key out to
try and decrypt that but we can just
bypass all that hook into the SSL calls
and look at the unencrypted data before
it's encrypted or after it's decrypted
this does unfortunately highlight a
current limitation of BPF Trace which is
that we can only uh
print or capture strings up to 200 bytes
and Links at most uh that is a fixable
limitation but no one's fixed it yet and
so there are there is some software ones
called ecapture which uses like Python
and go to do this and and can bypass
that limitation and print out all the
data but if you use BPF Trace to do this
you'll only get 200 bytes at a time
and as a bonus because I wanted to throw
an extra one in and number six out of
five
um I wanted to uh Trace something in the
kernel but then correlate that with the
kernel stack and in this case I was
trying to understand uh
systemd was at some point changing the
CPU set of a process that's the list of
CPUs that can run on
and I didn't know why from which
um which kind of uh you know area of
system dude was doing that so I just you
can actually Wild Card keeper
unfortunately it's not on the slide
right now but I said CPU set star
probe every CPU function in the kernel
and then print me out the user space
stack of what ultimately called it and
so I could see all the code paths and
systemd that were calling into those
functions and that let me try to figure
out you know where to go looking for for
why it was changing the CPU set in a way
that I didn't expect
foreign
so ultimately there are many different
methods of doing these things some of
the limitations I talked about like top
uh Missing things you can solve those in
different ways but the the nice thing
about BPF Trace is it lets you solve a
lot of those problems in a language
that's very kind of cis-admin friendly
you don't need to be a kernel engineer
necessarily sometimes
um
and always using the same tool rather
than like there is a version of top
called atop which uses process
accounting to kind of not miss processes
but it's very complicated so it kind of
lets you solve lots of problems in a
quick and easy way but there are a bunch
of limitations like that string length
one and so if you wanted to kind of more
advanced stuff you can still use the
same technology but in a real language
like python or go and that gives you
some more flexibility
there are other couple other related
tools I often use for this uh the perf
tool itself if you don't want to get
into BPF Trace you can kind of do a lot
with just perf itself it just doesn't do
that summarizing part for you
um and and Flame graph if you've never
heard of is a really great tool to show
you graphically uh where you're spending
CPU time which can kind of help in these
and last of all as a quick note this
concept of putting these little tiny uh
event-driven programs into the kernel
that a user defined has kind of taken
off um which some of you may or may not
have seen but now we're not just doing
packet captures or uh or tracing you can
now put entire network load balances in
the kernel custom CPU schedulers
firewall processing uh profiling
auditing
it's become like an industry so the term
BPF has become a technology and every
company that's doing uh crazy stuff
often in kubernetes is now putting all
sorts of crazy stuff in it and so if
that sounds interesting or horrifying
I'd recommend reading up on it and and
seeing what you can do
if you want to find out more there's
some resources uh here there's a couple
good books by Brendan Greg he's a very
very good resource on this topic uh
that's where to find BPF trades if your
YouTube BPF trades there are a lot more
talks that will go into a lot more depth
and that is all I have
so I believe we have oh maybe a couple
minutes or questions a little bit of
time anyone got any questions
my go-tool for this is system tap how
does BPF tracing system they're a great
question so the question uh is how to
system a system tap compared to BPF
Trace so system tap lets you do a bunch
of the same things that BPF Trace does
and has also done that for a long time
the way our system tap worked internally
is it would take a similar kind of
language it's different but kind of
similar it would then comp turn it into
C and compile it and load it as a kernel
module and so it didn't have that same
kind of like
I mean it tried to do its own safety
guarantees but it didn't have that same
implicit safety guarantee of the generic
BPF system it also required you to your
compiler kernel load a module and uh
that has become more of a problem now
with secure boot because you need to
then sign that module and that kind of
thing which you kind of avoid uh
potentially with with the BBF method but
you can solve a lot of the same problems
with with system tap
um Sonic I didn't talk about very much
was right now when your probe a user
space program that's actually a much
bigger performance penalty than the
kernel side because it does actually
trap to the kernel and back every time
one of those is hit
um system tap had a solution for that
where it would kind of push some of that
stuff into the into user space the same
thing could be done with BPF Trace but
no one's really done the work to make
that happen yet so there might be an
advantage there in some cases
okay thank you very much tread for your
time and effort it's a little gift from
us thank you very much just a little
thing people the key card for the Oaks
um accommodation hasn't been claimed so
if you're staying at one of the Oaks
venues please check that you've got your
key card because finding out when you
get there this evening is not going to
be a lot of fun all right let me go