Hata Ayıklama ve Profilleme

Testler, beklenen davranışın korunduğunu söyler. Süreç yavaşladığında, belleği büyüdüğünde veya beklenmedik bir yerde takıldığında testler sessiz kalır: bunlar doğruluk sorunu değil, davranış sorunudur.

Bu ders o sorunları görünür kılan araçları ele alır. Hepsi çalışma zamanının içindedir; ek bir bileşen gerekmez.

İnceleyici Arayüzü

Çalışma zamanı, bir hata ayıklayıcının bağlanabileceği bir arayüz açabilir. Arayüz bir bağlantı noktası dinler ve üzerinden kesme noktası koyma, adımlama, değişken inceleme ve profil alma komutları geçirilir.

node --inspect=127.0.0.1:9229 -e "setTimeout(()=>{},200)"

{/* mask: (?<=ws://127[.]0[.]0[.]1:9229/)[0-9a-f-]+ */}

Debugger listening on ws://127.0.0.1:9229/0dd16a67-741b-482d-86db-82b41709dc92
For help, see: https://nodejs.org/learn/getting-started/debugging

Adresin sonundaki kimlik her çalıştırmada değişir; oturumu tanımlar ve rastgele bağlanmayı zorlaştırır. Bağlantı noktası numarası da isteğe göre değiştirilir.

Adresin başındaki 127.0.0.1 bölümü ihmal edilmemelidir. Bu arayüz, sürecin belleğine tam erişim verir ve keyfi kod çalıştırabilir; ağa açık bir arayüzde dinlemesi, sürecin denetimini dışarıya bırakmak demektir. Bir sunucuda tanı almak gerektiğinde arayüz yerel adreste açılır ve bağlantı, Linux Ağ Yönetimi ve Sorun Giderme kursunda tanıtılan güvenli kabuk üzerinden tünellenir.

--inspect-brk bayrağı, ilk satırı çalıştırmadan önce durur; açılış sırasında oluşan sorunları incelemenin yoludur. Zaten çalışan bir sürece sonradan da bağlanılabilir: SIGUSR1 sinyali alan bir süreç inceleyici arayüzünü açar.

Bellek Kullanımını Okumak

process.memoryUsage() çağrısı birkaç ayrı sayı döndürür ve hangisine bakıldığı önemlidir:

node -e "console.log(process.memoryUsage())"

{/* mask: (?<=rss: )[0-9]+ /} {/ mask: (?<=heapTotal: )[0-9]+ /} {/ mask: (?<=heapUsed: )[0-9]+ /} {/ mask: (?<=external: )[0-9]+ */}

{
  rss: 45137920,
  heapTotal: 5783552,
  heapUsed: 3768872,
  external: 1582649,
  arrayBuffers: 137503
}

Sayılar bayt cinsindendir ve her çalıştırmada değişir; büyüklük sıraları anlamlıdır.

• rss, sürecin fiziksel bellekte tuttuğu toplam alandır; çalışma zamanının kendi kodunu ve yığıtı da içerir.
• heapTotal, JavaScript nesneleri için ayrılmış öbek alanıdır.
• heapUsed, o öbeğin gerçekten kullanılan bölümüdür. Sızıntı aranırken bakılan sayı budur.
• external, V8’e bağlı C++ nesnelerinin bellek kullanımıdır. arrayBuffers bunun bir alt kümesidir; ArrayBuffer ve arabelleklere ayrılan belleği sayar.

Bilerek büyüyen bir diziyle farkı görelim:

// sizinti.mjs
import { mkdirSync } from 'node:fs';
import v8 from 'node:v8';

mkdirSync('profil', { recursive: true });

const gecmis = [];

function olcumEkle(kayit) {
  gecmis.push(kayit);            // hicbir zaman bosaltilmiyor
}

function obekMB() {
  return (process.memoryUsage().heapUsed / 1024 / 1024).toFixed(0);
}

console.log('baslangicta kullanilan obek (MB):', obekMB());
for (let i = 0; i < 500000; i += 1) {
  olcumEkle({ dugum: `kenar-${i % 3}`, metrik: 'sicaklik', deger: i % 40 });
}
console.log('500 bin kayittan sonra (MB)     :', obekMB());

