awk ile Uygulama Performans Loglarından Yüzdelik Dilim ve Yanıt Süresi Dağılımı Analizi

Yazar:komut.io ekibi Metin İşleme Komutları (grep, awk, sed)
0 Yorum

Prodüksiyon ortamında bir servis yavaşladığında, ilk içgüdü genellikle ortalama yanıt sürelerine bakmak olur. Ama ortalama, sizi yanıltır. 999 isteğin 10ms’de tamamlandığı, birinin 10 saniye sürdüğü bir sistemde ortalama hâlâ “iyi” görünebilir. İşte bu yüzden yüzdelik dilimler (percentile) gerçek hayatta çok daha anlamlı. P95, P99 değerleri olmadan bir servisin gerçek performansını anlamak mümkün değil. Bu yazıda, production log dosyalarından sadece awk kullanarak nasıl anlamlı percentile analizleri çıkarabileceğinizi göstereceğim.

Neden awk?

Python, R, Elasticsearch, Grafana… Bunların hepsi harika araçlar. Ama bir müşteri şikayeti geldiğinde, SSH açıp log sunucusuna bağlandığınızda, elinizin altında sadece terminal varken ne yaparsınız? awk her Linux sisteminde var, bağımlılığı yok, büyük dosyalarda bile şaşırtıcı derecede hızlı çalışıyor. Birkaç satır awk kodu ile gigabaytlık log dosyalarını dakikalar içinde analiz edebilirsiniz.

Ayrıca şunu da söyleyeyim: awk öğrenmek sizi farklı bir seviyeye taşır. Sadece log analizi için değil, metin işlemenin her alanında. Yıllarca sistem yöneticiliği yapıp awk‘ı yüzeysel kullanan insanlar gördüm. O potansiyeli boşa harcamak yazık olur.

Log Formatını Tanımak

Önce ne tür loglarla çalışacağımızı netleştirelim. Nginx access log formatı tipik olarak şöyle görünür:

192.168.1.45 - - [12/Jan/2025:14:23:01 +0300] "GET /api/v2/users HTTP/1.1" 200 1423 0.045
192.168.1.12 - - [12/Jan/2025:14:23:02 +0300] "POST /api/v2/orders HTTP/1.1" 201 892 0.823
192.168.1.78 - - [12/Jan/2025:14:23:02 +0300] "GET /api/v2/products HTTP/1.1" 200 5421 0.012

Buradaki son alan (0.045, 0.823, 0.012) saniye cinsinden yanıt süresi. Nginx konfigürasyonunuzda $request_time ile bu değeri log formatına eklemeniz gerekiyor. Eğer henüz eklemediyseniz, şimdi tam zamanı.

Uygulama logları farklı formatlarda olabilir. Mesela bir Java uygulamasının custom log formatı:

2025-01-12 14:23:01 INFO  RequestFilter - method=GET path=/api/users status=200 duration_ms=45 user_id=1234
2025-01-12 14:23:02 INFO  RequestFilter - method=POST path=/api/orders status=201 duration_ms=823 user_id=5678
2025-01-12 14:23:03 INFO  RequestFilter - method=GET path=/api/products status=200 duration_ms=12 user_id=9012

Her iki format için de örnekler vereceğim. Konsept aynı, sadece alan ayrıştırma değişiyor.

Temel Yanıt Süresi Çıkarımı

İlk adım, log dosyasından sadece yanıt sürelerini çıkarmak. Nginx formatı için:

awk '{print $NF}' /var/log/nginx/access.log | sort -n > /tmp/response_times.txt

$NF son alanı verir. Ama dikkat: Bazı log satırlarında son alan farklı bir şey olabilir. Daha güvenli bir yaklaşım:

awk '
  /^[0-9]/ {
    # Son alanın sayısal değer olduğunu kontrol et
    if ($NF ~ /^[0-9]+.?[0-9]*$/) {
      print $NF
    }
  }
' /var/log/nginx/access.log | sort -n > /tmp/response_times.txt

Java uygulama logu için duration_ms değerini çıkaralım:

awk '
  /duration_ms=/ {
    for (i=1; i<=NF; i++) {
      if ($i ~ /^duration_ms=/) {
        split($i, arr, "=")
        print arr[2]
      }
    }
  }
' /var/log/app/application.log | sort -n > /tmp/response_times.txt

Percentile Hesaplama Mantığı

Percentile hesaplamanın birkaç yöntemi var. En yaygın kullanılan “nearest rank” yöntemi şu şekilde çalışır: P95 için toplam veri sayısını 0.95 ile çarpıp en yakın tam sayıya yuvarlıyorsunuz. O indeksteki değer P95’iniz oluyor.

