Sertaç Yıldırım saha notları

Ana sayfa → Teknik

Nerede 200 ms Gitti?

Müşteri şikâyetçi: emirler bazen geç açılıyor. Ölçtük — uçtan uca 240 ms. Dört servis, her biri kendi logunda “ben işimi bitirdim” diyor. Kendi söyledikleri sürelerin toplamı 40 ms. Kalan 200 ms nerede?

Sertaç Yıldırım · · 9 dk okuma

Özet
  • Servislerin kendi süreleri toplamı, gerçek süreyi vermez. Zaman aradaki boşluklarda kayboluyor.
  • Correlation ID en ucuz kazanç. Tam tracing kuramıyorsan bile bunu bugün ekle. Ama thread havuzuna geçerken taşı, iş bitince temizle.
  • Trace, kuyruklardan da geçmeli. Yoksa iz yarı yolda kopuyor.
  • Her isteği izlemek zorunda değilsin. Ama yavaş ve hatalı olanları mutlaka sakla; örnekleme kararı da servisler arasında aynı yorumlanmalı.

Loglar neden yetmiyor?

Elimizde dört servisin logu vardı ve hepsi kendince doğruydu:

Dört servis, altı satır, tek bir gerçek yok 
gateway     10:30:00.112  emir dogrulandi (8 ms)
gateway     10:30:00.115  redis'e yazildi (3 ms)
risk        10:30:00.320  risk kontrolu tamam (5 ms)
teminat     10:30:00.331  teminat ayrildi (11 ms)
kopru       10:30:00.344  MT5 fill alindi (13 ms)
gateway     10:30:00.344  musteriye dondu

Servislerin kendi soyledigi: 8+3+5+11+13 = 40 ms
Musterinin bekledigi:                  240 ms
Aradaki 200 ms: ???

Kayıp zaman servislerin içinde değil, aralarında: kuyrukta bekleme, bağlantı havuzunda (connection pool) sıra bekleme, ağ, serileştirme, ve en sinsisi — iş parçacığı havuzunda (thread pool) sıraya girme.

Boşluk aslında yukarıdaki damgaların içinde duruyor: .115’ten .320’ye 205 ms geçmiş (risk’in kendi 5 ms’si dahil; saf bekleme 200 ms). Ama bunu görmek için dört makinenin logunu yan yana koyup elle çıkarma yapman gerekiyor. Tek istek için kolay; saniyede 50 bin istekte, hangi satırın hangi isteğe ait olduğunu bile bilmeden, saatler sürüyor. Üstelik sunucu saatleri milisaniye düzeyinde kayıyor, dolayısıyla çıkardığın fark bazen negatif bile olabiliyor.

Önce en ucuzu: correlation ID

Tam bir tracing altyapısı kurmak zaman alır. Ama tek bir kimliği bütün sisteme taşımak bir günlük iş ve faydasının çoğunu hemen veriyor.

Kural: giriş noktasında üret, her yere taşı, iş bitince temizle 
// 1) Gateway: istek girerken
String cid = istek.header("Correlation-Id");       // X- oneki artik onerilmiyor (RFC 6648)
if (cid == null || !cid.matches("[A-Za-z0-9-]{8,64}")) {
    cid = UUID.randomUUID().toString();            // disaridan geleni dogrulamadan alma
}
MDC.put("cid", cid);                               // log altyapisina koy

// 2) HTTP cagrilarinda tasi
httpClient.header("Correlation-Id", cid);

// 3) KUYRUK MESAJLARINDA DA TASI  ← en cok atlanan
redis.xadd("emirler", Map.of("cid", cid, "govde", json));

// 4) Tuketici tarafta geri al, isin sonunda temizle
String gelen = mesaj.get("cid");
if (gelen == null || !gelen.matches("[A-Za-z0-9-]{8,64}")) {   // ayni dogrulama: kuyruga sadece gateway yazmiyor
    gelen = "yok-" + mesaj.id();
}
MDC.put("cid", gelen);
try {
    isle(mesaj);
} finally {
    MDC.remove("cid");   // havuzdaki thread eski cid'yi sonraki mesaja yapistirmasin
}

Üçüncü madde kritik. Çoğu ekip HTTP başlıklarında taşıyor ama iş kuyruğa girince zinciri bırakıyor. Oysa asenkron sistemlerde zamanın çoğu tam da orada geçiyor — yani izi tam da kaybetmemen gereken yerde kaybediyorsun.

