ftrace
Derinlemesine Kernel İzleme

00 ftrace Neden?

Kernel davranışını anlamak için en fazla başvurulan yöntem printk eklemektir; ancak bu yaklaşım yüksek overhead oluşturur, derleme gerektirir ve üretim sistemlerinde uygulanamaz. ftrace bu sınırlamaların tamamını ortadan kaldırır.

printk Maliyeti

printk çağrısı seri port veya konsol sürücüsünü tetikler; bu işlem mikrosaniyelerden milisaniyelere kadar gecikme ekleyebilir. Gerçek zamanlı sistemlerde IRQ handler içinde printk kullanmak zamanlama ölçümlerini tamamen bozar. Üstelik her eklenen printk için yeniden derleme, kurulum ve yeniden başlatma gerekir.

Ring Buffer Mekanizması

ftrace, kernel içinde kilitsiz (lock-free) ring buffer'lar kullanır. Her CPU'nun kendi ring buffer'ı vardır; bu sayede CPU arası çakışma önlenir. Tracepoint kayıt işlemi genellikle 50-100 ns aralığındadır — printk'ten 1000 kat daha hızlı.

Kernel Fonksiyon / Olay
        |
        v
ftrace ring buffer (CPU başına)
        |
        +----> /sys/kernel/tracing/trace      (anlık okuma)
        |
        +----> /sys/kernel/tracing/trace_pipe (akış okuma)
        |
        +----> trace-cmd / perf okuma (binary format)
  

Sıfır-Overhead Tracepoint'ler

Statik tracepoint'ler (TRACE_EVENT makrosu ile tanımlanmış) devre dışıyken yalnızca bir NOP talimatı olarak çalışır. Etkinleştirildiğinde kernel, NOP'u JMP ile değiştirir (text_poke ile). Bu mekanizma sayesinde devre dışı tracepoint'lerin sistemde pratik olarak sıfır maliyeti vardır.

Kernel Yapılandırması

CONFIG_FTRACE=y
CONFIG_FUNCTION_TRACER=y          # function tracer
CONFIG_FUNCTION_GRAPH_TRACER=y    # function_graph tracer
CONFIG_DYNAMIC_FTRACE=y           # dinamik etkinleştirme (NOP mekanizması)
CONFIG_KPROBES=y                  # kprobe desteği
CONFIG_KPROBE_EVENTS=y            # kprobe olay izleme
CONFIG_UPROBES=y                  # uprobe desteği
CONFIG_UPROBE_EVENTS=y            # uprobe olay izleme
CONFIG_TRACING=y
CONFIG_TRACEPOINTS=y
CONFIG_TRACE_EVENTS_ENABLED=y

01 Tracefs Altyapısı

Tracefs, ftrace ile etkileşimin temel arayüzüdür. /sys/kernel/tracing (veya eski /sys/kernel/debug/tracing) altındaki sanal dosya sistemi aracılığıyla tüm ftrace özellikleri yapılandırılır ve veriler okunur.

Temel Dizin Yapısı

Tracefs Bağlama

# Modern çekirdeklerde otomatik bağlı gelir:
mount -t tracefs tracefs /sys/kernel/tracing

# Yol kısayolu (geriye dönük uyumluluk):
ls /sys/kernel/debug/tracing   # debugfs altında ayna

# Çalışma dizinini ayarla (kolaylık için)
TRACING=/sys/kernel/tracing

Temel Kullanım Kalıbı

TRACING=/sys/kernel/tracing

# 1. Buffer temizle
echo > $TRACING/trace

# 2. Tracer seç
echo function > $TRACING/current_tracer

# 3. Buffer boyutunu artır (gömülü sistemlerde dikkatli ol)
echo 4096 > $TRACING/buffer_size_kb

# 4. İzlemeyi başlat
echo 1 > $TRACING/tracing_on

# 5. Test yükü çalıştır
my_test_program

# 6. İzlemeyi durdur
echo 0 > $TRACING/tracing_on

# 7. Sonuçları oku
cat $TRACING/trace | head -100

Önemli Performans Notu