awk ile bu hesaplamayı tek geçişte yapmak için önce tüm değerleri bir diziye yüklemek gerekiyor:

awk '
BEGIN {
  count = 0
}
{
  values[count++] = $1 + 0
}
END {
  if (count == 0) {
    print "Veri bulunamadi"
    exit
  }
  
  # Percentile hesaplama fonksiyonu
  # Not: Dizi zaten sort -n ile siralandi
  
  p50_idx  = int(count * 0.50)
  p75_idx  = int(count * 0.75)
  p90_idx  = int(count * 0.90)
  p95_idx  = int(count * 0.95)
  p99_idx  = int(count * 0.99)
  p999_idx = int(count * 0.999)
  
  # Sinir kontrolu
  if (p50_idx  >= count) p50_idx  = count - 1
  if (p75_idx  >= count) p75_idx  = count - 1
  if (p90_idx  >= count) p90_idx  = count - 1
  if (p95_idx  >= count) p95_idx  = count - 1
  if (p99_idx  >= count) p99_idx  = count - 1
  if (p999_idx >= count) p999_idx = count - 1
  
  printf "Toplam istek : %dn", count
  printf "Minimum      : %.3f msn", values[0]
  printf "P50 (medyan) : %.3f msn", values[p50_idx]
  printf "P75          : %.3f msn", values[p75_idx]
  printf "P90          : %.3f msn", values[p90_idx]
  printf "P95          : %.3f msn", values[p95_idx]
  printf "P99          : %.3f msn", values[p99_idx]
  printf "P99.9        : %.3f msn", values[p999_idx]
  printf "Maksimum     : %.3f msn", values[count-1]
}
' /tmp/response_times.txt

Bu scripti çalıştırdığınızda şuna benzer bir çıktı alırsınız:

Toplam istek : 48291
Minimum      : 1.000 ms
P50 (medyan) : 34.000 ms
P75          : 89.000 ms
P90          : 187.000 ms
P95          : 342.000 ms
P99          : 891.000 ms
P99.9        : 2341.000 ms
Maksimum     : 15823.000 ms

P50 ile P99 arasındaki farka bakın. Ortalama size muhtemelen 60-70ms gibi makul bir değer gösterirdi. Ama %1’lik kullanıcı kitleniz 891ms bekliyordu. Yüksek trafikli bir serviste bu, her 100 kullanıcıdan birinin kötü deneyim yaşaması demek.

Endpoint Bazında Analiz

Gerçek dünyada “genel P99 kötü” demek yeterli değil. Hangi endpoint problemli? Bunu bulmak için gruplama yapmanız gerekiyor:

awk '
{
  # Nginx log formatı: IP - - [tarih] "METHOD /path HTTP/version" status bytes time
  # $7 = path, $NF = response time
  
  # Sorgu parametrelerini temizle
  path = $7
  gsub(/?.*/, "", path)
  
  # Veriyi topla
  times[path][counts[path]++] = $NF + 0
  sum[path] += $NF + 0
}
END {
  for (path in counts) {
    n = counts[path]
    
    # Basit bubble sort (kucuk veri setleri icin)
    # Buyuk veri setleri icin once sort | awk yapisi tercih edin
    do {
      swapped = 0
      for (i = 0; i < n-1; i++) {
        if (times[path][i] > times[path][i+1]) {
          tmp = times[path][i]
          times[path][i] = times[path][i+1]
          times[path][i+1] = tmp
          swapped = 1
        }
      }
    } while (swapped)
    
    p95_idx = int(n * 0.95)
    p99_idx = int(n * 0.99)
    if (p95_idx >= n) p95_idx = n - 1
    if (p99_idx >= n) p99_idx = n - 1
    
    avg = sum[path] / n
    
    printf "%-40s istek:%-6d avg:%-8.1f p95:%-8.1f p99:%.1fn",
           path, n, avg, times[path][p95_idx], times[path][p99_idx]
  }
}
' /var/log/nginx/access.log | sort -k5 -t: -rn | head -20

Önemli not: Bu yaklaşım, her endpoint için tüm değerleri bellekte tutar. Çok sayıda farklı path ve milyonlarca log satırı varsa bellek sorunuyla karşılaşabilirsiniz. Bu durumda, önce endpoint’e göre gruplayıp sonra analiz etmek daha sağlıklı:

# Önce endpoint ve süreleri çıkar, endpoint'e göre sırala
awk '{gsub(/?.*/, "", $7); print $7, $NF}' /var/log/nginx/access.log 
  | sort -k1,1 -k2,2n 
  | awk '