Dördüncü maddedeki finally de süs değil. MDC thread-local çalışır: iş bir executor’a, CompletableFuture’a ya da başka bir thread havuzuna geçtiğinde cid kendiliğinden taşınmaz; taşıyan bir executor sarmalayıcısı yazman gerekir. Temizlemezsen de havuzdan geri gelen thread, eski cid’yi alakasız bir isteğin loglarına yapıştırır. Sonuç: A müşterisinin loglarında B müşterisinin kimliği. Bu gerçek bir üretim hatası ve fark edilmesi haftalar alıyor.

Birinci maddedeki doğrulama da öyle: dışarıdan gelen header’ı olduğu gibi loga koyarsan, uzunluk ve karakter sınırı olmadan, biri sana satır sonu karakteri gönderip loglarına sahte satır yazdırabilir (log injection).

Sonuç: tek bir aramayla bütün yolculuğu görüyorsun.

Artık mümkün 
$ grep -h 'cid=a91c-4d02' /var/log/*/app.log | sort
# -h: dosya adini bastirma, yoksa ilk alan damga degil "yol:damga" olur
# ya da log platformunda:  cid:"a91c-4d02"

10:30:00.104  gateway  cid=a91c-4d02  emir alindi
10:30:00.115  gateway  cid=a91c-4d02  redis'e yazildi
10:30:00.315  risk     cid=a91c-4d02  mesaj alindi      ← 200 ms BOSLUK!
10:30:00.320  risk     cid=a91c-4d02  kontrol tamam

İşte 200 ms. Emir Redis stream’ine yazıldıktan sonra risk servisinin onu alması 200 ms sürmüş. Sebep: risk servisi tek tüketiciyle çalışıyordu ve önünde büyük bir toplu emir vardı — klasik sıra başı tıkanması (head-of-line blocking).

Bu bulguya loglara bakarak ulaşmak günler alırdı. Correlation ID ile on beş dakika sürdü.

Correlation ID, gözlemlenebilirlik yatırımları içinde en yüksek getirili olanı. Bir günlük iş, ilk kullanışta masrafını çıkarıyor.

Sonra asıl olan: trace

Correlation ID sana “ne oldu, hangi sırayla” sorusunu cevaplıyor. Trace ise bir adım öteye gidiyor: her adımın ne kadar sürdüğünü ve hangi adımın hangisinin içinde olduğunu gösteriyor.

İki kavram, hepsi bu
  • Trace: bir isteğin tamamı. Tek bir trace_id.
  • Span: o istek içindeki tek bir iş parçası. Her span’in bir başlangıcı, süresi ve bir ebeveyni var.
trace_id: 7f3a...  "emir ac"                        240 ms
├─ gateway: dogrulama                                 8 ms
├─ gateway: redis xadd                                3 ms
┆  ··· bosluk: kuyrukta bekleme ···                 200 ms   ← iste burada
├─ risk: kontrol                                      5 ms
│  └─ risk: postgres sorgusu                          3 ms
├─ teminat: ayirma                                   11 ms
└─ kopru: MT5 gonderimi                              13 ms
   └─ kopru: TCP yazma                                9 ms

Bu görünüm, dört log dosyasını yan yana koymanın yapamayacağı şeyi tek bakışta yapıyor: boşluğu görünür kılıyor.

İki not. Birincisi: “kuyrukta bekleme” diye bir span kendiliğinden oluşmaz. O satır, redis xadd span’inin bitişiyle risk: kontrol span’inin başlangıcı arasındaki boşluk; trace aracı bunu ağaçta boş bir aralık olarak gösterir, adını sen koyarsın. İkincisi: span süreleri güvenilir, çünkü her biri kendi makinesinin saatiyle ölçülüyor. Span’ler arasındaki boşluk ise iki makinenin saati arasındaki fark — saat kayması burada da var. Birkaç ms’lik kayma 200 ms’lik boşluğu gizlemez; ama 5 ms’lik bir boşluğa bakıp karar verme.

Kuyruğun iki yakasını birleştirmek

Trace’in asenkron sistemlerdeki en kritik detayı bu. Mesajı yazarken trace bağlamını mesajın içine koyman, okurken de oradan devam etmen gerekiyor:

Bağlamı mesajla taşı 
// Uretici tarafi
Map<String,String> tasiyici = new HashMap<>();
propagator.inject(Context.current(), tasiyici, Map::put);
redis.xadd("emirler", birlestir(govde, tasiyici));   // traceparent mesajda

// Tuketici tarafi
Context ust = propagator.extract(Context.root(), mesaj, GETTER);
Span span = tracer.spanBuilder("risk kontrolu")
                  .setParent(ust)                    // ← zincir kopmuyor
                  .startSpan();
try (Scope s = span.makeCurrent()) {                 // alt span'ler bunun altina girsin
    riskKontrolu(mesaj);
} finally {
    span.end();                                      // kapatilmayan span disa aktarilmaz
}

Bunu yapmazsan her tüketici yeni bir trace başlatır ve elinde birbiriyle ilgisiz yüzlerce kısa trace olur. Teknik olarak tracing kurmuş olursun, pratikte hiçbir soruyu cevaplayamazsın.

Toplu tüketimde bir fark var: tüketici bir seferde 100 mesaj alıyorsa tek bir ebeveyn olmaz, çünkü 100 mesajın 100 ayrı trace’i var. Bir span’in tek ebeveyni olabilir. OpenTelemetry’nin önerisi burada setParent yerine addLink: batch span’i her mesajın bağlamına link verir, sen de herhangi bir mesajın trace’inden batch’e atlayabilirsin.

İki kimlik nasıl bir arada yaşar?

Yukarıda iki ayrı kimlik gördün: cid ve trace_id. Eş anlamlı değiller ve en yaygın karışıklık burada çıkıyor.

  • OpenTelemetry kuruyorsan ayrı bir correlation header üretme. W3C traceparent zaten standart; içindeki trace_id istek başına tekil. Onu MDC’ye koy, log satırında trace_id olarak yazdır; cid’ye gerek kalmaz. Yazının başındaki Correlation-Id header’ı bununla çelişmiyor: onu bugün kuruyorsun çünkü OpenTelemetry aylar sürüyor; OTel geldiğinde istek kimliği görevini trace_id’ye devrediyor, cid’yi yalnızca aşağıdaki iş akışı kimliği olarak tutuyorsun.
  • İş akışı tek istekten uzunsa ikisini birden taşı. Emir açılır, gün sonu fill gelir, ertesi gün mutabakat çalışır: üç ayrı istek, üç ayrı trace. Bunları bağlayan şey iş kimliği (order_id gibi) ya da akış boyunca taşınan bir cid. Kural: trace_id = bir istek, cid = bir iş akışı. İkisini de log satırına yaz, ikisini de ayrı alan yap.

Örnekleme: her isteği izlemek zorunda değilsin

Saniyede 50 bin işlem yapan bir sistemde her isteği kaydetmek ne mantıklı ne de ucuz. Ama rastgele %1 örneklemek de tek başına yetmiyor — çünkü ilgilendiğin şey ortalama istek değil, kötü olan istek.

Kuyruk sonu örnekleme (tail sampling)

Doğru yaklaşım, kararı istek bittikten sonra vermek:

  • Hata aldıysa → %100 sakla
  • Süre 100 ms’yi aştıysa → %100 sakla
  • Belirli müşteriler / VIP hesaplar → %100 sakla
  • Geri kalan normal istekler → %1 sakla (temel çizgi için)

Böylece hem maliyet düşük kalıyor hem de sorun yaşanan her istek elinde oluyor. “Müşteri şikâyet etti ama o isteğin trace’i örneklenmemişti” cümlesi, tracing kurmuş olmanın en can sıkıcı hali.

Bedeli var. Karar istek bittikten sonra verildiği için bir trace’in bütün span’leri aynı collector örneğinde toplanmalı: yük dengeleyici trace_id’ye göre tutarlı yönlendirme yapmalı, collector da karar verene kadar span’leri bellekte tutmalı. Saniyede 50 bin istekte bu, collector katmanının kendi başına bir sistem olması demek. Kurulumun zor kısmı “yavaş olanları sakla” cümlesi değil, burası.

Örnekleme kararı servisler arasında nasıl yayılır?

Tail sampling kuramıyorsan karar giriş noktasında verilir (head sampling) ve traceparent’ın son iki hanesindeki sampled bayrağıyla (01 sakla, 00 atla) alt servislere yayılır. Bir servis bu bayrağı yok sayıp kendi zarını atarsa yarım trace’ler görürsün: gateway’de var, risk’te yok, teminatta yine var. “Tracing kurduk ama trace’ler eksik çıkıyor” şikâyetinin en yaygın sebebi bu. Kural: karar bir yerde verilir, herkes bayrağa uyar. Tail sampling yapacaksan tersi geçerli: uçtaki servis her zaman 01 göndermeli (AlwaysOn), yoksa uçta 00 denen yavaş istek collector’a hiç ulaşmaz ve sonradan kurtarılamaz.

Üç yaygın hata
  • Span’a büyük veri koymak. Emrin tamamını JSON olarak span’a eklemek, trace deposunu şişiriyor ve pahalıya patlıyor. Sadece kimlikleri koy: order_id, symbol, müşteriyi doğrudan göstermeyen bir iç kimlik.
  • Trace göndermeyi istek yolunda senkron yapmak. Toplayıcı yavaşladığında uygulaman da yavaşlıyor. Gönderim her zaman arka planda ve tampon dolduğunda düşürerek olmalı — gözlem aracı asıl işi bekletmemeli.
  • Kişisel veriyi span’a yazmak. Müşteri adı, e-posta, hesap numarası — trace deposu genelde loglardan daha az korunuyor.

Üçünü bir arada tutmak

Metrik, log ve trace aynı sorunun üç farklı görüntüsü. Asıl güç, aralarında geçiş yapabilmekten geliyor:

AraçCevapladığı soruNereye götürür
MetrikBir sorun var mı?“p99 gecikme 240 ms” → trace’e
TraceHangi adımda?“kuyrukta 200 ms” → loga
LogTam olarak ne oldu?“tüketici tek, batch önde”

Bu zincirin çalışması için tek bir şey gerekiyor: her log satırında trace_id olmalı. Trace’te bir yavaşlık gördüğünde tek tıkla o isteğin loglarına gidebiliyorsan sistem işini yapıyor demektir; kimliği elle kopyalayıp aramak zorunda kalıyorsan yarısı eksik.

Nereden başlamalı?

  1. Correlation ID. Bugün. HTTP ve kuyruk dahil her yerde; thread havuzuna geçerken taşı, iş bitince temizle.
  2. Yapısal log. Düz metin yerine alanları olan log; cid ve trace_id ayrı alan olsun.
  3. Kritik akışta trace. Bütün sistemi bir anda donatma; sadece emir akışına koy, faydasını gör.
  4. Örnekleme. Önce head sampling ve bayrağa uyan servisler; tail sampling’e collector katmanını kurduktan sonra geç. Yavaş ve hatalı olanlar %100.
  5. Yayılmayı genişlet. Değeri kanıtlandıktan sonra diğer akışlara.

İlk iki adım, tracing altyapısı hiç kurmasan bile problemlerinin çoğunu çözüyor. “Önce OpenTelemetry kuralım” diye başlayan projeler genelde altı ay sonra hâlâ kurulum aşamasında oluyor; correlation ID ise ertesi gün işe yarıyor.

Kontrol listesi

Gözlemlenebilirlik
  • Her istekte bir correlation ID var mı?
  • Bu kimlik kuyruk mesajlarında da taşınıyor mu?
  • İş thread havuzuna geçince kimlik taşınıyor, iş bitince MDC temizleniyor mu?
  • Her log satırında trace_id ve (varsa) cid ayrı alan olarak var mı?
  • Trace zinciri kuyruğun iki yakasını birleştiriyor mu?
  • Her span finally içinde kapatılıyor mu?
  • Yavaş ve hatalı istekler %100 saklanıyor mu?
  • sampled bayrağı bütün servislerde aynı şekilde yorumlanıyor mu?
  • Span’lar büyük gövdeden ve kişisel veriden temiz mi?
  • Trace gönderimi arka planda mı çalışıyor?
  • Metrikten trace’e, trace’ten loga tıklayarak geçebiliyor musun?

Sonuç

Dağıtık bir sistemde en pahalı şey, sorunun nerede olduğunu bilmeden geçirilen saatler. Kod düzeltmesi genelde on dakika; onu bulmak günler sürüyor.

Baştaki 200 ms bir hata değildi; tek tüketicili bir kuyruktu. Kimse yanlış kod yazmamıştı, kimse yanlış bir şey yapmamıştı — sadece hiç kimse bütünü göremiyordu. Tracing’in yaptığı tek şey de bu: parçaların arasındaki boşluğu görünür kılmak.