Gömülü sistemlerde ring buffer boyutunu dikkatli ayarlayın. Her CPU için 4 MB buffer, 512 MB RAM'li bir sistemde önemli bir pay olabilir. buffer_size_kb değerini ihtiyaca göre küçültün; saved_cmdlines_size de PID-komut eşlemesi için bellek kullanır.

02 function ve function_graph Tracer

function tracer her çağrılan kernel fonksiyonunu kaydeder. function_graph ise çağrı ağacını zaman damgalarıyla birlikte gösterir; hangi fonksiyonun ne kadar süre çalıştığını görselleştirir.

function Tracer

TRACING=/sys/kernel/tracing

# function tracer'ı etkinleştir
echo function > $TRACING/current_tracer

# Yalnızca belirli fonksiyonları izle (örn: ext4 yazma yolu)
echo 'ext4_*' > $TRACING/set_ftrace_filter

# Gürültülü fonksiyonları dışla
echo 'rcu_*' > $TRACING/set_ftrace_notrace

echo 1 > $TRACING/tracing_on
# ... işlem ...
echo 0 > $TRACING/tracing_on
cat $TRACING/trace

function Tracer Çıktısı

# tracer: function
#
#           TASK-PID   CPU#  ||||  TIMESTAMP  FUNCTION
#              | |       |   ||||     |         |
       kworker-45    [001] d... 1234.567890: ext4_file_write_iter <-new_sync_write
       kworker-45    [001] d... 1234.567891: ext4_buffered_write_iter <-ext4_file_write_iter
       kworker-45    [001] d... 1234.567892: generic_perform_write <-ext4_buffered_write_iter

TIMESTAMP sütunu, sistemin başlamasından bu yana geçen saniyeyi gösterir. Latency formatı etkinleştirilirse IRQ durumu, preemption sayacı ve NEED_RESCHED bayrağı da görünür.

function_graph Tracer

# function_graph tracer'ı etkinleştir
echo function_graph > $TRACING/current_tracer

# Yalnızca belirli bir fonksiyondan başla
echo tcp_sendmsg > $TRACING/set_graph_function

# Maksimum çağrı derinliği (varsayılan: 0 = sınırsız)
echo 5 > $TRACING/max_graph_depth

echo 1 > $TRACING/tracing_on
# ...
echo 0 > $TRACING/tracing_on

function_graph Çıktısı

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 0)   0.842 us    |              _raw_spin_lock_irqsave();
 0)   0.310 us    |              _raw_spin_unlock_irqrestore();
 0)   + 14.560 us |           tcp_sendmsg_locked() {
 0)   1.042 us    |             tcp_rate_check_app_limited();
 0)   2.384 us    |             tcp_send_mss();
 0)               |             tcp_write_xmit() {
 0)   0.917 us    |               tcp_nagle_test();
 0)   + 8.124 us  |             }
 0)   + 14.560 us |           }

Latency Format Sembolleri

03 Event Tracing

Event tracing, kernel içindeki önceden tanımlanmış TRACE_EVENT noktalarını izler. Zamanlayıcı, ağ, disk I/O, bellek yönetimi gibi alt sistemler için kapsamlı izleme olanakları sunar.

Mevcut Olayları Keşfetme

TRACING=/sys/kernel/tracing

# Tüm olay kategorilerini listele
ls $TRACING/events/

# Belirli bir kategorinin olaylarını listele
ls $TRACING/events/sched/

# Tüm mevcut olayları düz liste
cat $TRACING/available_events | grep sched | head -20

Olay Etkinleştirme

# Tüm zamanlayıcı olaylarını etkinleştir
echo 1 > $TRACING/events/sched/enable

# Yalnızca belirli olayı etkinleştir
echo 1 > $TRACING/events/sched/sched_switch/enable
echo 1 > $TRACING/events/sched/sched_wakeup/enable

# IRQ olaylarını etkinleştir
echo 1 > $TRACING/events/irq/enable

# Block I/O olayları
echo 1 > $TRACING/events/block/block_rq_issue/enable
echo 1 > $TRACING/events/block/block_rq_complete/enable

Olay Formatı

# Olay formatını incele (alanlar ve türler)
cat $TRACING/events/sched/sched_switch/format