BEGIN { current_path = ""; count = 0 }
{
  if ($1 != current_path) {
    if (current_path != "" && count > 0) {
      p95_idx = int(count * 0.95)
      p99_idx = int(count * 0.99)
      if (p95_idx >= count) p95_idx = count - 1
      if (p99_idx >= count) p99_idx = count - 1
      printf "%-45s cnt:%-6d p95:%-8.3f p99:%.3fn",
             current_path, count, values[p95_idx], values[p99_idx]
    }
    current_path = $1
    count = 0
    delete values
  }
  values[count++] = $2 + 0
}
END {
  if (current_path != "" && count > 0) {
    p95_idx = int(count * 0.95)
    p99_idx = int(count * 0.99)
    if (p95_idx >= count) p95_idx = count - 1
    if (p99_idx >= count) p99_idx = count - 1
    printf "%-45s cnt:%-6d p95:%-8.3f p99:%.3fn",
           current_path, count, values[p95_idx], values[p99_idx]
  }
}
'

Bu yaklaşım çok daha bellek verimli çünkü her seferinde sadece bir endpoint’in verilerini tutuyor.

Zaman Bazlı Percentile Analizi

“Dün gece saat kaçta performans düştü?” sorusuna cevap vermek için saatlik percentile analizi çok işe yarıyor:

awk '
{
  # [12/Jan/2025:14:23:01 +0300] formatından saat çıkar
  match($4, /([0-9]{2}:[0-9]{2})/, arr)
  # Sadece saati al (dakika bazında cok granüler olur)
  split(arr[1], time_parts, ":")
  hour = time_parts[1]
  
  response_time = $NF + 0
  
  data[hour][hour_count[hour]++] = response_time
  hour_sum[hour] += response_time
}
END {
  print "Saat | Istek | Ort(ms) | P95(ms) | P99(ms)"
  print "-----+-------+---------+---------+--------"
  
  n_hours = asorti(hour_count, sorted_hours)
  
  for (h = 1; h <= n_hours; h++) {
    hour = sorted_hours[h]
    n = hour_count[hour]
    
    # Siralama (bu ornekte kucuk veri seti varsayilmistir)
    for (i = 0; i < n-1; i++) {
      for (j = i+1; j < n; j++) {
        if (data[hour][i] > data[hour][j]) {
          tmp = data[hour][i]
          data[hour][i] = data[hour][j]
          data[hour][j] = tmp
        }
      }
    }
    
    p95_idx = int(n * 0.95)
    p99_idx = int(n * 0.99)
    if (p95_idx >= n) p95_idx = n - 1
    if (p99_idx >= n) p99_idx = n - 1
    
    printf " %s  | %5d | %7.1f | %7.1f | %6.1fn",
           hour, n, hour_sum[hour]/n, data[hour][p95_idx], data[hour][p99_idx]
  }
}
' /var/log/nginx/access.log

Historgram Çıktısı ile Dağılım Analizi

Sayılar bazen yeterli değil, dağılımı görmek istiyorsunuz. ASCII histogram her zaman işe yarıyor:

sort -n /tmp/response_times.txt | awk '
BEGIN {
  bucket_size = 50  # 50ms araliklar
  max_bar_width = 50
}
{
  bucket = int($1 / bucket_size) * bucket_size
  count[bucket]++
  total++
  if ($1 > max_val) max_val = $1
}
END {
  # En yuksek bucket sayisini bul (bar genisligini normalize etmek icin)
  for (b in count) {
    if (count[b] > max_count) max_count = count[b]
  }
  
  printf "nYanit Suresi Dagilimi (Bucket: %dms)n", bucket_size
  printf "%-12s %-8s %-8s %sn", "Aralik(ms)", "Sayi", "Yuzde", "Grafik"
  printf "%-12s %-8s %-8s %sn", "----------", "----", "------", "------"
  
  for (b = 0; b <= max_val; b += bucket_size) {
    if (count[b] > 0) {
      pct = count[b] / total * 100
      bar_len = int(count[b] / max_count * max_bar_width)
      bar = ""
      for (i = 0; i < bar_len; i++) bar = bar "#"
      printf "%-12s %-8d %5.1f%%  |%sn",
             b "-" (b+bucket_size-1), count[b], pct, bar
    }
  }
  printf "nToplam: %d istekn", total
}
'

Çıktı şuna benzer bir şey olacak:

