20 satırlık sorgu 14 saniye sürdü: max() alt sorgusu 936 bin satırı geriye taradı

Semptom

26 Eylül'ü 27'ye bağlayan gece bir güvenlik panosunun canlı akışını yazıyordum. Sunucu beş saniyede bir tur atıyor, her turda bir dizi sorgu çalıştırıyordu; turdaki her sorguya 10 saniyelik bir statement_timeout koymuştum. Sorgulardan biri, bilgisi son turdan beri yeni zenginleşen en fazla 20 IP adresi için o adresin olay kayıtlarında en son ne zaman görüldüğünü buluyordu. İlgili parçası şuydu (tablo ve sütun adları jenerikleştirildi):

SELECT i.ip,
       (SELECT max(f.ts)
          FROM olaylar f
         WHERE f.src_ip = i.ip
           AND f.action = 'ssl-login-fail') AS son_gorulme
  FROM adresler i
 WHERE i.ilk_gorulme > $1          -- son turun imleci
 ORDER BY i.ilk_gorulme
 LIMIT 20;

olaylar bir güvenlik duvarının kayıtlarını tutuyordu, 936 bin satır; aradığım eylem SSL-VPN giriş hatasıydı. Gerçek sorguda aynı biçimde üç alt sorgu vardı, her biri başka bir olay kaynağına gidiyordu. Sorun çıkaran, ikinci bir koşul (action) taşıyan buydu.

Normal akışta imleç hep "şimdi"nin hemen gerisinde durduğu için bir turda dönen satır sayısı küçüktü ve sorgu sorunsuz görünüyordu. Sınamak için imleci geriye sardım; sorgu 20 satırla döndü ve 10 saniyelik zaman aşımına takıldı. Ölçtüğümde süre 14 saniyeydi: 20 adresin her biri için ortalama 0,7 saniye.

Yanlış yollar

Bu vakada uzun süre yanlış yolda yürümedim, ama iki varsayım sorguyu neredeyse hatalı hâliyle canlıya gönderiyordu ve masada kolay bir çıkış duruyordu:

• "Normal turda hızlı, öyleyse hızlı." İlk denemeler gerçek veride, gerçek akışta yapıldı ve geçti. Ama akışın o anki hâli en iyi durumdu: imleç güncel, satır az. Canlıda ilk büyük aralıkta — örneğin birikmiş bir zenginleştirme partisinin ardından — aynı sorgu zaman aşımına düşecekti.
• "src_ip'de indeks var." Vardı. Planlayıcı onu kullanmadı. İndeksin varlığı kullanılacağının garantisi değil; hangi indeksin seçildiğini yalnız plan söyler.
• Zaman aşımını büyütmek. En kolay çıkış buydu: 10 saniyeyi 20'ye çıkar, sorgu geçer. Ama beş saniyede bir çalışması gereken bir döngüde 14 saniyelik sorgu, döngünün kendisini bozmak demek. Zaman aşımı burada hatanın kendisi değil, hatanın haberiydi.

Doğru test

Ayırt edici test iki parçadan oluştu. Birincisi sorguyu en kötü aralıkta çalıştırmak: imleci geriye sarıp 20 satırı zorlamak. İkincisi planı tahmin etmek yerine okumak: EXPLAIN (ANALYZE).

EXPLAIN (ANALYZE, COSTS OFF) ...

  SubPlan 2
    ->  Result (actual time=698.3..698.3 rows=1 loops=20)
          InitPlan 1
            ->  Limit (actual time=698.3..698.3 rows=0 loops=20)
                  ->  Index Scan Backward using olaylar_ts_idx on olaylar f (actual time=698.3..698.3 rows=0 loops=20)
                        Index Cond: (ts IS NOT NULL)
                        Filter: ((src_ip = i.ip) AND (action = 'ssl-login-fail'::text))
                        Rows Removed by Filter: 936214
...
Execution Time: 13970.612 ms

Kök neden

PostgreSQL, GROUP BY içermeyen ve tek tabloyu okuyan bir sorgudaki min()/max()'ı, uygun bir B-tree indeks varsa şu biçime çevirmeyi dener ve iki yolu maliyetle karşılaştırır:

-- yazdığım
SELECT max(f.ts) FROM olaylar f
 WHERE f.src_ip = i.ip AND f.action = 'ssl-login-fail';

-- planlayıcının değerlendirdiği eşdeğer
SELECT f.ts FROM olaylar f
 WHERE f.src_ip = i.ip AND f.action = 'ssl-login-fail'
   AND f.ts IS NOT NULL
 ORDER BY f.ts DESC
 LIMIT 1;

Çoğu zaman bu harika bir dönüşüm: zaman indeksini en yeni uçtan okumaya başlar, koşula uyan ilk satırda durur. Planlayıcı LIMIT 1'li yolun maliyetini, koşula uyan satırların indeks boyunca eşit dağıldığını varsayarak hesaplar; tahmini eşleşme sayısı N ise ilk eşleşmeyi indeksin yaklaşık 1/N'lik kısmında bulacağını düşünür.

Bu varsayımı iki şey çökertti. Birincisi, alt sorgu ilişkili: i.ip plan anında bilinmiyor, planlayıcı "herhangi bir IP" için ortalama bir seçicilik kullanıyor. Hangi adresin seyrek, hangisinin hiç geçmediğini bilemez. İkincisi, sorgu tam da yeni tanınan adresleri soruyordu; bunların bu tabloda o eylemle kaydı ya seyrekti ya hiç yoktu. Eşleşme yoksa "ilk eşleşmede dur" hiç gerçekleşmez: indeks sondan başa yürünür, her satır tablodan okunup süzgeçten geçirilir. 936 bin satır, 20 kez.