name: sched_switch
ID: 315
format:
    field:unsigned short common_type;       offset:0;  size:2; signed:0;
    field:unsigned char common_flags;       offset:2;  size:1; signed:0;
    field:int common_pid;                   offset:4;  size:4; signed:1;

    field:char prev_comm[16];               offset:8;  size:16; signed:1;
    field:pid_t prev_pid;                   offset:24; size:4;  signed:1;
    field:int prev_prio;                    offset:28; size:4;  signed:1;
    field:long prev_state;                  offset:32; size:8;  signed:1;
    field:char next_comm[16];               offset:40; size:16; signed:1;
    field:pid_t next_pid;                   offset:56; size:4;  signed:1;
    field:int next_prio;                    offset:60; size:4;  signed:1;

Olay Filtreleme

Filter sözdizimi, C koşul ifadelerine benzer biçimde alanlar üzerinde karşılaştırma yapar:

# Yalnızca pid=1234 olan sched_switch olayları
echo 'prev_pid == 1234 || next_pid == 1234' \
    > $TRACING/events/sched/sched_switch/filter

# IRQ latency filtresi (100 µs üzeri)
echo 'irq_duration > 100000' \
    > $TRACING/events/irq/irq_handler_entry/filter

# String filtresi
echo 'comm == "my_process"' \
    > $TRACING/events/sched/sched_wakeup/filter

Önemli Event Kategorileri

04 kprobe Dinamik İzleme

kprobe, herhangi bir kernel sembolüne veya belirli bir adrese çalışma anında dinamik iz noktası eklemeyi sağlar. Kaynak kodu değişikliği veya yeniden derleme gerektirmez.

kprobe_events Sözdizimi

# Temel sözdizim:
# p[:[grup/]ad] SEMBOL[+ofset] [arg1 ...]
# r[:[grup/]ad] SEMBOL[+ofset] [arg1 ...]  (dönüş noktası)

TRACING=/sys/kernel/tracing

# tcp_sendmsg girişinde izleme: uzunluk argümanı (x86_64: rdx)
echo 'p:myprobes/tcp_send tcp_sendmsg size=%dx' \
    > $TRACING/kprobe_events

# tcp_sendmsg dönüşünde: dönüş değeri
echo 'r:myprobes/tcp_send_ret tcp_sendmsg ret=$retval' \
    >> $TRACING/kprobe_events

Argüman Okuma Sözdizimi

kprobe Olayını Etkinleştirme ve Okuma

# Probe olayını etkinleştir
echo 1 > $TRACING/events/myprobes/tcp_send/enable
echo 1 > $TRACING/events/myprobes/tcp_send_ret/enable

# İzlemeyi başlat ve akışı oku
echo 1 > $TRACING/tracing_on
cat $TRACING/trace_pipe &

# ... test işlemi ...

echo 0 > $TRACING/tracing_on

# Tüm probe'ları temizle
echo > $TRACING/kprobe_events

Kernel Fonksiyon Parametrelerine Erişim

Hangi register'ın hangi parametreye karşılık geldiği sisteme ve calling convention'a göre değişir. ARM64 için:

# ARM64 calling convention:
# x0 = arg1, x1 = arg2, x2 = arg3, x3 = arg4

# do_sys_open(dfd, filename, flags, mode)
echo 'p:myprobes/open do_sys_openat2 filename=+0(%x1):string flags=%x2' \
    > $TRACING/kprobe_events

kretprobe ile Gecikme Ölçümü

# Fonksiyon giriş/çıkış çiftini tanımla
echo 'p:t/start schedule' > $TRACING/kprobe_events
echo 'r:t/end   schedule ret=$retval' >> $TRACING/kprobe_events

# Trigger ile otomatik histogram
echo 'hist:key=common_pid:val=hitcount' \
    > $TRACING/events/t/start/trigger

# Sonuçları oku
cat $TRACING/events/t/start/hist

05 uprobe Kullanıcı Alanı İzleme

uprobe, kullanıcı alanı binary'leri ve kütüphaneleri içindeki fonksiyonları kernel seviyesinde izler. ELF sembol tablosu veya USDT (User Statically Defined Tracing) noktaları kullanılabilir.

ELF Offset Hesaplama

uprobe için fonksiyonun ELF binary içindeki offset'ini bulmak gerekir:

# objdump ile sembol offset'ini bul
objdump -d /usr/bin/my_app | grep -A 3 "<my_function>"

# readelf ile sembol tablosu
readelf -s /usr/bin/my_app | grep my_function

# nm ile sembol adresi
nm -D /usr/bin/my_app | grep my_function

# Örnek çıktı: 0000000000001a40 T my_function
# Offset: 0x1a40

uprobe Tanımlama

TRACING=/sys/kernel/tracing

# p:grup/ad YOLU:OFFSET [argümanlar]
# /usr/bin/my_app içinde my_function (offset 0x1a40)
echo 'p:myuprobes/my_func /usr/bin/my_app:0x1a40' \
    > $TRACING/uprobe_events

# Geri dönüş noktası
echo 'r:myuprobes/my_func_ret /usr/bin/my_app:0x1a40 ret=$retval' \
    >> $TRACING/uprobe_events

# Etkinleştir
echo 1 > $TRACING/events/myuprobes/my_func/enable

# Belirli bir PID'e sınırla
echo PID_VALUE > $TRACING/set_event_pid

Paylaşılan Kütüphane izleme

# libc malloc fonksiyonunu izle
# malloc offset'ini bul:
readelf -s /lib/aarch64-linux-gnu/libc.so.6 | grep " malloc$"
# Örnek: 000000000007a2d0 T malloc

echo 'p:alibs/malloc /lib/aarch64-linux-gnu/libc.so.6:0x7a2d0 size=%x0' \
    > $TRACING/uprobe_events

echo 1 > $TRACING/events/alibs/malloc/enable

USDT (User Statically Defined Tracing)

USDT, kaynak koduna eklenmiş statik iz noktalarıdır. GCC/Clang sys/sdt.h başlığı ile tanımlanır:

/* Uygulama kaynak kodu */
#include <sys/sdt.h>

void process_request(int req_id, size_t size)
{
    DTRACE_PROBE2(myapp, request__start, req_id, size);
    /* ... işlem ... */
    DTRACE_PROBE1(myapp, request__end, req_id);
}

# USDT noktalarını listele
readelf -n /usr/bin/my_app | grep -A 5 NT_STAPSDT

# bpftrace ile USDT izleme
bpftrace -e 'usdt:/usr/bin/my_app:myapp:request__start {
    printf("req_id=%d size=%d\n", arg0, arg1);
}'

uprobe ile Performans Profilleme

06 trace-cmd Kullanımı

trace-cmd, ftrace'in tracefs arayüzü üzerine kurulmuş komut satırı aracıdır. İkili format kaydı, sıkıştırma ve KernelShark görselleştirme desteğiyle üretim analizini kolaylaştırır.

trace-cmd record

# Tüm zamanlayıcı olaylarını kaydet
trace-cmd record -e sched ./my_workload

# Birden fazla olay kategorisi
trace-cmd record \
    -e sched \
    -e irq \
    -e block \
    ./my_workload

# Function_graph tracer ile belirli fonksiyon
trace-cmd record \
    -p function_graph \
    -g tcp_sendmsg \
    -O nohup \
    sleep 5

# Belirli PID
trace-cmd record -e sched -P 1234 sleep 10

# Ring buffer boyutu (MB cinsinden)
trace-cmd record -b 8 -e sched sleep 5

trace-cmd report

# trace.dat dosyasını metin olarak raporla
trace-cmd report

# Belirli bir CPU'nun izini göster
trace-cmd report --cpu 0

# Zaman aralığı filtresi
trace-cmd report --start-time 1234.5 --stop-time 1234.6

# Özet istatistikler
trace-cmd report --stat

# Latency formatı
trace-cmd report -l

trace-cmd hist ile Histogram

# sched_switch gecikme histogramı
trace-cmd hist -e sched_switch

# IRQ handler süre dağılımı
trace-cmd hist -e irq_handler_exit

# Örnek çıktı:
# usecs         count    distribution
# 0 -> 1        1523   |********************|
# 2 -> 3         892   |***********         |
# 4 -> 7         234   |***                 |
# 8 -> 15         45   |                    |
# 16 -> 31          8   |                    |

