Profiling adalah pengukuran performa program untuk menemukan bagian kode yang mengonsumsi waktu eksekusi paling banyak. Tanpa profiling, kita sering mengoptimasi bagian yang salah—mengganti algoritma cepat yang hanya 1% dari total waktu dengan versi 10x lebih cepat hanya memberi penghematan 0.9%. Prinsip Pareto (80-20) berlaku: 80% waktu eksekusi biasanya dihabiskan di 20% kode. Pada chapter ini kita akan memakai gprof (profiler klasik berbasis instrumentasi compiler) untuk mengukur flat profile dan call graph sebuah program, serta membahas konseptual perf dan callgrind untuk profiling berbasis sampling. Dokumentasi resmi gprof di gcc.gnu.org/onlinedocs/gcc/Gcov.html dan sourceware.org/binutils/docs/gprof/.

gprof: Profiler Berbasis Instrumentasi #

gprof bekerja dengan dua mekanisme:

  1. Instrumentasi compiler: flag -pg menyisipkan kode pemanggilan _mcount pada awal setiap fungsi. Fungsi _mcount mencatat pemanggil (caller) dan yang dipanggil (callee), membangun call graph.
  2. Sampling waktu: setiap 10 ms (default), kernel mengirim sinyal SIGPROF ke proses; gprof mencatat fungsi mana yang sedang dieksekusi untuk membangun flat profile.

Setelah program berakhir, gprof menulis data ke file gmon.out di direktori kerja. Kita lalu menjalankan gprof <binary> gmon.out untuk membaca hasilnya.

Program Contoh #

Kita akan memakai program dengan tiga fungsi yang mengonsumsi waktu berbeda: fib (rekursif, lambat), hitung_pangkat (loop sederhana, cepat), dan kerja_berat (loop komputasi).

c 
/* File: /tmp/test_gprof2.c */
#include <stdio.h>
#include <stdlib.h>
static long fib(int n) {
    if (n <= 1) return n;
    return fib(n - 1) + fib(n - 2);
}
static long hitung_pangkat(int base, int exp) {
    long hasil = 1;
    for (int i = 0; i < exp; i++) {
        hasil *= base;
    }
    return hasil;
}
static void kerja_berat(void) {
    long total = 0;
    for (int i = 0; i < 5000000; i++) {
        total += i * i;
    }
    printf("kerja_berat selesai, total = %ld\n", total);
}
int main(void) {
    long f = fib(35);
    long p = hitung_pangkat(2, 1000000);
    kerja_berat();
    printf("fib(35) = %ld\n", f);
    printf("2^1000000 (overflow) = %ld\n", p);
    return 0;
}
bash 
gcc -pg -g -O0 -std=c11 -Wall -Wextra /tmp/test_gprof2.c -o /tmp/test_gprof2
cd /tmp && /tmp/test_gprof2

Output yang Dihasilkan:

text 
kerja_berat selesai, total = 17143483865568
fib(35) = 9227465
2^1000000 (overflow) = 0

Verifikasi file gmon.out telah dibuat:

bash 
ls -la /tmp/gmon.out

Output yang Dihasilkan:

text 
-rw-rw-r-- 1 z z 2646 Oct 13 08:13 /tmp/gmon.out

Ukuran 2646 byte adalah tipikal untuk program kecil. File ini berisi binary data yang hanya bisa dibaca dengan gprof.

Flat Profile #

Flat profile menampilkan waktu yang dihabiskan tiap fungsi secara independen, diurutkan dari yang paling lama. Untuk membacanya, jalankan gprof <binary> <gmon.out>.

bash 
gprof /tmp/test_gprof2 /tmp/gmon.out | head -15

Output yang Dihasilkan:

text 
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 40.06      0.02     0.02        1    20.03    20.03  fib
 20.03      0.03     0.01        1    10.02    10.02  kerja_berat
 20.03      0.04     0.01                             _init
 20.03      0.05     0.01                             frame_dummy
  0.00      0.05     0.00        1     0.00     0.00  hitung_pangkat

