Hata ayıklama: önce ölç, sonra tahmin et

Bir hata bildirimi düşer ve bir dakika içinde birinin teorisi hazırdır. Teori kulağa mantıklı gelir, belirtiyle de uyuşur, ve iki kişiyi sorunla hiç ilgisi olmayan bir kod parçasına gönderir. Bu öğleden sonrayı yeterince kez ödediğim için çalışma sıramı değiştirdim: üret, daralt, ölç, teoriye en son izin ver.

İlk teori neden en pahalısı

İlk teori ortada hiçbir kanıt yokken, o hafta ne üzerinde çalıştıysanız ondan kurulur. Yani sistemi değil, sizin dikkatinizin nerede olduğunu tarif eder. Üstelik yapışkandır. Kanala bir kere "büyük ihtimalle cache sorunu" yazıldıktan sonra sonraki her gözlem bunu destekler gibi okunur, uymayan gözlemler ise takip edilmek yerine açıklanıp geçilir.

Maliyet o cümle değil. Maliyet, herkesin bundan sonra nereye bakacağıdır. Üç kişi cache katmanını okurken, hatanın geçtiği fonksiyonun adını veren tek log satırını kimse okumuyordur.

Teorileri yasaklamıyorum, insanlar zaten böyle düşünüyor. Onları bir adım erteliyorum ve ucuzlatıyorum. Erken gelen teori issue'ya fiyatıyla birlikte yazılır: "teori: cache eski satırı dönüyor. Deneme: okuma anında satırın sürümünü logla, beş dakika." Öldürmesi beş dakika süren bir teori faydalıdır. Öldürülemeyen ve bir öğleden sonraya mal olan teori artık bir inançtır.

Hatayı bulan sıra

1. Üret. Yarıdan fazla ihtimalle patlayan bir komuta, bir isteğe veya bir tıklama yoluna inin. Bu elinizde yokken yaptığınız her değişiklik, işe yarayıp yaramadığı bilinmeyen bir tahmindir.
2. Daralt. Alanı ikiye bölün, sonra bir daha. Hem değişiklikler arasında hem girdi içinde. Amaç henüz sebebi bulmak değil, kutuyu küçültmek.
3. Ölç. O kutunun kenarlarına sayı koyun: ne kadar sürdü, kaç tane, ne kadar büyük.
4. Teori kur. Artık teori ucuzdur, çünkü elde duran sayıları açıklamak zorundadır ve aday teorilerin çoğu sayılara değince ölür.

Atladığınız her adımın faizi sonra ödenir. Üretmeyi atlarsanız düzeltmenin işe yarayıp yaramadığını hiç öğrenemezsiniz. Daraltmayı atlarsanız yanlış bölgeyi ölçersiniz. Ölçmeyi atlarsanız teoriniz bir sistemi değil bir hikâyeyi açıklar.

Üretme adımının somut çıktısı, issue'ya yapıştırılabilen tek bir komuttur: hangi istek, hangi veri, hangi ortam. Bunu ilk yarım saatte yazmak iki şey kazandırır. Bir, işi devrettiğinizde karşı taraf sıfırdan başlamaz. İki, "bende çalışıyor" cevabı bir tartışma olmaktan çıkıp kontrol edilebilir bir farka dönüşür, çünkü aynı komutu iki makinede koşturup çıktıları yan yana koyabilirsiniz.

İki kere daraltmak

İki tür bisect vardır ve çoğu hata ikisini de ister. Birincisi değişiklikler arasında:

git bisect start
git bisect bad
git bisect good v1.4.0
git bisect run ./check.sh
git bisect reset

check.sh sağlamsa 0, bozuksa 1 döner. Yirmi commit beş çalıştırmaya iner. Disiplin script'in içindedir: eksik bir bağımlılık yüzünden değil, gerçekten umursadığınız sebep yüzünden patlamalıdır. Bu yüzden yürüyüşe güvenmeden önce script'i bozuk olduğunu bildiğiniz bir commit'te ve sağlam olduğunu bildiğiniz bir commit'te birer kere çalıştırın. Ara ara çıkan bir hata için script kontrolü beş kez koştursun, biri bile patlarsa bozuk desin.

İkinci daraltma girdi içindedir. On bin satırlık bir import patlıyor ve küçük test dosyası patlamıyorsa, dosyayı ikiye bölüp iki yarıyı da koşturun. Dört beş tur sonra elinizde tek başına patlayan tek bir kayıt kalır ve o kayıt genelde bir haftalık kod okumasından daha çok şey anlatır. İki yarı da geçip dosyanın tamamı patlıyorsa bu çıkmaz değil, bulgudur: hata kayıtların birbiriyle etkileşiminde demektir, yani aralarında paylaşılan her şeye bakın. Bir sayaç, bir bağlantı, bir batch tamponu.

Elinizdeki hatayı okuyun

Hata ayıklama oturumlarının en sık hatası, ekrandaki hata yerine beklenen hatayı okumaktır. Şuna bakın:

POST /api/import 500
TypeError: cannot read properties of undefined (reading 'id')
  at normaliseContact (import.js:212)

Kelime kelime okuyunca üç bilgi verir. Timeout değil 500, yani istek handler'a ulaşmış. Undefined bir şey üzerinde property okuması, yani bir arama hata fırlatmak yerine boş dönmüş. Ve veritabanına yazmadan önce, normalizasyon sırasında olmuş. O sabahı connection pool'larda geçiren herkes, elindeki hatayla değil beklediği hatayla çalışıyordu.