Uzak Sistemden Kayıt (Gömülü Hedef)

# Hedef sistemde agent başlat (trace-cmd'in bir parçası)
trace-cmd listen -p 1234

# Geliştirme makinesinden bağlan ve kaydet
trace-cmd record \
    -N 192.168.1.100:1234 \
    -e sched \
    sleep 10

# Kayıt dosyasını al ve raporla
trace-cmd report

KernelShark Görselleştirme

KernelShark, trace-cmd verisini grafiksel olarak gösterir. Zaman çizelgesinde CPU aktivitesini, görev geçişlerini ve olayları renkli şeritlerle sunar:

# trace.dat kayıt dosyasını KernelShark ile aç
kernelshark trace.dat

# Alternatif: trace-cmd stream ile canlı görüntüleme
trace-cmd stream -e sched | kernelshark -i -

trace-cmd ile Tetikleyici Kullanımı

# Belirli bir fonksiyon çağrıldığında izlemeyi başlat
trace-cmd record \
    -e sched \
    --func-trace \
    -T start_cond_func \
    sleep 5

07 Gömülü Senaryo — IRQ ve Zamanlayıcı Analizi

Gerçek zamanlı gömülü sistemlerde IRQ gecikme analizi ve zamanlayıcı uyandırma gecikmesi kritik önemdedir. ftrace bu metrikleri ölçmek için biçilmiş kaftandır.

IRQ Gecikme Analizi

TRACING=/sys/kernel/tracing

# irqsoff tracer: IRQ devre dışı bırakılan en uzun aralığı yakala
echo irqsoff > $TRACING/current_tracer
echo 1 > $TRACING/tracing_on

# Test yükü çalıştır
./irq_latency_test

echo 0 > $TRACING/tracing_on
cat $TRACING/trace

irqsoff Çıktı Yorumlama

# irqsoff latency trace v1.1.5 on 5.15.0-rt
# -----------------
# latency: 127 us, #4/4, CPU#1 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:4)
#    -----------------
#    | task: irq/35-eth0-312 (uid:0 nice:0 policy:1 rt_prio:50)
#    -----------------
#
#                  _------=> CPU#
#                 / _-----=> irqs-off
#                | / _----=> need-resched
#                || / _---=> hardirq/softirq
#                ||| / _--=> preempt-depth
#                |||| /
#  TIME           TASK/PID     DURATION        FUNCTION CALLS
# |                 | |           |             |   |   |   |
 0.000000 |   0)  irq/35-312   |             | spin_lock_irqsave();
 0.000041 |   0)  irq/35-312   |   41 us   ! | _raw_spin_lock();
 0.000127 |   0)  irq/35-312   |  127 us   ! | spin_unlock_irqrestore();

Wakeup Latency Ölçümü

# wakeup tracer: yüksek öncelikli görevin uyanma gecikmesi
echo wakeup > $TRACING/current_tracer

# Yalnızca RT görevleri için
echo wakeup_rt > $TRACING/current_tracer

echo 1 > $TRACING/tracing_on
# Test: RT thread uyandır
./rt_wakeup_test
echo 0 > $TRACING/tracing_on
cat $TRACING/trace

PREEMPT_RT ile Karşılaştırma

Standart Kernel                    PREEMPT_RT Kernel
----------------                   -----------------
IRQ Handler (hardirq)              IRQ thread (kthread)
  |                                  |
  v                                  v
softirq / tasklet                  RT kthread (prio=50)
  |                                  |
  v                                  v
Zamanlayıcı (CFS/RT)               Zamanlayıcı (CFS/RT)

Gecikme: ~50-500 µs                Gecikme: ~20-100 µs (iyileştirilmiş)

ftrace irqsoff tracer ile ölç:
  Standart: max latency 300 µs     PREEMPT_RT: max latency 80 µs
  

Pratik Analiz Senaryo: SPI IRQ Gecikmesi

# SPI transfer tamamlanma IRQ'sından veri işlemeye kadar gecikme
# Adım 1: IRQ girişini kprobe ile izle
echo 'p:spi_irq spi_transfer_one_irq' \
    > $TRACING/kprobe_events