IP indeksi bu sırada oradaydı. O yol "bu adresin bütün satırlarını getir, eylemi süz, en büyüğü al" demekti ve tahmini maliyeti daha yüksek göründüğü için seçilmedi. Aynı sorgudaki kardeş alt sorgular — başka tablolara giden, ikinci koşulu olmayan max()'lar — sorun çıkarmadı; tuzak, ikinci bir süzgecin eşleşmeyi seyrekleştirdiği yerde kuruldu.

Çözüm

Planlayıcıya bu dönüşümü yaptırmamanın en dar yolu, alt sorguyu bir OFFSET 0 çitinin arkasına koymak:

-- OFFSET 0: max() zaman indeksini geriye taramasın (936 bin satır, 14 sn); IP indeksi kullanılsın
(SELECT max(t)
   FROM (SELECT f.ts AS t
           FROM olaylar f
          WHERE f.src_ip = i.ip
            AND f.action = 'ssl-login-fail'
         OFFSET 0) x) AS son_gorulme

Neden çalışıyor: PostgreSQL normalde FROM içindeki basit alt sorguları dış sorguya katar (düzleştirir, pull-up). Çitsiz yazsaydım iç sorgu düzleşir ve her şey yine SELECT max(f.ts) FROM olaylar f WHERE …'ya dönerdi. LIMIT ya da OFFSET taşıyan bir alt sorgu ise düzleştirilmez, ayrı planlanır. OFFSET 0 sonucu değiştirmez — planlayıcı onun için bir düğüm bile üretmez — ama alt sorguyu ayrı tutar. Artık max()'ın girdisi bir tablo değil bir alt sorgu olduğu için min/max dönüşümü devreye girmez; iç sorgu sıradan bir süzgeç olarak planlanır ve doğal yolu seçer: IP indeksi.

Düzeltilmiş sorgunun süresini notuma yazmamışım; bu yüzden burada sayı vermiyorum. Planın biçimi ise şuna döndü:

  SubPlan 2
    ->  Aggregate
          ->  Index Scan using olaylar_src_ip_idx on olaylar f
                Index Cond: (src_ip = i.ip)
                Filter: (action = 'ssl-login-fail'::text)

Alternatif indeks. (src_ip, ts) bileşik indeksi, LIMIT 1'li yolu tablonun tamamı yerine yalnız o adresin satırları içinde sondan başa yürütür. Eylem de sabitse daha dar bir seçenek kısmi indeks:

CREATE INDEX CONCURRENTLY olaylar_vpnfail_src_idx
    ON olaylar (src_ip) INCLUDE (ts)
 WHERE action = 'ssl-login-fail';

Aynı hafta sonu, aynı soruyu ("bu adresin bu eylemle kaydı var mı") soran başka bir sorgu için tam bu biçimde bir kısmi indeks ekledim. Bu sorguda çit yeterliydi ve değişikliği sorgunun içinde tutuyordu; indeks, tabloyu kullanan her sorguyu etkileyen ayrı bir karar. İkisi birbirini dışlamaz.

Aynı ailenin bir üyesi aynı sorgudaydı: bir EXISTS alt sorgusu, adresin başka bir olay tablosunda belirli türde olayı olup olmadığına bakıyordu. EXISTS de ilk eşleşmede durur; çok olaylı bir adreste aranan tür yoksa adresin bütün satırları okunur. Sınırsız hâli 10 saniyeyi aşıyordu. Burada çözüm çit değil zaman sınırı oldu, çünkü soru zaten "son iki saatte" sorusuydu ve o tabloda (src_ip, ts) indeksi vardı:

EXISTS (SELECT 1 FROM oturum_olaylari e
         WHERE e.src_ip = i.ip
           AND e.ts > now() - interval '2 hours'
           AND e.event_type IN ('giris_basarili', 'komut'))

Kalıcı ders

• Yeni sorguyu en kötü aralıkta sına. Canlı akışın o anki hâli çoğu zaman en iyi durumdur. İmleci geriye sar, en büyük pencereyi zorla, sorgunun döndürebileceği en fazla satırla ölç.
• Planı oku, indeksi varsayma. EXPLAIN (ANALYZE) çıktısında "Index Scan Backward" ile büyük bir "Rows Removed by Filter" yan yana görürsen bu tuzaktır.
• max(), min(), EXISTS ve ORDER BY … LIMIT 1 aynı ailedir. Hepsi "ilk eşleşmede dur" sayesinde hızlıdır ve eşleşme olmadığında en pahalı hâline geçer. Seyrek değeri soran sorguda en kötü girdi "hiç yok"tur.
• Çit bir karardır, yorumunu yaz. OFFSET 0 planlayıcının elini bağlar; veri dağılımı değişirse kendiliğinden düzelmez. Aynı çiti başka bir sorguda bir birleşim için de kullandım: düz birleşimde planlayıcı 140 bin satırlık adres tablosunun tamamını hash'liyordu (yaklaşık 180 ms), oysa 24 saatlik pencerede birkaç bin adres vardı. LEFT JOIN LATERAL (… OFFSET 0) her adres için tek bir birincil anahtar araması yaptırdı. İki yerde de çitin nedeni, ölçümüyle birlikte kodun içinde yazıyor.