Redis SLOWLOG ve LATENCY Komutlarıyla Yavaş Komutları Bulmak

Slow log neyi ölçer, neyi ölçmez?

Slow log'un ölçtüğü süre yalnızca komutun yürütülme süresidir. Komut sayfası bunu açıkça vurgular: istemciyle konuşmak, yanıtı göndermek gibi G/Ç işleri bu süreye dahil değildir. Ölçülen aşama, Redis'in ana iş parçacığının o komut için kilitlendiği ve başka hiçbir isteğe hizmet edemediği aşamadır. Bu ayrım önemlidir: uygulamanız 200 ms gecikme görüyor ama slow log boşsa, sorun büyük olasılıkla ağda, istemci tarafındaki bağlantı havuzunda ya da büyük yanıtların aktarımındadır; komutun kendisinde değil.

Kayıt kuralı basittir. Bir komutun yürütülme süresi slowlog-log-slower-than ayarındaki eşiği aşarsa günlüğe yeni bir girdi eklenir. Günlüğün en fazla kaç girdi tutacağını slowlog-max-len belirler; günlük dolduğunda her yeni girdi en eski girdiyi siler. Günlük bellekte tutulur ve SLOWLOG RESET ile temizlenene ya da sunucu yeniden başlayana kadar kalır. Bu sayfalarda eşiğin birimi açıkça yazılmıyor; girdilerdeki süre ise mikrosaniye cinsindendir. Sunucunuzdaki güncel değerleri değiştirmeden görmek için CONFIG GET kullanın:

redis-cli CONFIG GET slowlog-log-slower-than
redis-cli CONFIG GET slowlog-max-len
redis-cli SLOWLOG LEN

SLOWLOG LEN günlükteki girdi sayısını tamsayı olarak döndürür. Ayarları okuma ve değiştirme komutlarının ayrıntısı CONFIG GET, SET ve REWRITE yazısında anlatılıyor.

SLOWLOG GET: bir girdinin yedi alanı

SLOWLOG GET günlükteki girdileri döndürür. Argümansız çağrıldığında en son on girdiyi verir; isteğe bağlı count argümanı dönen girdi sayısını sınırlar ve özel değer -1 tüm girdileri ister. Her girdi şu yedi değerden oluşur:

• Her girdiye verilen, artarak ilerleyen benzersiz bir kimlik.
• Komutun işlendiği anın Unix zaman damgası.
• Yürütme için geçen süre, mikrosaniye cinsinden.
• Komutun argüman dizisi.
• İstemcinin IP adresi ve portu.
• İstemci CLIENT SETNAME ile bir ad verdiyse o ad.
• Komut adı dahil toplam argüman sayısı. Bu yedinci değer Redis 8.10 ile eklendi.

Kimlik alanı izleme betikleri için değerlidir: sunucu çalıştığı sürece sıfırlanmaz, yalnızca yeniden başlatma onu sıfırlar. Böylece her yeni girdi için bir uyarı gönderen bir betik, en son işlediği kimliği saklayarak aynı girdiyi iki kez işlemekten kaçınabilir. Çok sayıda argüman alan komutlarda argüman dizisi kırpılır: sayfaya göre slowlog-max-argc ayarının izin verdiğinden (varsayılan 32) fazla argüman varsa son eleman ... (N more arguments) biçiminde bir metinle değiştirilir. Yedinci değer kırpılmadan önceki gerçek sayıyı taşıdığı için bu metni ayrıştırmanıza gerek kalmaz. Belgedeki örnek, varsayılan sınırda 33 argümanlı bir SADD komutunu gösterir:

> CONFIG SET slowlog-log-slower-than 0
OK
> SLOWLOG RESET
OK
> SADD myset 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33
(integer) 31
> SLOWLOG GET 1
1) 1) (integer) 12
   2) (integer) 1752422400
   3) (integer) 21
   4)  1) "SADD"
       2) "myset"
       3) "3"
       4) "4"
          ...
      32) "... (2 more arguments)"
   5) "127.0.0.1:52276"
   6) ""
   7) (integer) 33

