How to trace the write system call in the Linux kernel?

Question

I am trying to do this: I am sending packet through iperf-an open source tool from one machine to another and I want to trace the write system or send call. Please help me to do that,if someone can guide through Ftrace framework to trace system call that would be great otherwise by any other tracing tool.

Answer 1

The hard part is to know exactly what to trace so you can see only the results that you want, but the tracing itself is very easy:

• First, your kernel must be configured with CONFIG_FTRACE=y

• Determine what event you want to trace

  cat /sys/kernel/debug/tracing/available_events

• Write the event that you have chosen into set_event

  echo sys_enter_write > /sys/kernel/debug/tracing/set_event

• Determine what kind of trace you want to trace

  cat /sys/kernel/debug/tracing/available_tracers

• Write the kind of trace that you want in current_tracer file

  echo function_graph > /sys/kernel/debug/tracing/current_tracer

• Enable tracing:

  echo 1 > /sys/kernel/debug/tracing/tracing_on

• Now you can run the "iperf -c... " as you wish, and disable tracing when it is done.

  echo 0 > /sys/kernel/debug/tracing/tracing_on

To see the results:

vi /sys/kernel/debug/tracing/trace

Answer 2

strace

If you are going to just trace one process, why not just use strace? It can even connect to running processes: How does strace connect to an already running process?

For ftrace, use echo none > /sys/kernel/debug/tracing/current_tracer to trace just the system calls

As of Linux 4.15 at least, if you use function_graph instead, then it shows a ton of functions in addition to the system call.

You could work around that with filtering, but it is simpler to just use nop: How to trace just system call events with ftrace without showing any other functions in the Linux kernel?

Run with sudo:

#!/bin/sh
set -eux

d=debug/tracing

mkdir -p debug
if ! mountpoint -q debug; then
  mount -t debugfs nodev debug
fi

# Stop tracing.
echo 0 > "${d}/tracing_on"

# Clear previous traces.
echo > "${d}/trace"

# Find the tracer name.
cat "${d}/available_tracers"

# Disable tracing functions, show only system call events.
echo nop > "${d}/current_tracer"

# Find the event name with.
grep write "${d}/available_events"

# Enable tracing write.
# Both statements below seem to do the exact same thing,
# just with different interfaces.
# https://www.kernel.org/doc/html/v4.18/trace/events.html
echo sys_enter_write > "${d}/set_event"
# echo 1 > "${d}/events/syscalls/sys_enter_write/enable"

# Start tracing.
echo 1 > "${d}/tracing_on"

# Generate two write calls by two different processes.
rm -rf /tmp/a /tmp/b
printf a > /tmp/a
printf b > /tmp/b

# View the trace.
cat "${d}/trace"

# Stop tracing.
echo 0 > "${d}/tracing_on"

umount debug

and a sample output:

# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
            a.sh-18135 [004] .... 11152.454767: sys_write(fd: 2, buf: 5558769acc00, count: 2)
            a.sh-18135 [004] .... 11152.454777: sys_write(fd: 2, buf: 555877f6a968, count: 2)
            a.sh-18135 [004] .... 11152.454785: sys_write(fd: 2, buf: 555877f6a968, count: 4)
            a.sh-18135 [004] .... 11152.454793: sys_write(fd: 2, buf: 555877f6a968, count: 7)
            a.sh-18135 [004] .... 11152.454801: sys_write(fd: 2, buf: 555877f6a968, count: 7)
            a.sh-18135 [004] .... 11152.454807: sys_write(fd: 2, buf: 7ffc5f3f2be7, count: 1)
 gnome-terminal--3419  [005] .... 11152.454833: sys_write(fd: 4, buf: 7ffe4f3a61c0, count: 8)
 gnome-terminal--3419  [005] .... 11152.454862: sys_write(fd: 4, buf: 7ffe4f3a61c0, count: 8)
 gnome-terminal--3419  [005] .... 11152.454887: sys_write(fd: 4, buf: 7ffe4f3a61c0, count: 8)
 gnome-terminal--3419  [005] .... 11152.454894: sys_write(fd: 4, buf: 7ffe4f3a61c0, count: 8)
           gmain-3193  [002] .... 11152.456141: sys_write(fd: 4, buf: 7fbfe5a93c40, count: 8)
           gmain-3193  [002] .... 11152.456168: sys_write(fd: 4, buf: 7fbfe5a92bd0, count: 8)
           gmain-3193  [002] .... 11152.456172: sys_write(fd: 4, buf: 7fbfe5a93c40, count: 8)
            a.sh-18135 [004] .... 11152.456534: sys_write(fd: 2, buf: 5558769acbd8, count: 2)
            a.sh-18135 [004] .... 11152.456547: sys_write(fd: 2, buf: 555877f6a968, count: 6)
            a.sh-18135 [004] .... 11152.456555: sys_write(fd: 2, buf: 555877f6a968, count: 2)
            a.sh-18135 [004] .... 11152.456561: sys_write(fd: 2, buf: 7ffc5f3f2be7, count: 1)
            a.sh-18135 [004] .... 11152.456578: sys_write(fd: 1, buf: 555877f6af00, count: 1)
 gnome-terminal--3419  [005] .... 11152.456651: sys_write(fd: 4, buf: 7ffe4f3a61c0, count: 8)
 gnome-terminal--3419  [005] .... 11152.456660: sys_write(fd: 4, buf: 7ffe4f3a61c0, count: 8)
            a.sh-18135 [004] .... 11152.456674: sys_write(fd: 2, buf: 5558769acbd8, count: 2)
            a.sh-18135 [004] .... 11152.456683: sys_write(fd: 2, buf: 555877f6a968, count: 6)
            a.sh-18135 [004] .... 11152.456690: sys_write(fd: 2, buf: 555877f6a968, count: 2)
            a.sh-18135 [004] .... 11152.456694: sys_write(fd: 2, buf: 7ffc5f3f2be7, count: 1)
            a.sh-18135 [004] .... 11152.456703: sys_write(fd: 1, buf: 555877f6af00, count: 1)
            a.sh-18135 [004] .... 11152.456738: sys_write(fd: 2, buf: 5558769acb88, count: 2)
            a.sh-18135 [004] .... 11152.456745: sys_write(fd: 2, buf: 555877f6a968, count: 3)
            a.sh-18135 [004] .... 11152.456750: sys_write(fd: 2, buf: 555877f6a968, count: 14)
            a.sh-18135 [004] .... 11152.456756: sys_write(fd: 2, buf: 7ffc5f3f2be7, count: 1)
 gnome-terminal--3419  [005] .... 11152.456816: sys_write(fd: 4, buf: 7ffe4f3a61c0, count: 8)
 gnome-terminal--3419  [005] .... 11152.456845: sys_write(fd: 4, buf: 7ffe4f3a61c0, count: 8)

As you can see, write is a very common system call, so it is difficult to isolate our two write calls. Things would be easier to see with a less common call, e.g. mkdir: How do I trace a system call in Linux?

Tested on Ubuntu 18.04, Linux kernel 4.15.