"Yes," he said, "they are quite plain: a hobbit's footprints. Pippin's I think. He is smaller than the other. And look at this!" He held up a thing that glittered in the sunlight. It looked like the new-opened leaf of a beech-tree, fair and strange in that treeless plain.
"The brooch of an elven-cloak!" cried Legolas and Gimli together.
"Not idly do the leaves of Lórien fall," said Aragorn. "This did not drop by chance: it was cast away as a token to any that might follow."
—The Two Towers, Book III, Chapter 2
One reality of working with the Linux kernel is that traditional
troubleshooting tools such as debuggers are much less accessible. Even the
printk function may be too heavyweight to be used in
time sensitive code paths such as interrupt handlers and scheduler code.
However, there are very robust tracing utilities available to the kernel
developer that allow you to record system behavior and review it after
In this studio, you will:
ftrace) via two utilities called
Please complete the required exercises below, as well as any optional enrichment exercises that you wish to complete.
As you work through these exercises, please record your answers, and when finished email your results to email@example.com with the phrase Kernel Tracing in the subject line.
Make sure that the name of each person who worked on these exercises is listed in the first answer, and make sure you number each of your responses so it is easy to match your responses with each exercise.
straceon the manual page.
Every system call listed here has a manual page entry that
will help you understand what it does. In this case, you should specify the
second chapter of the man pages, which covers system calls, since otherwise it's
possible you might get the wrong page. For example, "
will bring up the documentation for the program called
man 2 write" gives you the documentation for the system
write. See the manual pages documentation
man man") for details.
Pick out two of the system calls you see in the output from running your do-nothing program in the system call tracer, and as the answer to this exercise please describe what you think they are accomplishing in this context (based on the man page descriptions of those system calls).
straceto trace the
singprogram from the previous studio, as in:
strace ./sing 1
printf(hint: it's the one that is sending strings to the standard output stream towards the end of the trace).
strace ./dense_mm 100 &> dense100trace.txt
strace ./dense_mm 300 &> dense300trace.txt
&>operation redirects both the standard error stream and the standard output stream into a file - if you want to see the output while also sending it all to a file you can add the
teecommand to your command line.
Once you have done that, you can observe the differences between the runs by comparing
the output files, as in
diff dense100trace.txt dense300trace.txt | less
which lets you you scroll up and down to see all the places the output differs - most of the output is similar except for the relative memory addresses (since the programs likely were loaded at different base addresses), until you get to the point where the system calls that are being invoked differ.
As the answer to this exercise please say which system calls are used by each program, in the place (or places) where the sets of system calls being used are different.
mallocto allocate ten memory regions of 100 bytes each. Profile this program with
strace, and save the results to a file.
Modify your program to allocate ten memory regions of 1,000,000 (one million) bytes each. Again profile it with strace, and save the results to a file.
Compare the results files for these two different runs, and as the answer to this exercise please say which different system calls are used (in the places where the system calls that are being used are different).
ftrace(short for Function Tracer) and is a part of the Linux kernel. We will be using two utilities called
trace-cmdand Kernelshark to access the function tracer.
On your Raspberry Pi, install these utilites with the command
sudo apt-get install trace-cmd kernelshark
and as the answer to this question please say approximately how long it took for them to install on your Raspberry Pi.
sudo trace-cmd record -e sched_switch ./dense_mm 100 | less
record option specifies that we want to record a new trace. The
-e sched_switch option specifies that the event we want to trace is
invocations of the
sched_switch kernel function (which responsible
for switching processes). In addition to generating output you can scroll through
less utility, a file called "
trace.dat" is generated.
For more information, you can see the man pages at "
man trace-cmd" and
As the answer to this question, please indicate how many events were read, and how many events were dropped, on each CPU core (there are 4 cores on your Raspberry Pi).
Start by zooming in on the trace until you can make out discrete events. To zoom in: press and hold the left mouse button; drag the cursor to the right; and then release to define a zoom window. Zooming out is the reverse: press and hold the left mouse button; drag the cursor to the left; and then release the mouse button.
As the answer to this question, please give the names of at least two different processes that were running on the same core according to this trace.
dense_mmand click on the check box to activate it. Scroll down or enlarge the viewing window until you see the timeline for that process at the bottom. This timeline only shows the activity of this one process, and different colors represent execution time on different processors (red boxes on this timeline represent time where this task was not scheduled on any processor).
You can use the CPU and task timelines to see exactly how your
process executed over its lifetime. If you zoom in to where you can
see discrete events, you can mouse over those events to see exactly
which processes are switched. As the answer to this exercise, please
say which other tasks preempted the
dense_mmprocess. Look at the other three CPU cores, and as the answer to this exercise please answer the following questions. What did the other cores spend their time doing? How does the frequency of
sched_switchevents differ, either between processors or on a given processor throughout the trace?
dense_mmdoesn't create a really interesting trace because it can only use one processor at a time. Generate a new (parallel) program trace with the command
sudo trace-cmd record -e sched_switch ./parallel_dense_mm 200
stracecan be used on any binary. Try using it on common programs such as
su. You can even attach it to running programs such as the ssh authentication daemon with the
-poption. This is a great first step towards reverse engineering a binary or looking for security vulnerabilities, though we don't cover that in this course. As the answer to this exercise please explain briefly what you did and what you observed when you did that.
listoption can be used with
ftraceabout what kinds of tracers are currently available on the system. The command "
sudo trace-cmd list -e" will print out all available events. You can narrow the possible events with simple pattern matching: the command "
sudo trace-cmd list -e sched" will list all events with "sched" in their name, which includes every event in the scheduler subsystem as well as a few others. See the man page at "
man trace-cmd-list" for more info. Try this, and as the answer to this exercise please explain briefly what you saw and what you learned when doing so.
trace-cmd, and Kernelshark is extremely powerful. Try searching the documentation (or online) to find examples for doing all of the above, as well as other neat things people have done. As the answer to this exercise, please describe briefly what you found.