Stack trace'te de en üstteki satır sizin kodunuz değilse aşağı inin ve kendi dosyanızın geçtiği ilk satırı bulun. Kütüphanenin içindeki satır hatanın nerede patladığını söyler, sizin satırınız ise oraya neyi gönderdiğinizi. İkincisi neredeyse her zaman daha faydalıdır.

Mesaj işe yarar hiçbir şey söylemiyorsa devam etmeden önce mesajı düzeltin. "import failed" diyen bir hata, batch numarasını, satır numarasını ve patlayan alanın uzunluğunu taşıyan bir hataya dönüşür ve bir sonraki sefer soruyu kendi kendine cevaplar. Soruşturmanın ortasında bir sonraki saati ucuzlatmak meşru iştir; bu, log'lara doğru üç alanı koymakla aynı alışkanlıktır.

Dokunmadan önce kutuyu ölçün

Şüpheli bölgenin kenarlarındaki üç sayı çoğu tartışmayı bitirir: süre, adet, boyut.

const t0 = Date.now();
const rows = await loadRows(batchId);
log.info({ batchId, rows: rows.length, ms: Date.now() - t0 }, 'loaded');

Bunlardan birini bölgenin girişine, birini çıkışına koyun ve patlayan senaryoyu bir kere koşturun. Benim gördüğüm kadarıyla sayılardan en az biri herkesin doğru sandığı bir şeyi çürütür: giren kayıt sayısı çıkanla aynı değildir, ya da "zaten hiç sürmeyen" adım dört saniye sürüyordur. Sizi şaşırtan bir ölçüm, sizi doğrulayan on ölçümden değerlidir. Bu da hangi kütüphanenin ağır olduğunu tartışmak yerine gerçek bir telefonda ölçmekle aynı disiplin.

Düzeltmeden önce hatayı yazın

Düzeltmeye geçmeden önce ürettiğiniz senaryoyu teste çevirin:

test('ismi olmayan satır import sırasında düşmez', async () => {
  const result = await importRows([{ phone: '5551112233' }]);
  expect(result.failed).toBe(0);
});

Bunu önce yazınca üç şey olur. Hatayı gerçekten daraltıp daraltmadığınızı öğrenirsiniz, çünkü yazamadığınız test yerini bulamadığınız hata demektir. Kırmızıdan yeşile geçişi sebebini gösterebildiğiniz bir şekilde görürsünüz, "galiba düzeldi" demezsiniz. Ve senaryo suite'te kalır; altı ay sonraki bir refactor'dan sonra aynı hatanın geri gelmesini engelleyen şey budur. Düzeltmeyi tek başına yayına alınabilir kılan da budur, yani küçük ve geri alınabilir adımlar mantığı.

Ne zaman bırakmalı

Arama alanı küçülmeden doksan dakika geçtiyse bırakıyorum. İrade meselesi değil, getirisi bittiği için. Asıl önemli olan nasıl bıraktığınız. Issue'ya üç satır yazın: ne biliyorum, neyi eledim, sıradaki denemem ne. Ertesi gün bu üç satıra dönmek bir dakika sürer, aynı noktayı yeniden üretmek bir saat.

Cevap çoğu zaman ertesi sabah geliyor ve sebebi bence hiç romantik değil: klavyenin başından kalkınca bütün öğleden sonrayı savunduğunuz teoriyi savunmayı bırakıyorsunuz ve o teoriye hiç uymayan tek gözlem nihayet söz hakkı buluyor.

Nelere dikkat etmeli

• Hatayı değil senaryoyu düzeltmek. Undefined değerin etrafına koyduğunuz kontrol hata mesajını susturur, eksik kayıt eksik kalır. "Nasıl hayatta kalırım" değil "orada ne olmalıydı" diye sorun.
• Baktığınızda yer değiştiren hatalar. Eklediğiniz bir log satırı zamanlamayı değiştirir ve bir yarış durumunu gizleyebilir. Böyle bir durumda adım adım ilerlemek yerine kanıtı kaydedin: zaman damgaları, kimlikler ve sıra bir dosyaya yazılsın, sonra okuyun.
• Aynı anda iki hata. Belirtisi, birbiriyle çelişen kanıtlar ve saçma bir commit gösteren bisect'tir. İstediğiniz an üretebildiğiniz bir belirtiyi seçip diğerini o bitene kadar görmezden gelerek ayırın.
• Paylaşılan ortamlar. Siz bisect yaparken deploy alan bir arkadaşınız, sağlam commit'i bozuk gösterir. Daraltmayı kimsenin değiştirmediği bir makinede yapın.

Sıra, içindeki tekniklerin hepsinden önemli. Üretmek işin ne zaman bittiğini söyler, daraltmak nereye bakacağınızı, ölçmek gerçekte ne olduğunu. Bu üçünden sonra gelen teori ise kanıt üretmek yerine kanıta çarpmak zorundadır. Hata ayıklamaya kaybettiğim saatlerin çoğu zor hatalar yüzünden değildi; ilk dakikada birinin kendinden emin söylediği bir cümleye göre hareket ettiğim için gitti, o cümle çoğu zaman benimdi.