Çıktıda girdinin kimliği 12, yürütme süresi 21 mikrosaniye, istemci adı boş (çünkü istemci ad vermemiş) ve toplam argüman sayısı 33'tür. Argüman dizisi ise 32 elemanda kesilmiş ve son eleman eksik iki argümanı haber veriyor. Bir sürüm notu ayrıntısı: Redis 8.8 sürüm notları kırpma sınırlarını slowlog-entry-max-argc ve slowlog-entry-max-string-len adlarıyla anıyor, SLOWLOG GET sayfası ise slowlog-max-argc adını kullanıyor. Sunucunuzda hangi adın geçerli olduğunu CONFIG GET slowlog-* ile kontrol edin.

Slow log'u okumak: tipik şüpheliler

Günlükte gördüğünüz komutları yorumlarken komutun kendisine ve argümanlarına bakın. Tüm anahtar uzayını gezen KEYS komutu, çok büyük bir koleksiyonda tüm elemanları döndüren HGETALL, SMEMBERS ya da LRANGE 0 -1 çağrıları ve çok sayıda anahtarı tek seferde işleyen DEL tipik adaylardır. LATENCY DOCTOR örnek çıktısındaki tavsiyelerden biri de bununla ilgilidir: çok büyük nesneleri silmek, süresinin dolması ya da tahliye edilmesi engelleyici bir işlemdir ve sık silinen büyük nesneleri birden çok küçük nesneye bölmeniz önerilir. KEYS yerine imleçli tarama için SCAN ve KEYS farkı yazısına, büyük anahtarları bulmak için Redis bellek kullanımı yazısına bakın.

Günlükte bir Lua betiği ya da FCALL görüyorsanız sürenin tamamı betiğin içinde geçen süredir; betik çalışırken Redis başka komut çalıştırmaz. Uzun süren betikler BUSY hatasına yol açar ve bu hata Redis hata mesajları yazısında anlatılıyor. Betiklerin kendisi için Lua script ve EVAL yazısı uygun başlangıçtır.

Redis 8.8 ile slow log bilgisi INFO çıktısına da girdi. INFO stats içinde slowlog_commands_count (günlüğe yazılan komutlar), slowlog_commands_time_ms_sum (bu komutların toplam süresi) ve slowlog_commands_time_ms_max (en uzun süre) alanları bulunur. INFO commandstats satırlarına da komut başına slowlog_count, slowlog_time_ms_sum ve slowlog_time_ms_max eklendi. Bu sayaçlar günlük dönüp eski girdiler silinse bile birikmeye devam ettiği için, uzun dönem eğilimi görmek açısından SLOWLOG GET'ten daha güvenilirdir. Eski bir sürümdeyseniz bu alanlar çıktıda yoktur.

Gecikme izleme: LATENCY komut ailesi

Slow log yalnızca komutları görür. Oysa bir Redis sunucusunda gecikme sıçramaları komut dışındaki olaylardan da gelir: RDB kaydı için yapılan fork, AOF dosyasına yazma ve fsync, süresi dolan anahtarların temizlenme döngüsü, bellek sınırında yapılan tahliye ve aktif birleştirme bunlardan bazılarıdır. Gecikme izleme çerçevesi bu olayları adlarıyla ayrı ayrı izler. LATENCY HISTORY, LATENCY RESET ve LATENCY GRAPH sayfalarında geçerli olay adları şöyle listelenir:

Tablodaki açıklamalar olay adlarının kendisinden çıkarılmıştır; komut sayfaları yalnızca adları listeler ve her olayın ayrıntılı açıklamasını Latency Monitoring Framework sayfasına bırakır. Olayların hangi eşikten sonra kaydedileceğini latency-monitor-threshold ayarı belirler; modül API başvurusu, bu eşikten küçük gecikmelerin kaydedilmediğini belirtir. Eşiğin varsayılan değeri ve birimi bu yazının dayandığı sayfalarda yer almıyor; sunucunuzda CONFIG GET latency-monitor-threshold ile kontrol edin.

LATENCY LATEST ve LATENCY HISTORY

LATENCY LATEST her olay için son kaydedilen sıçramayı dört alanla verir: olay adı, son sıçramanın Unix zaman damgası, son gecikme (milisaniye) ve tüm zamanların en yüksek gecikmesi. "Tüm zamanlar" sunucunun açılışından ya da LATENCY RESET çağrısından bu yana demektir. Belgedeki örnek, gecikmeyi yapay olarak üretmek için DEBUG SLEEP kullanır:

> debug sleep 1
OK
(1.00s)
> debug sleep .25
OK
> latency latest
1) 1) "command"
   2) (integer) 1405067976
   3) (integer) 251
   4) (integer) 1001

Çıktıda command olayının son sıçraması 251 ms, tüm zamanların en yükseği ise 1001 ms olarak görünüyor; yani ilk DEBUG SLEEP 1 en kötü değeri, ikinci çağrı son değeri belirlemiş. LATENCY HISTORY ise tek bir olayın zaman serisini döndürür: olay başına en fazla 160 zaman damgası ve gecikme çifti. İzleme panellerine ham veri aktarmak için bu komut kullanılır:

> latency history command
1) 1) (integer) 1405067822
   2) (integer) 251
2) 1) (integer) 1405067941
   2) (integer) 1001

LATENCY DOCTOR, GRAPH ve RESET

LATENCY DOCTOR çerçevenin en güçlü analiz aracıdır: sıçramaların ortalamasını, ortalama sapmasını, sıçramalar arasındaki ortalama süreyi hesaplar ve insan tarafından okunabilir bir rapor ile öneriler üretir. Fork gibi bazı olaylarda sistemin fork hızını da ekler. Belgedeki örnek rapor, beş komut sıçraması tespit ettikten sonra üç öneri sunar: slow log o anki ayarla yalnızca gecikme izleme eşiğinden yavaş olayları kaydettiği için slowlog-log-slower-than değerini düşürmek (raporda önerilen değer 1000), slow log'u inceleyip yavaş komutları bulmak ve sık silinen büyük nesneleri küçük parçalara bölmek. Sayfa ayrıca yardım isterken posta listesine gönderilmesi gereken çıktının bu olduğunu söyler.

LATENCY GRAPH belirli bir olay için ASCII tabanlı bir grafik çizer; grafik en düşük ile en yüksek değer arasında ölçeklenir ve sütunların altındaki etiketler olayın kaç saniye, dakika, saat ya da gün önce gerçekleştiğini gösterir. LATENCY RESET argümansız çağrıldığında tüm olayların zaman serilerini ve en yüksek değer kayıtlarını siler, olay adları verilirse yalnızca onları sıfırlar. Yanıtı sıfırlanan zaman serisi sayısını veren bir tamsayıdır. Araştırmaya başlamadan önce sıfırlayıp sorunu yeniden üretmek, eski sıçramaların kafanızı karıştırmasını önler.

redis-cli LATENCY DOCTOR
redis-cli LATENCY GRAPH command
redis-cli LATENCY RESET command fork

LATENCY HISTOGRAM: komut başına dağılım

LATENCY HISTOGRAM ötekilerden farklı bir şey yapar: eşiğe bakmadan her komut için gecikme dağılımını birikimli bir histogram olarak döndürür. Her kova bir önceki kovanın iki katı aralığı kapsar, boş kovalar yanıta girmez, izlenen gecikmeler 1 nanosaniye ile yaklaşık 1 saniye arasındadır ve 1 saniyenin üstü sonsuz sayılır; en fazla 30 kova olur. Komut adları verilirse yalnızca onların histogramı döner. Belgedeki örnek:

> LATENCY HISTOGRAM set
1# "set" =>
   1# "calls" => (integer) 100000
   2# "histogram_usec" =>
      1# (integer) 1 => (integer) 99583
      2# (integer) 2 => (integer) 99852
      3# (integer) 4 => (integer) 99914
      4# (integer) 8 => (integer) 99940
      5# (integer) 16 => (integer) 99968
      6# (integer) 33 => (integer) 100000

Histogram birikimli olduğu için satırları "bu süreye kadar tamamlanan çağrılar" diye okursunuz: 100 bin SET çağrısının 99.583'ü 1 mikrosaniye kovasında, tamamı ise 33 mikrosaniye kovasına kadar bitmiş. Bu komut genişletilmiş gecikme izlemenin açık olmasını gerektirir; varsayılan olarak açıktır ve kapalıysa latency-tracking ayarıyla açılır. Histogram verisini silmek için CONFIG RESETSTAT kullanılır. Aynı altyapı INFO latencystats bölümündeki p50, p99 ve p999 yüzdeliklerini de üretir.

