dtrace, ftrace, ltrace, strace .. so many to choose from !

Vicente-Cheng has been asking questions about some curious kernel
messages when dtrace is loaded into the kernel, and it seems like a good
topic to cover in more detail. So, here is his question:


The dtrace_xcall code patch failed. (Actually, I don't know how you know that from log.)
by this description?
"ftrace failed to modify [ffffffffa04cdd44] dtrace_xcall+0x4/0x28 [dtracedrv]"

The ftrace module will got something wrong when dtrace kernel module loading.

The tainted kernel is normal because of the different license (GPL & CDDL).


Lets do a little history lesson.

In the beginning, Solaris gave rise to a tool called "truss". "truss"
is a tool for tracing system calls. It was a breakthrough tool (versions
for other OS's existed previously, but the truss implementation was simple
and easy to use; BSD kernels had there own tool .. but I digress). truss
lets you understand what calls a tool makes and you can see
the parameters to the syscall. Great for educational purposes or for
diagnosing performance problems in an application.

On Linux systems (and other Unixes), strace was created to emulate
truss - a system call tracing tool.

"ltrace" is another tool, which can be used to trace any dynamic
library function call. Sometimes very useful, but at the library
level, the number of calls executed can be huge - something as simple
as starting an X Windows program can involve lots of nested calls
to fopen, string library and other calls - but because of the level
of detail - they can make it hard to understand what an application is
doing.

A few years back - dtrace was born. dtrace is a tracing tool which
runs at the system level - this means you can trace all processes, into
and out of the kernel, rather than selecting a single process to trace.

There are two common modes of operation: trace system calls (you
can see who executes the call - rather than with strace/truss, you pick
a single process and see what calls it does), and you can trace
kernel function calls (seeing which process triggers the trace).
[dtrace does other things, such as tracing user land shared libraries,
just like ltrace, but again, you can find which processes invoke a function
rather than knowing up front, which one to trace].

When tracing in the kernel (and user space), the basic mechanism is
that of a breakpoint: one or more breakpoint instructions are placed
at the places you choose (using the dtrace probes syntax), and
dtrace converts these breakpoint traps into the events and callbacks that
a D script can trigger on.

DTrace works at the function level: you pick a function to trace and
dtrace computes the start of the function (very easy - the symbol table
gives us the start address of each function), and also, the (multiple)
end addresses of a function. (Each function can have multiple exit
points, so dtrace needs to "find" each of these). Finding the exit
points of a function involves disassembling the function and trapping
the RET instruction. (Solaris/dtrace traps the LEAVE instruction which
preceeds the RET instruction, but this is not very useful on Linux, when
using gcc, since the compiler rarely emits a LEAVE/RET instruction sequence).

Its possible for the disassembler to get confused and Linux's dtrace
is tuned for the type of output typical from gcc. It can result in not
finding the end part of a function or getting confused by inlined
constant tables (gcc used to create switch-statement jump tables
and inline them in the code body; fortunately, it no longer does this - all
read-only data is put in its own ELF section, and code in memory is exactly
that -- code -- nothing else).

dtrace needs to intercept loadable kernel modules - so that it can expose
tracable functions, and, intercept module unloading - otherwise it
could leave a trap exposed in a part of memory that is freed or used
for something else.

Lets switch to ftrace: ftrace is a Linux kernel subsystem, similar to dtrace,
and an integral part of the kernel. Because of licensing conflicts between
dtrace, ftrace exists in its own right. It works similarly to dtrace - intercepting
module loads and letting you place traps in the kernel. (ftrace is
different in many respects to dtrace - it provides a richer API
for kernel tracing, but it can allow dangerous user scripts to crash
the kernel).

ftrace is quite vocal - if it detects anything it cannot handle in a loadable
module, it will log a message - indicating what and why it couldnt
handle the instruction sequence it meets. This results in a kernel log
message, such as the following, when dtrace is loaded:

[  357.679832] WARNING: at kernel/trace/ftrace.c:1509 ftrace_bug+0x28f/0x2e0()
[  357.679834] Hardware name: VirtualBox
[  357.679835] Modules linked in: dtracedrv(PO+) lockd sunrpc be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i cxgb4 cxgb3i cxgb3 mdio libcxgbi ib_iser rdma_cm ib_addr iw_cm ib_cm ib_sa ib_mad ib_core iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ppdev snd_intel8x0 parport_pc parport i2c_piix4 i2c_core e1000 snd_ac97_codec microcode ac97_bus snd_pcm snd_page_alloc snd_timer snd soundcore uinput [last unloaded: scsi_wait_scan]
[  357.679855] Pid: 2350, comm: insmod Tainted: P           O 3.3.1-3.fc17.x86_64 #1
[  357.679857] Call Trace:
[  357.679862]  [] warn_slowpath_common+0x7f/0xc0
[  357.679866]  [] ? __probe_kernel_read+0x46/0x70
[  357.679874]  [] ? ctf_hash_size+0x4/0x20 [dtracedrv]
[  357.679881]  [] ? ctf_hash_size+0x4/0x20 [dtracedrv]
[  357.679883]  [] warn_slowpath_null+0x1a/0x20
[  357.679885]  [] ftrace_bug+0x28f/0x2e0
[  357.679888]  [] ftrace_process_locs+0x39c/0x560
[  357.679891]  [] ftrace_module_notify+0x47/0x50
[  357.679895]  [] notifier_call_chain+0x4d/0x70
[  357.679898]  [] __blocking_notifier_call_chain+0x58/0x80
[  357.679901]  [] blocking_notifier_call_chain+0x16/0x20
[  357.679904]  [] sys_init_module+0x10a3/0x20b0
[  357.679906]  [] system_call_fastpath+0x16/0x1b
[  357.679908] ---[ end trace 54106b526adf7ab1 ]---
[  357.679909] ftrace failed to modify [] ctf_hash_size+0x4/0x20 [dtracedrv]
[  357.679915]  actual: e8:0f:62:03:00

Here, the code in ftrace.c at line 1509, is complaining.
Its not obvious what its complaining about, but the last two lines
highlight what ftrace was confused about. The "actual" message
shows the instruction it didnt like. Those bytes correspond to:

e8 0f 62 03 00          call   0x00036214

I dont know what it doesnt like about that, but it is possibly suggesting
that ftrace, in computing the call-graph of the kernel, may have found
a code path which could result in a kernel hang (this might be
dtrace violating a kernel API constraint, or, because ftrace doesnt
realise how dtrace works).

To date, I have not observed any side effect of this warning (I havent
tried to use ftrace on a system running dtrace, so its possible that
ftrace or dtrace may cause a hang, when they are enabled, together).

By the way - always treat kernel stack traces (such as this) or
even from dtrace itself, with suspicion. Because of the way GCC
compiles code, it is not possible to create a 100% accurate stack
trace in all scenarios. The stack walker looks at all the words on the
stack and lists out potentially likely active stack frames. (The "?"
marks in the trace show the stack walker highlighting definitely questionable
stack boundaries; walking the stack has enough gotchas and complexity that
maybe I will return to the subject in a future blog topic).



Post created by CRiSP v10.0.31a-b6267