const yol = v8.writeHeapSnapshot('profil/olcum.heapsnapshot');
console.log('anlik goruntu                   :', yol.split('/').pop());

node sizinti.mjs

baslangicta kullanilan obek (MB): 4
500 bin kayittan sonra (MB)     : 48
anlik goruntu                   : olcum.heapsnapshot

Megabayt değerleri çalışma zamanı sürümüne ve çöp toplayıcının o andaki durumuna göre birkaç birim oynar; belirleyici olan artışın büyüklüğüdür.

Bu, ölçüm toplayıcının gerçek bir riskidir: gelen her kaydı bir diziye eklemek, belleği girdi hacmiyle doğru orantılı büyütür. Özetleyicinin kova haritası bu yüzden kayıtları saklamaz, yalnızca sayaç ve toplam tutar — bellek, ayrı anahtar sayısıyla sınırlıdır.

Öbek Anlık Görüntüsü

writeHeapSnapshot, o andaki bütün nesneleri ve aralarındaki başvuruları bir dosyaya yazar. Dosya bir çizgedir: her düğüm bir nesne, her kenar bir başvuru — Veri Yapıları kursundaki çizge gösterimlerinin doğrudan uygulaması.

Anlık görüntü tek başına az şey söyler. Yöntem, iki görüntüyü karşılaştırmaktır: biri yükten önce, biri sonra alınır ve arada hangi nesne türünün sayısının arttığına bakılır. Sürekli artan ve hiç azalmayan bir tür, sızıntının kaynağına götürür.

Görüntü alma işlemi süreci durdurur ve büyük bir dosya üretir; yukarıdaki örnekte dosya onlarca megabayttır. Üretim ortamında alınacaksa, isteklerin geciktirilmesi göze alınarak ve disk alanı denetlenerek yapılır.

Aynı sinyal düzeneği burada da kullanılabilir: süreç, önceden belirlenmiş bir sinyal aldığında anlık görüntü alacak biçimde yazılabilir. Böylece sorun ortaya çıktığı anda, süreci yeniden başlatmadan görüntü alınır.

İşlemci Profili

İşlemci profili, sürecin zamanını hangi fonksiyonda geçirdiğini örnekleyerek ölçer. Belirli aralıklarla çağrı yığıtının anlık görüntüsü alınır; bir fonksiyon örneklerin çoğunda görünüyorsa zamanın çoğunu orada geçiriyordur.

Profil bir bayrakla açılır ve süreç bittiğinde dosyaya yazılır. Küme ve İşçi İş Parçacıkları dersindeki pahalı hesabı profilleyelim; ana iş parçacığında çalışan sürümü çalışma dizininde yoksa önce yazın:

// isci-yok.mjs
const YINELEME = 3e8;

function agirToplam(yineleme) {
  let toplam = 0;
  for (let i = 0; i < yineleme; i += 1) toplam += Math.sqrt(i) % 1;
  return toplam;
}

setTimeout(() => console.log('3 zamanlayici ancak simdi calisti'), 0);
console.log('1 hesap basliyor');
console.log('2 sonuc:', Number(agirToplam(YINELEME).toFixed(3)));

node --cpu-prof --cpu-prof-dir=cpu-profil isci-yok.mjs

Üretilen dosya JSON biçimindedir ve doğrudan okunabilir:

// profil-oku.mjs
import { readdirSync, readFileSync } from 'node:fs';
import path from 'node:path';

const dizin = process.argv[2] ?? 'cpu-profil';
const dosya = readdirSync(dizin).find((a) => a.endsWith('.cpuprofile'));
const profil = JSON.parse(readFileSync(path.join(dizin, dosya), 'utf8'));

const cerceveler = new Map(profil.nodes.map((d) => [d.id, d.callFrame]));
const sayaclar = new Map();
for (const id of profil.samples) sayaclar.set(id, (sayaclar.get(id) ?? 0) + 1);