Yanit Suresi Dagilimi (Bucket: 50ms)
Aralik(ms)   Sayi     Yuzde    Grafik
----------   ----     ------   ------
0-49         18432    38.2%    |##################################################
50-99        12891    26.7%    |###################################
100-149      8234     17.1%    |######################
150-199      4123     8.5%     |###########
200-249      2341     4.8%     |######
250-299      1203     2.5%     |###
300-499      891      1.8%     |##
500+         401      0.8%     |#

Bu dağılıma baktığınızda hemen görüyorsunuz: Uzun kuyruk var. O %0.8’lik 500ms üzeri istekler neden bu kadar uzun sürüyor?

Yavaş İstekleri Filtrelemek ve Örüntü Bulmak

P99 değerinizi buldunuz, şimdi o yavaş isteklerin kim olduğunu bulmanız gerekiyor:

awk '
{
  response_time = $NF + 0
  
  # 500ms üzeri istekleri filtrele (nginx formatı)
  if (response_time > 0.500) {
    gsub(/?.*/, "", $7)
    path = $7
    method = $6
    gsub(/"/, "", method)
    status = $9
    
    slow_paths[path]++
    slow_methods[method " " path]++
  }
}
END {
  print "=== En Cok Yavaslik Yasayan Endpointler ==="
  n = asorti(slow_paths, sorted, "@val_num_desc")
  for (i = 1; i <= n && i <= 10; i++) {
    printf "%5d istek | %sn", slow_paths[sorted[i]], sorted[i]
  }
}
' /var/log/nginx/access.log

HTTP Status Kodlarına Göre Percentile Karşılaştırması

Başarılı istekler ile hata alan isteklerin yanıt süreleri farklı mı? Genellikle 500 hataları çok daha hızlı dönüyor (circuit breaker, early fail) ya da çok daha yavaş (timeout). Bunu görmek için:

awk '
{
  status = $9
  response_time = $NF + 0
  
  # Sadece 2xx, 4xx, 5xx gruplarını al
  if (status ~ /^2/) status_group = "2xx"
  else if (status ~ /^4/) status_group = "4xx"
  else if (status ~ /^5/) status_group = "5xx"
  else next
  
  data[status_group][group_count[status_group]++] = response_time
}
END {
  for (group in group_count) {
    n = group_count[group]
    
    # Bubble sort
    for (i = 0; i < n-1; i++) {
      for (j = i+1; j < n; j++) {
        if (data[group][i] > data[group][j]) {
          tmp = data[group][i]
          data[group][i] = data[group][j]
          data[group][j] = tmp
        }
      }
    }
    
    p50 = data[group][int(n*0.50)]
    p95 = data[group][int(n*0.95) < n ? int(n*0.95) : n-1]
    p99 = data[group][int(n*0.99) < n ? int(n*0.99) : n-1]
    
    printf "HTTP %s -> istek:%d  P50:%.3fs  P95:%.3fs  P99:%.3fsn",
           group, n, p50, p95, p99
  }
}
' /var/log/nginx/access.log

Gerçek Dünya Senaryosu: Gece Yarısı İncidenti

Şöyle bir senaryo: Gece 02:00’de monitoring alarmı çaldı, P99 latency 2 saniyeyi geçti. Sabah geldiğinizde postmortem için log analizi yapmanız gerekiyor.

#!/bin/bash

LOG_FILE="/var/log/nginx/access.log"
DATE="12/Jan/2025"
START_HOUR="01"
END_HOUR="03"

echo "=== Incident Analizi: $DATE $START_HOUR:00 - $END_HOUR:00 ==="
echo ""

# Sadece incident zamanındaki logları filtrele ve analiz et
grep "[$DATE:" "$LOG_FILE" | awk -v sh="$START_HOUR" -v eh="$END_HOUR" '
{
  # Saati çıkar
  match($4, /:([0-9]{2}):/, arr)
  hour = arr[1]
  
  if (hour < sh || hour > eh) next
  
  response_time = $NF + 0
  gsub(/?.*/, "", $7)
  path = $7
  
  all_times[total++] = response_time
  path_times[path][path_count[path]++] = response_time
}
END {
  # Genel istatistik
  # Siralama
  for (i = 0; i < total-1; i++) {
    for (j = i+1; j < total; j++) {
      if (all_times[i] > all_times[j]) {
        tmp = all_times[i]; all_times[i] = all_times[j]; all_times[j] = tmp
      }
    }
  }
  
  printf "Toplam istek : %dn", total
  printf "P50          : %.3f snn", all_times[int(total*0.50)]
  printf "P95          : %.3f snn", all_times[int(total*0.95) < total ? int(total*0.95) : total-1]
  printf "P99          : %.3f snn", all_times[int(total*0.99) < total ? int(total*0.99) : total-1]
  printf "MAX          : %.3f snn", all_times[total-1]
  
  print "n=== En Yavas Endpointler (P99 bazli) ==="
  
  for (path in path_count) {
    n = path_count[path]
    if (n < 10) continue  # Az ornekli endpointleri atla
    
    for (i = 0; i < n-1; i++) {
      for (j = i+1; j < n; j++) {
        if (path_times[path][i] > path_times[path][j]) {
          tmp = path_times[path][i]
          path_times[path][i] = path_times[path][j]
          path_times[path][j] = tmp
        }
      }
    }
    
    p99_idx = int(n*0.99)
    if (p99_idx >= n) p99_idx = n-1
    
    printf "P99:%.3fs cnt:%d %sn", path_times[path][p99_idx], n, path
  }
}
' | sort -t: -k2 -rn | head -15

Bu script size o gece yarısı tam olarak hangi endpoint’in ne zaman patlak verdiğini gösterecek. Postmortem toplantısında “galiba şuydu” yerine somut verilerle geleceksiniz.

Performans Trendini İzlemek: Günlük Karşılaştırma

Son olarak, günlük P95/P99 trendini takip etmek için küçük bir script:

#!/bin/bash
# Birden fazla log dosyasını karşılaştır (nginx daily rotation varsayımı)

for log_file in /var/log/nginx/access.log.{7..1} /var/log/nginx/access.log; do
  if [ ! -f "$log_file" ]; then continue; fi
  
  date_label=$(stat -c %y "$log_file" | cut -d' ' -f1)
  
  result=$(awk '
  {
    val = $NF + 0
    if (val > 0 && val < 100) {
      data[count++] = val
    }
  }
  END {
    if (count < 2) { print "VERI_YOK"; exit }
    for (i=0; i<count-1; i++)
      for (j=i+1; j<count; j++)
        if (data[i]>data[j]) { t=data[i]; data[i]=data[j]; data[j]=t }
    p95 = data[int(count*0.95) < count ? int(count*0.95) : count-1]
    p99 = data[int(count*0.99) < count ? int(count*0.99) : count-1]
    printf "istek:%d p95:%.3f p99:%.3f", count, p95, p99
  }
  ' "$log_file")
  
  echo "$date_label | $result | $(basename $log_file)"
done

Dikkat Edilmesi Gereken Noktalar

Tüm bu güçlü araçları kullanırken aklınızda tutmanız gereken birkaç pratik nokta var:

  • Bellek kullanımı: awk tüm değerleri RAM’de tutar. 10 milyon satırlık log dosyasında bellek dolabilir. Büyük dosyalar için önce sort, sonra awk pipeline’ı kullanın.
  • Sıralama varsayımı: Percentile hesaplamalarının çoğu verinin sıralandığını varsayar. sort -n ile önceden sıralamanız kritik.
  • Log rotation: Cron ile çalışan bir analiz scriptiniz varsa, logrotate zamanlamasını göz önünde bulundurun. Yarım saat önceki loglar zaten rotate edilmiş olabilir.
  • Zaman dilimi: Sunucularınız UTC’de log yazıyor ama siz Türkiye saatiyle çalışıyorsanız, saat filtrelerinde +3 farkı hesaplayın.
  • Yeterli örnek sayısı: Bir endpoint’e sadece 5 istek geldiyse P99 istatistiksel olarak anlamsız. En az 100-200 örnek olan endpointleri analiz edin.

Sonuç

awk ile percentile analizi yapmak ilk bakışta karmaşık görünebilir, ama bir kez altyapıyı kurduğunuzda inanılmaz hızlı içgörüler elde edebiliyorsunuz. Elasticsearch’e veri göndermeden, Grafana açmadan, Python ortamı kurmadan, sadece terminal ile production’daki gerçek problemi bulabiliyorsunuz.

Ortalama yanıt süreleri sizi kandırır. P95, P99 değerleri gerçeği gösterir. “Sistemimiz iyi çalışıyor” dediğinizde arkasındaki %1’lik kullanıcı kitlesinin ne yaşadığını bilmiyorsanız, aslında hiçbir şey bilmiyorsunuz demek. Bu scriptleri kendi log formatlarınıza uyarlayın, cron ile otomatize edin, alarmlarınıza P99 eşiklerini ekleyin. Ortalama değil, yüzdelikler üzerine karar verin.

Bir yanıt yazın

E-posta adresiniz yayınlanmayacak. Gerekli alanlar * ile işaretlenmişlerdir