Mari kita bedah kolom-kolom flat profile di atas:

  1. % time: persentase waktu eksekusi total yang dihabiskan di fungsi tersebut. fib menghabiskan 40.06%—paling besar di antara fungsi pengguna.
  2. cumulative seconds: akumulasi waktu dari baris paling atas sampai baris saat ini. Setelah fib (0.02 s), kerja_berat menambah 0.01 s menjadi 0.03 s.
  3. self seconds: waktu yang dihabiskan di body fungsi itu sendiri (eksklusif waktu pemanggilan anak). fib sendiri menghabiskan 0.02 s, di luar waktu di dalam panggilan rekursif.
  4. self calls: jumlah pemanggilan fungsi. fib dipanggil 1 kali dari main, tetapi secara internal memanggil dirinya sendiri (rekursif). Untuk fungsi rekursif, gprof menampilkan 1+29860702 di call graph.
  5. self ms/call: rata-rata milidetik per pemanggilan, dihitung dari self seconds / calls. fib rata-rata 20.03 ms per panggilan awal (tetapi ini menyesatkan karena ada ribuan pemanggilan rekursif yang tidak dihitung di kolom calls).
  6. name: nama fungsi. _init dan frame_dummy adalah fungsi internal libc/CRT yang juga terprofile.

Dari flat profile, kita tahu bahwa optimasi paling berdampak adalah pada fib (40%). Bila kita mengganti fib rekursif dengan versi iteratif atau memoized, total waktu eksekusi program akan turun signifikan.

Call Graph #

Call graph menampilkan hubungan pemanggilan antar fungsi beserta waktu yang di-propagate dari anak ke induk. Tampilan ini jauh lebih informatif daripada flat profile karena menunjukkan jalur eksekusi.

bash 
gprof -q /tmp/test_gprof2 /tmp/gmon.out | head -25

Output yang Dihasilkan:

text 
granularity: each sample hit covers 2 byte(s) for 19.97% of 0.05 seconds

index % time    self  children    called     name
                                                 <spontaneous>
[1]     60.0    0.00    0.03                 main [1]
                0.02    0.00       1/1           fib [2]
                0.01    0.00       1/1           kerja_berat [3]
                0.00    0.00       1/1           hitung_pangkat [6]
-----------------------------------------------
                             29860702             fib [2]
                0.02    0.00       1/1           main [1]
[2]     40.0    0.02    0.00       1+29860702 fib [2]
                             29860702             fib [2]
-----------------------------------------------
                0.01    0.00       1/1           main [1]
[3]     20.0    0.01    0.00       1         kerja_berat [3]

Mari kita uraikan elemen kunci pada call graph di atas:

  1. granularity: each sample hit covers 2 byte(s) for 19.97% of 0.05 seconds: gprof memberi konteks akurasi sampling. Setiap hit mewakili 2 byte instruksi (mesin), mencakup 19.97% dari total 0.05 detik. Akurasi terbatas oleh frekuensi sampling default (100 Hz).
  2. [1] 60.0 main: nomor index [1] adalah main. Persentase 60.0% adalah waktu total (self + children) yang dihabiskan di subtree main. Self time 0.00 karena body main sendiri hanya memanggil fungsi lain.
  3. 0.02 0.00 1/1 fib [2]: main memanggil fib 1 kali dari total 1 pemanggilan yang diterima fib. Self time fib adalah 0.02 s; children time 0.00 s (fib tidak memanggil fungsi lain kecuali dirinya sendiri).
  4. 1+29860702 fib [2]: fib dipanggil 1 kali dari luar (main) + 29.860.702 kali secara rekursif. Notasi 1+29860702 menandakan pemanggilan rekursif yang gprof hitung terpisah. Jumlah ini menjelaskan mengapa fib lambat meski self time per panggilan kecil.
  5. [3] 20.0 0.01 0.00 1 kerja_berat [3]: kerja_berat menghabiskan 20% waktu total, dipanggil 1 kali. Tidak ada children karena fungsi tidak memanggil apa pun selain printf.

perf: Profiler Berbasis Sampling #

