How to trace/profile C function calls in Linux (using gcc, strace, systemtap, sysdig, ktap, lttng)

'-finstrument-functions'
  void __cyg_profile_func_enter (void *this_fn, void *call_site);
  void __cyg_profile_func_exit  (void *this_fn, void *call_site);

$ cat trace.c
#include <stdio.h>
#include <time.h>
static FILE *fp_trace;
/* GCC's constructor/destructor attributes define functions executed before/after main */
void __attribute__ ((constructor)) trace_begin (void) { fp_trace = fopen("trace.out", "w"); }
void __attribute__ ((destructor)) trace_end (void) { if(fp_trace != NULL) fclose(fp_trace); }
/* GCC's instrument-functions */
void __cyg_profile_func_enter (void *func,  void *caller) { 
    if(fp_trace != NULL) fprintf(fp_trace, "e %p %p %lun", func, caller, time(NULL) );
}
void __cyg_profile_func_exit (void *func, void *caller) {
    if(fp_trace != NULL) fprintf(fp_trace, "x %p %p %lun", func, caller, time(NULL));
}

$ gcc -finstrument-functions -g -c -o main.o main.c
$ gcc -c -o trace.o trace.c
$ gcc main.o trace.o -o main
$ ./main
foo
$ cat trace.out
e 0x400679 0x394281c40b 1286372153
e 0x400648 0x40069a 1286372153
(use 'addr2line' to map execution address to source file and line)

from Trace and profile function calls with GCC

strace [OPTIONS] command [args ...]
'-p pid' attach to the process pid and begin tracing
'-f' trace child processes created from fork
$ strace ls
execve("/bin/ls", ["ls"], [/* 21 vars */]) = 0
$ sudo strace -p `pidof firefox`
...

## filter
'-e trace=set,set' filter by syscall set (all,open,close,read,write,file,open,stat,chmod,unlink,process,network,signal,ipc)
'-e signal=set' filter by signal (all,SIGIO,...)
'-e read/write=number' filter by file descriptor number
$ strace -e trace=open,read ls
open("/etc/ld.so.cache", O_RDONLY)      = 3

## output
'-c' report stats: count time, calls, and errors for each syscall
'-t' print absolute timestamps, '-r' print relative timestamp
'-T' show time spent in syscall
$ strace -t -e open ls /home
20:42:37 open("/etc/ld.so.cache", O_RDONLY) = 3
$ strace -r ls 
    0.000000 execve("/bin/ls", ["ls"], [/* 37 vars */]) = 0
    0.000846 brk(0)                    = 0x8418000
$ strace -c ls
% time     seconds  usecs/call     calls    errors syscall
  -nan    0.000000           0         9           read

from 7 Strace Examples to Debug the Execution of a Program in Linux

## install, requires kernel 3.5 with utrace/probes
$ sudo yum install systemtap systemtap-runtime  | $ sudo apt-get install systemtap gcc
# also requires packages's -debuginfo with same build-id, e.g.: for kernel-debuginfo kernel-debuginfo-common kernel-devel

stap [OPTIONS] FILENAME [ARGS]
'-L probe' lists probe-able functions and script-level local variables
$ stap -L 'process("asterisk").function("*@manager.c")' | sort

'-e SCRIPT' runs script, where script is 
  probe PROBEPOINT [, PROBEPOINT] { [STMT ...] }
'-c CMD' start the probes, run CMD, and exit when CMD finishes
'-x PID' allows scripts to be written that filter on a specific process

## kernel and user-space probes
syscall.system_call /* e.g.: system_call.close, system_call.close.return, system_call.*.return */
kernel.function("func[@file]")  /* .call or .return */
kernel.statement("func@file:linenumber")
kernel.trace("tracepoint") /* statically marked with tracepoints */
module("module").function("function") /* similar to kernel.function */
begin,end
timer.ms(milliseconds), timer.us(microseconds), ...
process("PATH"|PID).function("func[@file]") /* similar to kernel.function */ 
process("PATH"|PID).statement("func@file:linenumber") /* similar to kernel.statement */ 
process("PATH"|PID).mark("marker") /* static markers */
process.begin, process.end, process.thread.begin, process.thread.end

