Tracing dan Profiling

Rule udev pada chapter sebelumnya menuntaskan sisi kedatangan perangkat; sekarang kita menghadapi pertanyaan yang jauh lebih sering menghantui administrator: sistem terasa lambat, dan tidak ada pesan galat yang mau bicara. Kabar baiknya, kernel Linux menyediakan dua kaca pembesar untuk kasus ini. Tracing menjawab “apa yang terjadi, dan kapan” — ia mencatat setiap event yang lewat lengkap dengan cap waktunya, seperti rekaman CCTV. Profiling menjawab “di mana waktu dihabiskan” — ia mengambil sampel secara berkala lalu memetakan titik panasnya. Chapter ini membedah keduanya lewat ftrace dan perf, menempatkan strace pada tempatnya yang semestinya, lalu menutup dengan panduan memilih alat untuk tiap gejala.

Tracing Menjawab Kapan, Profiling Menjawab di Mana #

Bayangkan dua cara mengaudit sebuah pabrik. Tracing adalah CCTV: setiap peristiwa terekam berurutan dengan cap waktu, sehingga kita bisa memutar ulang momen sebelum mesin macet. Profiling adalah studi waktu kerja: pengamat mampir ke lantai pabrik setiap sepuluh detik dan mencatat stasiun yang sedang sibuk; dari ratusan catatan singkat itu, stasiun yang menelan waktu terbanyak terlihat sendirinya. Dua pendekatan ini melahirkan alat yang berkarakter berbeda:

Satu sistem bisa keduanya — perf bahkan punya mode tracing (perf trace) di samping mode sampling-nya. Pemisahan pentingnya ada pada pertanyaan yang kita bawa, bukan pada nama alatnya.

ftrace: Tracer yang Menempel di Kernel #

Kernel modern membawa mesin tracing lengkap bernama ftrace — bukan satu alat, melainkan kerangka: sekumpulan tracer yang bisa dipilih, ditambah antarmuka berkas di tracefs. Pada distro modern tracefs terpasang di /sys/kernel/tracing; bila kosong, ia bisa dipasang dengan mount -t tracefs (butuh root). Mengaktifkan tracer semudah menulis ke berkas sysfs: cat /sys/kernel/tracing/available_tracers mencantumkan pilihan, echo function > current_tracer mengaktifkan salah satunya, dan hasil jejaknya terbaca dari berkas trace — semuanya ring buffer per CPU, bukan berkas di disk.

Dua tracer yang paling sering dipakai untuk memahami jalur eksekusi:

1. function: mencatat setiap pemanggilan fungsi kernel yang lolos filter — sangat deras, karena itu set_ftrace_filter biasanya dipakai untuk mempersempit ke nama fungsi tertentu.
2. function_graph: seperti function, tetapi mencatat juga durasi tiap fungsi dan menggambarkan kedalaman pemanggilan lewat lekukan.

Berikut contoh tampilan function_graph saat sebuah program membuka berkas — nomor di kolom kiri adalah CPU, angka di tengah adalah durasi, dan lekukan menunjukkan hubungan induk-anak:

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
#  0)   0.100 us    |  mutex_unlock();
  0)               |  do_sys_openat2() {
  0)   0.480 us    |    getname();
  0)               |    do_filp_open() {
  0)   0.100 us    |      alloc_empty_file();
  0)   2.300 us    |    }
  0)   3.500 us    |  }

Selain kedua tracer generik itu, ftrace bisa menempel di titik-titik khusus. Tracepoint adalah penanda statis yang ditanam pengembang kernel di titik strategis — misalnya events/syscalls/sys_enter_openat/enable — dan stabil lintas versi kernel. Kprobe sebaliknya menempel dinamis di alamat fungsi mana pun, sehingga bisa melacak fungsi tanpa tracepoint, tetapi tidak dijamin namanya stabil antar versi kernel.

Membaca Jejak: Durasi per Fungsi dari Cap Waktu #

Tracer function_graph sudah menghitung durasi untuk kita. Versi mentahnya — jejak function polos — hanya mencatat cap waktu; durasi tiap fungsi harus dihitung dari selisihnya, dan penghitungan semacam itulah yang kita latih sekarang. Berkas trace-baca.txt pada bundle chapter ini berisi jejak terkompres pembukaan satu berkas: setiap baris memuat cap waktu (mikrodetik), arah enter/exit, dan nama fungsinya — persis pasangan tanda kurung pada function_graph di atas:

cat trace-baca.txt
awk '
$2 == "enter" { mulai[$3] = $1; next }
$2 == "exit"  { durasi[$3] += $1 - mulai[$3]; panggil[$3]++ }
END {
    for (f in durasi)
        printf "%3d us  %-16s %d panggilan\n", durasi[f], f, panggil[f]
}' trace-baca.txt | sort -rn

Output yang Dihasilkan:

# jejak function tracer (dipadatkan): timestamp_us arah fungsi
5012412 enter do_sys_open
5012415 enter getname
5012441 exit  getname
5012443 enter do_filp_open
5012445 enter alloc_empty_file
5012452 exit  alloc_empty_file
5012478 exit  do_filp_open
5012481 exit  do_sys_open
 69 us  do_sys_open      1 panggilan
 35 us  do_filp_open     1 panggilan
 26 us  getname          1 panggilan
  7 us  alloc_empty_file 1 panggilan

Cara kerja skrip awk di atas:

1. $2 == "enter": setiap baris jejak dibaca kolom per kolom — cap waktu, arah, nama fungsi. Fungsi yang dimasuki dicatat waktunya pada array mulai, dengan nama fungsi sebagai kunci.
2. durasi[$3] += $1 - mulai[$3]: saat baris exit tiba, durasi adalah cap waktu keluar dikurangi cap waktu masuk; operator += mengakumulasi bila satu fungsi dipanggil berkali-kali.
3. for (f in durasi): urutan pemindaian array awk tidak menentu, sehingga hasilnya diteruskan ke sort -rn agar selalu terurut dari durasi terbesar.
4. Pola angkanya: do_sys_open total 69 µs, padahal anak-anaknya hanya menempati 35 + 26 = 61 µs — durasi induk selalu mencakup durasi anak. Sisa 8 µs adalah pekerjaan si induk sendiri; konsep “durasi kumulatif” ini akan kita jumpai lagi sebagai kolom Children di perf.

perf: Mencari Titik Panas dengan Sampling #

perf adalah profiler resmi proyek kernel, dengan tiga sub-perintah yang menutup hampir semua kebutuhan. perf stat menjalankan sebuah program lalu melaporkan counter-nya — termasuk cache-miss, context switch, dan page fault dari perangkat keras. Berikut contoh tampilannya pada program kompresi gambar fiktif bernama kucing:

$ perf stat ./kucing foto.jpg

 Performance counter stats for './kucing foto.jpg':

         8.594.112.736      cycles
        14.973.204.881      instructions     #    1.74  insn per cycle
             1.204.317      cache-misses     #   14.02% of all cache refs
                 2.314      context-switches
                   412      page-faults

       1.812341 seconds time elapsed

perf record bekerja berbeda: ia menjalankan program sambil mengambil sampel — opsi -F 99 sering dipilih agar bebannya ringan sekaligus tidak selaras dengan aktivitas periodik. Dengan -g, tiap sampel membawa call chain: jejak tumpukan pemanggil hingga fungsi yang sedang berjalan. Hasilnya lalu dibaca dengan perf report; berikut cuplikan laporan --stdio milik berkas fixture di bundle:

cat laporan-perf.txt
awk 'NR > 2 { print $2, $6 }' laporan-perf.txt | sort -rn | head -3

Output yang Dihasilkan:

# Children  Self  Command  Shared Object  Symbol
# ........  ....  .......  .............  ....................
    92.10%  62.40%  kucing  kucing  [.] compress_block
    48.30%  30.20%  kucing  kucing  [.] sha256_update
    22.70%  18.10%  kucing  libc    [.] memcpy
     5.90%   5.90%  kucing  kucing  [.] main
62.40% compress_block
30.20% sha256_update
18.10% memcpy

Bedah satu baris pipeline di atas:

1. NR > 2: dua baris pertama fixture adalah kepala laporan, jadi dilewati.
2. $2 dan $6: kolom kedua adalah persentase Self dan kolom keenam adalah nama simbol — sisanya (Children, command, objek bersama) tidak kita perlukan.
3. sort -rn | head -3: mengurutkan menurun sebagai angka lalu memotong tiga teratas; hasilnya tiga titik panas yang jadi kandidat optimasi.
4. Children vs Self: kolom Children mencakup waktu anak-anak callee, persis durasi kumulatif do_sys_open pada jejak ftrace; Self murni waktu milik fungsi sendiri. compress_block memegang 62,4% Self — di situlah optimasi dimulai, bukan di main yang tampak besar di kolom Children.

Dari mana persentase itu berasal? Bukan sihir — hanya penghitungan frekuensi pada kumpulan sampel. Skrip sampler.sh pada bundle meniru kerja perf record dengan 20 sampel di stack-samples.txt, satu baris per detikan timer:

bash sampler.sh stack-samples.txt

Output yang Dihasilkan:

 55.0%  compress_block  (11/20 sampel)
 25.0%  sha256_update   (5/20 sampel)
 15.0%  memcpy          (3/20 sampel)
  5.0%  main            (1/20 sampel)

Cara membaca hasilnya:

1. Setiap baris fixture adalah satu snapshot: saat “timer” berdetak, fungsi apa pun yang sedang berjalan itulah yang tercatat — begitu pula perf menyampel nilai program counter di CPU.
2. Array asosiatif hitung mengakumulasi jumlah kemunculan tiap fungsi, lalu persentase dihitung dari jumlah / total.
3. sort -rn mengunci urutan agar keluaran selalu sama — kebiasaan yang sama seperti dua latihan sebelumnya.
4. Sampel 20 vs 20.000: compress_block muncul pada 11 dari 20 sampel karena loop kompresinya memang menguasai runtime; perf melakukan penghitungan yang sama persis, hanya pada data jauh lebih besar yang diambil dari register CPU lewat syscall perf_event_open(2) .

strace: Alat yang Tepat untuk Pertanyaan yang Berbeda #

strace sudah kita pakai pada chapter syscall untuk membongkar percakapan program dengan kernel, dan di sanalah kekuatannya: menjawab “syscalls apa saja yang dipanggil, dengan argumen apa, dan apa balasannya”. Untuk mendiagnosis kegagalan — berkas yang tidak bisa dibuka, koneksi yang ditolak — strace adalah pilihan pertama. Untuk mencari titik panas, strace justru salah alat: mekanisme ptrace di baliknya menghentikan dan melanjutkan proses pada setiap syscall, sehingga program kaya syscall bisa melambat berlipat-lipat. Angka persentase dari strace -c pun menjelaskan waktu menunggu syscall, bukan waktu CPU di dalam fungsi Anda — dua pertanyaan yang berbeda.

Flame Graph dan Panduan Memilih Alat #

Ribuan sampel ber-call chain sulit dibaca sebagai tabel — di sinilah flame graph membantu. Graf api menggambar sampel sebagai kotak bertumpuk: tinggi menunjukkan kedalaman tumpukan pemanggil, lebar menunjukkan porsi sampel, sehingga fungsi panas tampak sebagai pelataran lebar. Cara kerjanya murni agregasi — menumpuk sampel yang berbagi awal tumpukan lalu menghitung lebar masing-masing — sehingga bisa dibangun dari keluaran perf script dengan skrip penggambar seperti flamegraph.pl. Ringkasan praktis pemilihan alat berdasarkan gejala:

Alat observasi kinerja lain di Linux dirangkum di halaman Arch tentang performance monitoring . Benang merah seluruh chapter ini adalah satu keterbatasan yang tersisa: ftrace hanya menjalankan tracer yang disediakan kernel, dan perf hanya menjawab lewat sampel periodik. Begitu pertanyaan kita berubah menjadi bentuk bebas — “tampilkan durasi openat per proses” atau “hitung paket dari satu subnet” — kita butuh mesin yang menjalankan program kecil milik kita sendiri di dalam kernel, dengan jaminan tetap aman. Mesin itu bernama eBPF, dan itulah topik chapter berikutnya.

#!/bin/bash
# sampler.sh -- profiler sampling mini di atas berkas sampel.
# Setiap baris pada berkas sampel adalah satu "snapshot" stack saat timer
# berdetak -- persis data mentah yang dikumpulkan perf record lewat
# perf_event_open, sebelum dirangkum perf report menjadi persentase.
# Pemakaian: bash sampler.sh <berkas-sampel>

if [ $# -lt 1 ]; then
    exit 0
fi
berkas=$1
if [ ! -f "$berkas" ]; then
    echo "berkas sampel tidak ditemukan: $berkas"
    exit 0
fi

declare -A hitung
total=0
while IFS= read -r fungsi; do
    case $fungsi in
        ''|'#'*) continue ;;
    esac
    hitung[$fungsi]=$(( ${hitung[$fungsi]:-0} + 1 ))
    total=$(( total + 1 ))
done < "$berkas"

for fungsi in "${!hitung[@]}"; do
    printf '%s %s\n' "${hitung[$fungsi]}" "$fungsi"
done | sort -rn | awk -v total="$total" \
    '{printf "%5.1f%%  %-15s (%s/%d sampel)\n", $1 * 100 / total, $2, $1, total}'