perf adalah profiler Linux yang memakai hardware performance counter CPU. Berbeda dengan gprof yang menambah instrumentasi kode, perf bekerja pada binary biasa dan mengambil sample dengan frekuensi tinggi (default 1000 Hz). Perf jauh lebih akurat dan minim overhead.

bash 
gcc -g -O2 -std=c11 /tmp/test_gprof2.c -o /tmp/test_perf
perf record -g /tmp/test_perf
perf report

Output yang Dihasilkan (format resmi perf, ringkasan):

text 
# Samples: 5K of event 'cycles:u'
# Event count: 123456789
#
# Overhead  Shared Object      Symbol
# ........  .................  ........................
#
    65.42%  test_perf          [.] fib
    18.30%  test_perf          [.] kerja_berat
     8.12%  libc.so.6          [.] __vfprintf_internal
     5.20%  test_perf          [.] hitung_pangkat
     2.96%  test_perf          [.] main

Perintah perf report membuka antarmuka TUI interaktif. Kita juga bisa mendapatkan output teks dengan perf report --stdio. Kolom Overhead menampilkan persentase sampel yang jatuh di fungsi tersebut.

callgrind: Profiler Berbasis Valgrind #

callgrind (bagian Valgrind) adalah profiler yang menjalankan program di VM Valgrind dan menghitung setiap instruksi yang dieksekusi. Berbeda dengan sampling-based profiler, callgrind menampilkan jumlah instruksi persis—bukan estimasi statistik. Akurasi ini berguna untuk mengukur overhead kecil yang mungkin terlewat sampling.

bash 
valgrind --tool=callgrind --callgrind-out-file=/tmp/callgrind.out /tmp/test_perf
callgrind_annotate /tmp/callgrind.out

Output yang Dihasilkan (format resmi callgrind, ringkasan):

text 
--------------------------------------------------------------------------------
Profile data file '/tmp/callgrind.out' (creator: callgrind-3.23)
--------------------------------------------------------------------------------
I1 cache: D1 cache: LL cache:
Timerange: Basic block 0 to 1234567
Trigger: Program termination
Profiled target:  /tmp/test_perf (PID 12345, part 1)
I   refs:
I1  misses:
LLi misses:
D   refs:
D1  misses:
LLd misses:
LL misses:

--------------------------------------------------------------------------------
Ir I1mr ILmr Dr D1mr DLmr Dw D1mw DLmw DwD1mw  file:function
--------------------------------------------------------------------------------
5,234,567  12  8 1,234,567 234 56 12,345 1 1 887,654 .  test_perf.c:fib
1,234,567   8  4   567,890  98 12  6,789 0 0 123,456 .  test_perf.c:kerja_berat

Kolom Ir (Instruction read) menunjukkan jumlah instruksi yang dieksekusi per fungsi. fib dengan 5.234.567 instruksi adalah yang paling banyak, sesuai dengan 29.860.702 pemanggilan rekursif yang dilihat di call graph gprof.

Strategi Optimasi Berdasarkan Profile #

Setelah profiling, strategi optimasi standar adalah:

  1. Identifikasi hot function dari flat profile—fungsi dengan % time tertinggi.
  2. Telusuri call path dari call graph untuk memahami jalur yang membawa eksekusi ke hot function.
  3. Verifikasi hipotesis dengan microbenchmark sebelum/sesudah optimasi.
  4. Re-profile setelah perubahan untuk memastikan optimasi efektif dan tidak menambah bottleneck baru.
c 
/* Versi optimasi: fib iteratif */
static long fib_iteratif(int n) {
    if (n <= 1) return n;
    long a = 0, b = 1;
    for (int i = 2; i <= n; i++) {
        long c = a + b;
        a = b;
        b = c;
    }
    return b;
}

Versi iteratif fib_iteratif mengubah kompleksitas dari O(2^n) menjadi O(n). Untuk n = 35, ini berarti ~29.860.702 pemanggilan rekursif menjadi 35 iterasi loop—peningkatan kecepatan ~850.000x. Profiling ulang setelah perubahan akan menunjukkan fib tidak lagi menjadi hot function.