redis-cli ile istemci tarafı gecikme ölçümü

Sunucu içi ölçümler istemcinin gördüğü gecikmeyi tam yansıtmaz; araya ağ ve işletim sistemi girer. redis-cli --latency saniyede 100 kez PING gönderip yanıt süresini ölçer ve en küçük, en büyük, ortalama değerleri milisaniye cinsinden canlı olarak günceller. --latency-history aynı ölçümü her 15 saniyede (varsayılan) sıfırdan başlatarak zaman içindeki değişimi gösterir; aralık -i ile değişir. --latency-dist renkli terminalde bir gecikme spektrumu çizer. Belgedeki örnek çıktılar:

$ redis-cli --latency
min: 0, max: 1, avg: 0.19 (427 samples)

$ redis-cli --latency-history
min: 0, max: 1, avg: 0.14 (1314 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.18 (1299 samples) -- 15.00 seconds range
min: 0, max: 1, avg: 0.20 (113 samples)^C

Belge burada bir uyarı ekler: çok hızlı bir sunucuda ortalama, redis-cli'yi çalıştıran sistemin çekirdek zamanlayıcısından kaynaklanan gecikme yüzünden biraz yüksek çıkar; örnekteki 0,19 ms aslında 0,01 ms ya da daha az olabilir. Redis 8.10 ile --latency ve --latency-history modlarına --latency-percentiles seçeneği eklendi; virgülle verdiğiniz yüzdelikleri raporlar. Daha eski bir redis-cli bu seçeneği tanımaz.

Bir de sunucuyla hiç konuşmayan bir mod vardır: --intrinsic-latency. Bu mod, bilgisayarın kendi doğal gecikmesini, yani çekirdek zamanlayıcısının ve sanallaştırılmış sunucularda hipervizörün eklediği gecikmeyi ölçer. Test süresi saniye cinsinden verilir ve komut Redis'in çalıştığı makinede çalıştırılmalıdır. Belgedeki örnekte en kötü değer 739 mikrosaniye çıkıyor; bu, o sistemde bazı sorguların zaman zaman 1 milisaniyeye yakın sürebileceği anlamına gelir ve Redis bu tabanın altına inemez. VPS kullanıyorsanız bu ölçüm, sorunun Redis'te mi yoksa sanal makinede mi olduğunu ayırmanıza yardım eder.

redis-cli --intrinsic-latency 5
redis-cli --latency-history -i 30
redis-cli --latency -h 10.0.0.12 -p 6379

MONITOR: güçlü ama pahalı

MONITOR, sunucunun işlediği her komutu gerçek zamanlı olarak geri akıtan bir hata ayıklama komutudur. Uygulamanın Redis'e tam olarak ne gönderdiğini görmek, gereksiz tekrarlanan sorguları ya da beklenmedik anahtar adlarını yakalamak için çok işe yarar. redis-cli ile kullanılır ve Ctrl-C ile durdurulur:

$ redis-cli monitor
1339518083.107412 [0 127.0.0.1:60866] "keys" "*"
1339518087.877697 [0 127.0.0.1:60866] "dbsize"
1339518090.420270 [0 127.0.0.1:60866] "set" "x" "6"
1339518096.506257 [0 127.0.0.1:60866] "get" "x"
1339518099.363765 [0 127.0.0.1:60866] "eval" "return redis.call('set','x','7')" "0"
1339518100.363799 [0 lua] "set" "x" "7"
1339518100.544926 [0 127.0.0.1:60866] "del" "x"

Her satırda zaman damgası, köşeli parantez içinde veritabanı numarası ve istemci adresi, ardından komut ve argümanları bulunur. Bir Lua betiğinin içinden çağrılan komutlar adres yerine lua etiketiyle görünür. Güvenlik nedeniyle yönetim komutları akışa yazılmaz, AUTH içindeki hassas veri gizlenir ve QUIT de kaydedilmez.

Küçük bir örnek: "uygulama ara ara donuyor"

Bir e-ticaret sitesinin sepet sayfası gün içinde birkaç kez saniyelerce donuyor ve geliştirici ekip Redis'ten şüpheleniyor diyelim. Önerdiğimiz sıra şöyledir. Önce sunucu içi bir sıçrama olup olmadığını LATENCY LATEST ve LATENCY DOCTOR ile görün. Raporda command olayı öne çıkıyorsa SLOWLOG GET 20 ile hangi komutların yavaş olduğuna bakın; girdilerdeki istemci adresi ve CLIENT SETNAME ile verilmiş ad, komutu hangi uygulamanın gönderdiğini söyler. Raporda fork öne çıkıyorsa sorun büyük olasılıkla arka plan kaydı sırasında yaşanıyordur; INFO stats içindeki latest_fork_usec değerine bakın.

Sunucu içi bir sıçrama göremiyorsanız redis-cli --latency-history ile uygulama sunucusundan Redis'e ölçüm alın ve aynı ölçümü Redis makinesinde --intrinsic-latency ile karşılaştırın. İki ölçüm de temizse sorun büyük olasılıkla uygulama tarafındadır: her istekte yeni bağlantı açmak, çok sayıda komutu tek tek göndermek gibi. Bağlantı havuzları için bağlantı URL ve connection pool, toplu gönderim için pipelining yazılarına bakın.

redis-cli LATENCY LATEST
redis-cli LATENCY DOCTOR
redis-cli SLOWLOG GET 20
redis-cli INFO stats
redis-cli --latency-history

Sık yapılan hatalar

• Slow log'u uçtan uca gecikme sanmak: Yalnızca yürütme süresi ölçülür; ağ ve yanıt aktarımı dahil değildir.
• Eşiği sıfıra çekip unutmak: Her komut kaydedilir, slowlog-max-len dolduğunda eski ve gerçekten önemli girdiler silinir.
• SLOWLOG RESET ile kanıtı silmek: Silinen girdiler geri gelmez; araştırma bitmeden sıfırlamayın.
• Eşiği kontrol etmeden boş yanıta şaşırmak: Eşiğin altında kalan gecikmeler kaydedilmez; LATENCY LATEST beklediğiniz olayı göstermiyorsa önce latency-monitor-threshold değerine bakın.
• MONITOR'u açık bırakmak: Bir terminal penceresinde unutulan MONITOR sunucunun verimini yarıya indirebilir.

Sık Sorulan Sorular

Slow log ile LATENCY komutları arasındaki fark nedir?

Slow log, eşiği aşan her komutun kendisini argümanları ve istemcisiyle kaydeder. Gecikme izleme ise olay türlerine göre (komut, fork, AOF yazımı, tahliye) yalnızca sıçramaların zamanını ve süresini tutar. Hangi komutun yavaş olduğunu slow log, sunucunun hangi iç işinin gecikme yarattığını LATENCY komutları söyler.

Slow log kalıcı mı?

Hayır. Girdiler bellekte tutulur; SLOWLOG RESET ile ya da sunucu yeniden başlayınca silinir. Uzun dönem eğilim için Redis 8.8 ile gelen INFO slow log sayaçlarını izleme sisteminize toplayın ya da girdileri kimliklerine göre düzenli aralıklarla dışarı aktarın.

MONITOR yerine ne kullanabilirim?

Yavaş komutları bulmak için SLOWLOG GET, hangi komut tipinin en çok yük oluşturduğunu görmek için INFO commandstats çok daha ucuzdur. MONITOR'u yalnızca uygulamanın tam olarak hangi komutları gönderdiğini görmeniz gerektiğinde ve kısa süreyle kullanın.

redis-cli --latency neden sıfır ve bir arasında değer gösteriyor?

Değerler milisaniye cinsindendir ve hızlı bir yerel bağlantıda PING genellikle 1 milisaniyenin altında döner. Belgenin de belirttiği gibi ortalama, ölçüm yapan makinenin zamanlayıcısı yüzünden biraz yüksek çıkabilir; asıl ilgilenmeniz gereken birkaç milisaniye ve üzerindeki sıçramalardır.

Marka adları sahiplerine aittir. Bu yazı bağımsız bir teknik rehberdir; adı geçen kuruluşlarla bayilik veya ortaklık ilişkisi bulunduğu anlamına gelmez.

İlgili içerikler: Redis öğrenme rehberi · Redis INFO komutu · SCAN ve KEYS farkı · Redis bellek kullanımı · CONFIG GET ve SET · redis-cli kullanımı