# Adım 2: Callback fonksiyonunu izle
echo 'p:spi_cb spi_complete_transfer' \
    >> $TRACING/kprobe_events

# Adım 3: Her ikisini etkinleştir ve kaydet
echo 1 > $TRACING/events/spi_irq/enable
echo 1 > $TRACING/events/spi_cb/enable
echo 1 > $TRACING/tracing_on

# Adım 4: Zaman farkını hesapla
trace-cmd record -e spi_irq -e spi_cb ./spi_test
trace-cmd report | awk '/spi_irq/ { t=$4 } /spi_cb/ { print $4 - t " us" }'

Scheduler Wakeup Histogram

# Histogram trigger ile otomatik gecikme dağılımı
echo 'hist:key=next_comm:val=lat:sort=lat' \
    > $TRACING/events/sched/sched_wakeup/trigger

# 10 saniye çalıştır
sleep 10

# Sonuçları oku
cat $TRACING/events/sched/sched_wakeup/hist

08 Hata Ayıklama ve Üretim Notları

ftrace gücünü doğru kullandığınızda sisteme minimal etki ederken maksimum gözlemlenebilirlik sunar. Ancak yanlış yapılandırma hem veri kaybına hem de performans sorunlarına yol açabilir.

Olay Kaybı (Lost Events)

Ring buffer dolduğunda yeni olaylar atılır. Bu durum trace_pipe okunurken görülebilir:

# Kayıp olayları kontrol et
cat /sys/kernel/tracing/per_cpu/cpu0/stats

# Örnek çıktı:
# entries: 4096
# overrun: 1523        <-- ring buffer taşması
# commit overrun: 0
# bytes: 266240
# oldest event ts: 12345.678

# Çözüm: buffer boyutunu artır
echo 16384 > /sys/kernel/tracing/buffer_size_kb

Ring Buffer Taşması ile Başa Çıkma

Tracer Overhead Ölçümü

# function tracer overhead testi (cyclictest ile)
# Önce baseline ölç
cyclictest -p 80 -t 1 -n -l 10000 --quiet > baseline.txt

# function tracer açıkken ölç
echo function > /sys/kernel/tracing/current_tracer
echo 1 > /sys/kernel/tracing/tracing_on
cyclictest -p 80 -t 1 -n -l 10000 --quiet > with_ftrace.txt
echo 0 > /sys/kernel/tracing/tracing_on
echo nop > /sys/kernel/tracing/current_tracer

# Karşılaştır
diff baseline.txt with_ftrace.txt

Üretim Ortamında ftrace

# Üretimde function tracer KULLANMAYIN -- overhead yüksek
# Bunun yerine: event tracing ve kprobe (çok daha düşük etki)

# Güvenli üretim kullanımı:
# 1. Yalnızca gerekli olayları etkinleştir
echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

# 2. İzlemeyi tamamlayınca kapat
echo 0 > /sys/kernel/tracing/tracing_on

# 3. Trace verisini hızla kopyala
cp /sys/kernel/tracing/trace /tmp/trace_$(date +%s).txt

# 4. Buffer ve filter'ları temizle
echo nop > /sys/kernel/tracing/current_tracer
echo > /sys/kernel/tracing/trace
echo > /sys/kernel/tracing/kprobe_events

Yaygın Sorunlar ve Çözümleri

Hızlı Başvuru Kartı

T=/sys/kernel/tracing

# Sıfırla
echo nop > $T/current_tracer; echo > $T/trace

# function tracer -- belirli fonksiyon
echo function > $T/current_tracer
echo my_func   > $T/set_ftrace_filter
echo 1 > $T/tracing_on; YOUR_CMD; echo 0 > $T/tracing_on
cat $T/trace

# function_graph -- çağrı ağacı
echo function_graph > $T/current_tracer
echo my_func        > $T/set_graph_function
echo 1 > $T/tracing_on; YOUR_CMD; echo 0 > $T/tracing_on

# Event izleme
echo 1 > $T/events/sched/sched_switch/enable
echo 1 > $T/tracing_on; YOUR_CMD; echo 0 > $T/tracing_on

# kprobe
echo 'p:t/f my_func arg=%x0' > $T/kprobe_events
echo 1 > $T/events/t/f/enable