const toplam = profil.samples.length;
console.log(`dosya: ${dosya.replace(/\d{8}\.\d{6}\.\d+/, 'TARIH.SAAT.PID')}`);
console.log(`ornek sayisi: ${toplam}`);
for (const [id, say] of [...sayaclar].sort((a, b) => b[1] - a[1]).slice(0, 1)) {
  const c = cerceveler.get(id);
  const ad = c.functionName || '(anonim)';
  const yer = c.url ? `${path.basename(c.url)}:${c.lineNumber + 1}` : '(ic)';
  console.log(`${((say / toplam) * 100).toFixed(0).padStart(3)}%  ${ad.padEnd(14)} ${yer}`);
}

node profil-oku.mjs cpu-profil

{/* mask: (?<=ornek sayisi: )[0-9]+ /} {/ mask: ^ *(9[0-9]|100)(?=% agirToplam) */}

dosya: CPU.TARIH.SAAT.PID.0.001.cpuprofile
ornek sayisi: 1829
100%  agirToplam     isci-yok.mjs:4

Dosya adı tarih, saat ve süreç kimliğini taşır; örnekte okunabilirlik için maskelendi. Betik yalnızca en çok örnek alan fonksiyonu yazar; örnek sayısı çalıştırmadan çalıştırmaya değişir, yüzde de bir iki birim oynayabilir. Sabit olan sonuçtur: zamanın tamamına yakını tek bir fonksiyonda geçmiş.

Profil okumanın iki kuralı vardır. Birincisi, yüzdesi düşük çok sayıda satır görüyorsanız darboğaz tek bir yerde değildir ve tek bir eniyileme sonucu değiştirmeyecektir. İkincisi, örnekleme yalnızca çalışan işlemciyi görür: girdi/çıktı beklerken geçen süre profilde görünmez. Bir isteğin yavaşlığı beklemeden geliyorsa işlemci profili boş çıkar ve süreyi başka türlü ölçmek gerekir.

Kod İçi Süre Ölçümü

Beklemeyi de kapsayan ölçüm için node:perf_hooks modülü kullanılır. İşaretler konur, aralar ölçülür ve ölçümler bir gözlemciyle toplanır.

Deneme için Komut Satırı Uygulamaları dersindeki özetleyici modülü ve ölçüm dosyası gerekir; çalışma dizininde yoksa önce bunları yazın:

// ozetleyici.mjs
export function satirdanKayit(satir) {
  const kayit = JSON.parse(satir);
  if (typeof kayit.dugum !== 'string' || typeof kayit.metrik !== 'string') {
    throw new TypeError('dugum ve metrik dizgi olmali');
  }
  if (!Number.isFinite(kayit.deger)) {
    throw new TypeError('deger sonlu bir sayi olmali');
  }
  return kayit;
}

export class Ozetleyici {
  #kovalar = new Map();

  ekle({ dugum, metrik, deger }) {
    const anahtar = `${dugum}/${metrik}`;
    const kova = this.#kovalar.get(anahtar) ?? { sayi: 0, toplam: 0, enBuyuk: -Infinity };
    kova.sayi += 1;
    kova.toplam += deger;
    kova.enBuyuk = Math.max(kova.enBuyuk, deger);
    this.#kovalar.set(anahtar, kova);
  }

  ozet() {
    return [...this.#kovalar].map(([anahtar, { sayi, toplam, enBuyuk }]) => ({
      anahtar,
      sayi,
      ortalama: Number((toplam / sayi).toFixed(2)),
      enBuyuk,
    }));
  }
}