## pretty printing variables, see https://sourceware.org/systemtap/langref/
$var refers to in-scope variable, supports $var->field and $val[N]
$$vars prints all local scope variables, $$vars$ expands structures, '$$vars$$' recursively
$$locals, $$params, $$return subsets of $$vars containing only local variables, function arguments and return value

## tapsets: scripts of pre-written probes

## examples
#! /usr/bin/env stap
# helloworld.stp
probe begin {
    printf ("hello world\n")
}

# func_time_stats.stp, function time stats
global start, intervals
probe $1 { start[tid()] = gettimeofday_us() }
probe $1.return {
    t = gettimeofday_us() 
    old_t = start[tid()]
    if (old_t) intervals << 1 %? if (tid() in trace) %)
    printf("%s%s%s %s\n", thread_indent (entry_p), (entry_p>0?"->":" 1 %?
global trace
probe $2.call {
    trace[tid()] = 1
}
probe $2.return {
    delete trace[tid()]
}
%)
probe $1.call   { trace(1, $$parms) }
probe $1.return { trace(-1, $$return) }

# regex.stp, prints opened files by name
probe syscall.open {
    if (filename =~ %($# == 0 %?
            "(\\.tar\\.(gz|bz2|xz)|\\.zip|\\.tgz|\\.tbz)$"
            %: @1 %) ) {
        printf ("opened %s\n", filename)
    }
}

# last_100_frees.stp, print recent free calls
global bt%[100]
probe process("/lib*/libc.so.*").function("free") {
    if (@defined($mem)) {
        bt[execname(), tid(), $mem, sprint_ubacktrace()] << %s\n", thread_indent(1), ppfunc())
}
probe kernel.function("*@net/socket.c").return {
    printf ("%s <- %s\n", thread_indent(-1), ppfunc())
}

# tcp_connections.stp, traces incoming TCP connections
probe begin {
    printf("%6s %16s %6s %6s %16s\n", "UID", "CMD", "PID", "PORT", "IP_SOURCE")
}
probe kernel.function("tcp_accept").return?, kernel.function("inet_csk_accept").return? {
    sock = $return
    if (sock != 0)
        printf("%6d %16s %6d %6d %16s\n", uid(), execname(), pid(), inet_get_local_port(sock), inet_get_ip_source(sock))
}

# tcpdumplike.stp, dump received UDP/TCP packets
probe udp.recvmsg /* ,udp.sendmsg */ {
    printf(" %15s %15s  %5d  %5d  UDP\n", saddr, daddr, sport, dport)
}
probe tcp.receive {
    printf(" %15s %15s  %5d  %5d  %d  %d  %d  %d  %d  %d\n", 
        saddr, daddr, sport, dport, urg, ack, psh, rst, syn, fin)
}

# sigmon.stp, tracks signal, usage: stap -x 31994 sigmon.stp SIGKILL
probe signal.send {
    if (sig_name == @1 && sig_pid == target())
        printf("%-8d %-16s %-5d %-16s %-6d %-16s\n", 
            pid(), execname(), sig_pid, pid_name, sig, sig_name)
}

# functioncallcount.stp, usage: stap functioncallcount.stp "*@mm/*.c"
global called
probe kernel.function(@1).call {
    called[ppfunc()] <<< 1
}
probe end {
  foreach (fn in called-)  # sort by call count (in decreasing order)
    printf("%s %d\n", fn, @count(called[fn]))
}

## systemtap initscript service, see https://sourceware.org/systemtap/man/systemtap.8.html
$ sudo yum install systemtap-initscript
$ cp script1.stp /etc/systemtap/script.d/
$ cat /etc/systemtap/conf.d/group1
script1_OPT="-o /var/log/group1.out -DRELAY_HOST=group1"
$ service systemtap restart

## '-g' guro mode, allows to embedded C within %{ ... %} and variables become writabble
    function : ( :, ... ) %{  %}
function add_one (val) %{
    STAP_RETVALUE = STAP_ARG_val + 1;
%}

## static probes, see https://sourceware.org/systemtap/wiki/AddingUserSpaceProbingToApps
$ sudo yum isnstall systemtap-sdt-devel
/* match STAP_PROBE(bar, baz ) */
probe process("foo").provider("bar").mark("baz")

## client-server probes, see http://jfsaucier.wordpress.com/tutorials-and-howto/systemtap-server-and-client/

from tutorial, guide/guide@rhel, langref, tapsets and examples

  • ktap similar to systemtap but based on bytecode, so it doesn't depend upon GCC, doesn't require compiling kernel module for each script, safe to use in production environment, fulfilling the embedded ecosystem's tracing needs.
## install
$ git clone http://github.com/ktap/ktap.git
$ cd ktap ; make ; sudo make load
$ ./ktap samples/helloworld.kp

## trace all syscalls in system
$ cat syscalls.kp
#/usr/bin/env ktap
trace syscalls:* { print(cpu(), pid(), execname(), argevent) }

## enable all tracepoints
$ ktap -e "trace *:* { print(argstr) }"

## syscall tracing on target process
$ ktap -e "trace syscalls:* { print(argstr) }" -- ls

## ftrace, http://en.wikipedia.org/wiki/Ftrace
$ ktap -e "trace ftrace:function { print(argstr) }"

## kprobe tracing, http://lwn.net/Articles/132196/
$ cat kprobe.kp
trace probe:do_sys_open dfd=%di fname=%dx flags=%cx mode=+4($stack) { print("entry:", execname, argstr) }
trace probe:do_sys_open%return fd=$retval { print("exit:", execname, argstr) }

## uprobe tracing, http://lwn.net/Articles/499190/
$ cat uprobe.kp
trace probe:/lib/libc.so.6:malloc { print("entry:", execname, argstr) }
trace probe:/lib/libc.so.6:malloc%return { print("exit:", execname, argstr) }
(stapsdt tracing - userspace static marker)

$ cat stapsdt.kp
#trace all static mark in libc
trace sdt:/lib64/libc.so.6:* { print(execname, argstr) }

from tutorial and ktap@github

  • sysdig architecture that is very similar to that of libpcap/tcpdump/wireshark: events are captured by kernel module using tracepoints, the rest (chisels) is user-space
## installing
$ curl -s https://s3.amazonaws.com/download.draios.com/stable/install-sysdig | sudo bash

## list chisels, show chisel info
$ sysdig -cl ; sysdig -i spy_port 
# list filters, to be applied to both live and trace files
$ sysdig -l

## execute a chisel on live data
$ sysdig -c bottlenecks
# or on saved/offline trace data
$ sysdig -w trace.scap ; sysdig -r trace.scap -c bottlenecks
$ sysdig -s 4096 -z -w $(hostname).scap.gz

## monitor user activity, network io amd file io
$ sysdig -r $(hostname).scap.gz -c spy_users 'user.name='
$ sysdig -s 4096 -A -c echo_fds fd.cip=192.168.0.100 -r $(hostname).scap.gz proc.name=apache2
$ sysdig -p '%user.name %proc.name %fd.name' 'evt.type=write and fd.name contains /home/' -z -w writetrace.scap.gz ; $ sysdig -r writetrace.scap.gz

from sysdig@xmodulo

  • lttng/lttng@wiki “Linux Trace Toolkit Next Generation” uses kernel modules (for Linux kernel tracing) and dynamically linked libraries (for application and library tracing), both controlled by session daemon, which receives commands from CLI.
Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s