cat > olcumler.ndjson <<'SON'
{"zaman":"2024-02-07T09:12:44Z","dugum":"kenar-01","metrik":"sicaklik","deger":21.4}
{"zaman":"2024-02-07T09:12:44Z","dugum":"kenar-01","metrik":"nem","deger":48.0}
{"zaman":"2024-02-07T09:13:02Z","dugum":"kenar-02","metrik":"sicaklik","deger":19.8}
{"zaman":"2024-02-07T09:13:02Z","dugum":"kenar-02","metrik":"nem","deger":52.5}
{"zaman":"2024-02-07T09:14:19Z","dugum":"kenar-01","metrik":"sicaklik","deger":21.9}
{"zaman":"2024-02-07T09:14:19Z","dugum":"kenar-03","metrik":"sicaklik","deger":24.1}
{"zaman":"2024-02-07T09:15:30Z","dugum":"kenar-02","metrik":"sicaklik","deger":20.2}
{"zaman":"2024-02-07T09:15:30Z","dugum":"kenar-03","metrik":"nem","deger":41.3}
{"zaman":"2024-02-07T09:16:04Z","dugum":"kenar-01","metrik":"nem","deger":47.2}
{"zaman":"2024-02-07T09:16:04Z","dugum":"kenar-03","metrik":"sicaklik","deger":24.6}
{"zaman":"2024-02-07T09:17:22Z","dugum":"kenar-02","metrik":"sicaklik","deger":20.7}
{"zaman":"2024-02-07T09:17:22Z","dugum":"kenar-01","metrik":"sicaklik","deger":22.3}
SON

// olcum-suresi.mjs
import { performance, PerformanceObserver } from 'node:perf_hooks';
import { readFile } from 'node:fs/promises';
import { Ozetleyici, satirdanKayit } from './ozetleyici.mjs';

const gozlemci = new PerformanceObserver((liste) => {
  for (const kayit of liste.getEntries()) {
    console.log(`${kayit.name.padEnd(12)} ${kayit.duration.toFixed(2)} ms`);
  }
});
gozlemci.observe({ entryTypes: ['measure'] });

performance.mark('okuma-basi');
const metin = await readFile('olcumler.ndjson', 'utf8');
performance.mark('okuma-sonu');

const o = new Ozetleyici();
for (const satir of metin.split('\n')) {
  if (satir.trim() === '') continue;
  o.ekle(satirdanKayit(satir));
}
performance.mark('ozet-sonu');

const okuma = performance.measure('okuma', 'okuma-basi', 'okuma-sonu');
const ozetleme = performance.measure('ozetleme', 'okuma-sonu', 'ozet-sonu');
console.log('okuma > ozetleme:', okuma.duration > ozetleme.duration);

node olcum-suresi.mjs

{/* mask: (?<=[ ])[0-9]+[.][0-9]+(?=[ ]ms) */}

okuma > ozetleme: true
okuma        0.82 ms
ozetleme     0.13 ms

Süreler her çalıştırmada değişir; ölçüm bir kez alınıp karar verilmez, tekrarlanır ve dağılımına bakılır. Anlamlı olan iki aşamanın karşılaştırmasıdır; betik bunu her çalıştırmada kendisi ölçüp ilk satıra yazar. Bu küçük dosyada okuma, özetlemeden uzun sürer.

Ölçüm sonuçları Günlükleme dersindeki kütük kaydına alan olarak eklenebilir. Süre alanı taşıyan kayıtlar biriktiğinde, yavaşlamanın hangi aşamadan geldiği profil almaya gerek kalmadan görülür — bu yüzden istek kütüklerine süre alanı yazmak yaygın bir alışkanlıktır.

Özet

• İnceleyici arayüzü sürecin belleğine tam erişim verir; yerel adreste açılır ve uzaktan erişim tünellenerek yapılır.
• Bellek alanları ayrı anlamlar taşır; sızıntı ararken kullanılan öbek alanına, ikili veri için öbek dışı alanlara bakılır.
• Öbek anlık görüntüsü nesneleri ve başvuruları bir çizge olarak yazar; tanı, iki görüntünün karşılaştırılmasıyla yapılır.
• İşlemci profili örnekleme ile çalışır ve yalnızca çalışan işlemciyi görür; bekleme süresi profilde görünmez.
• İşaret ve ara ölçümü beklemeyi de kapsar; süre alanının kütüğe yazılması, profil almadan yavaşlamanın kaynağını gösterir.

Sonraki Adım

Buraya kadar süreç hep elle başlatıldı ve uçbirim kapatılarak durduruldu. Üretimde süreci bir denetçi başlatır, çöktüğünde yeniden açar ve kapanması gerektiğinde bir sinyal gönderir. Sonraki ders bu sözleşmenin süreç tarafını kurar: sinyalleri karşılamak, süren istekleri tamamlayıp yeni bağlantı almamak ve hizmetin durumunu denetçiye bildirmek.