Das Slowlog fuer Performance-Diagnose gezielt auswerten

1. Was das Slowlog ist und wofuer es gedacht ist

Das Slowlog ist ein in Redis eingebauter Ringpuffer, der jeden Befehl protokolliert, dessen Ausfuehrungszeit einen konfigurierbaren Schwellenwert ueberschreitet. Da Redis intern als Single-Threaded-Event-Loop arbeitet, blockiert jeder langsam ausgefuehrte Befehl fuer seine gesamte Laufzeit alle anderen Clients gleichzeitig, unabhaengig davon, wie viele Verbindungen aktiv sind. Das Slowlog macht genau diese blockierenden Momente sichtbar, die sonst nur als diffuse Latenzspitzen im Monitoring auftauchen wuerden.

Wichtig ist das Verstaendnis, was das Slowlog tatsaechlich misst: nicht die gesamte Roundtrip-Zeit inklusive Netzwerklatenz, sondern ausschliesslich die Zeit, die der Befehl innerhalb der Redis-Engine selbst zur Ausfuehrung benoetigt hat. Ein Eintrag im Slowlog bedeutet damit immer, dass der Server selbst fuer diese Zeitspanne blockiert war, was es zum praezisesten verfuegbaren Werkzeug macht, um serverseitige Performance-Probleme von reinen Netzwerkproblemen zu unterscheiden.

2. SLOWLOG GET, LEN und RESET im Detail

SLOWLOG GET liefert die protokollierten Eintraege, standardmaessig die letzten zehn, wobei eine Zahl als Parameter die Anzahl steuert und SLOWLOG GET -1 saemtliche gespeicherten Eintraege zurueckgibt. Jeder Eintrag enthaelt eine eindeutige, monoton steigende ID, einen Unix-Timestamp, die Ausfuehrungsdauer in Mikrosekunden, die vollstaendigen Befehlsargumente sowie ab Redis 4.0 zusaetzlich Client-IP und Client-Name, was die Zuordnung zu einer konkreten Anwendung oder einem konkreten Prozess erheblich vereinfacht.

SLOWLOG LEN gibt lediglich die aktuelle Anzahl gespeicherter Eintraege zurueck, nuetzlich fuer schnelle Monitoring-Checks ohne die vollstaendigen Daten zu uebertragen. SLOWLOG RESET leert das Slowlog vollstaendig und wird typischerweise vor einem gezielten Test eingesetzt, um nur die waehrend dieses Tests aufgetretenen langsamen Befehle zu erfassen, ohne durch aeltere Eintraege abgelenkt zu werden.

redis-cli SLOWLOG GET 5
# 1) 1) (integer) 14
#    2) (integer) 1690000123
#    3) (integer) 45123
#    4) 1) "KEYS"
#       2) "session:*"
#    5) "10.0.1.42:51882"
#    6) ""

redis-cli SLOWLOG LEN
# (integer) 27

redis-cli SLOWLOG RESET
# OK

3. slowlog-log-slower-than richtig konfigurieren

Der Schwellenwert slowlog-log-slower-than wird in Mikrosekunden angegeben und liegt im Standard bei 10000, also 10 Millisekunden. Fuer die meisten Redis-Workloads, die typischerweise im Sub-Millisekunden-Bereich antworten, ist das bereits ein sehr grosszuegiger Wert: Ein Befehl, der 10 Millisekunden benoetigt, ist im Redis-Kontext bereits ein deutliches Alarmsignal, da einfache Operationen wie GET oder SET ueblicherweise im Bereich von zehn bis wenigen hundert Mikrosekunden liegen.

Fuer eine praezisere Diagnose lohnt sich eine temporaere Absenkung des Schwellenwerts auf 1000 Mikrosekunden oder sogar niedriger, um auch Befehle im niedrigen Millisekundenbereich zu erfassen, die in Summe durch hohe Frequenz spuerbare Auswirkungen haben koennen, ohne einzeln als dramatisch aufzufallen. Der Wert 0 protokolliert ausnahmslos jeden Befehl, was fuer eine kurze, gezielte Diagnosephase sinnvoll ist, aber wegen des Overheads niemals dauerhaft in Produktion aktiv bleiben sollte. Der Wert -1 deaktiviert das Slowlog vollstaendig.

# redis.conf , tuned for a production workload expecting sub-millisecond commands
slowlog-log-slower-than 1000
slowlog-max-len 512

# Temporary, more aggressive setting for a focused diagnosis window
# CONFIG SET slowlog-log-slower-than 0
# ... reproduce the issue ...
# CONFIG SET slowlog-log-slower-than 1000   # revert afterwards

4. slowlog-max-len und das Ringpuffer-Verhalten

slowlog-max-len begrenzt die Anzahl gleichzeitig gespeicherter Eintraege, im Standard auf 128 gesetzt. Sobald diese Grenze erreicht ist, verdraengt jeder neue Eintrag den jeweils aeltesten, das Slowlog verhaelt sich also wie ein klassischer Ringpuffer. Bei einem Server mit sehr vielen langsamen Befehlen innerhalb kurzer Zeit kann dieser Effekt dazu fuehren, dass relevante aeltere Eintraege bereits verdraengt wurden, bevor jemand das Slowlog ueberhaupt ausgelesen hat.

Ein hoeherer Wert fuer slowlog-max-len, etwa 512 oder 1024, erhoeht den Speicherbedarf nur geringfuegig, da jeder Eintrag lediglich Metadaten und die Befehlsargumente enthaelt, keine vollstaendigen Datenwerte. Fuer produktive Systeme mit unregelmaessigem Traffic-Muster ist ein grosszuegigerer Ringpuffer sinnvoll, damit auch bei einer kurzen Haeufung langsamer Befehle genuegend historische Eintraege fuer eine spaetere Analyse erhalten bleiben, statt bereits nach wenigen Sekunden ueberschrieben zu werden.

5. Blockierende Befehle identifizieren: KEYS, SORT, FLUSHALL

KEYS ist der Klassiker unter den blockierenden Befehlen: Er durchsucht den kompletten Keyspace in einem einzigen atomaren Schritt und blockiert dabei alle anderen Clients fuer die gesamte Dauer, die bei Millionen von Keys durchaus mehrere Sekunden betragen kann. Im Slowlog erscheint ein solcher Aufruf mit einer auffaellig hohen Dauer und dem Argument KEYS gefolgt vom verwendeten Pattern, was ihn sofort als Hauptverdaechtigen fuer eine gemeldete Latenzspitze identifiziert.

SORT ohne LIMIT-Klausel auf einer grossen Liste, Menge oder Sorted Set ist ein weiterer haeufiger Uebeltaeter, ebenso wie FLUSHALL und FLUSHDB ohne ASYNC-Option bei einer grossen Datenmenge, da das synchrone Loeschen aller Keys den Event-Loop fuer die gesamte Dauer blockiert. Auch SMEMBERS, HGETALL oder LRANGE auf einer extrem grossen Datenstruktur koennen auftauchen, wenn ein Datenmodell mit unbegrenztem Wachstum ueber lange Zeit nicht ueberprueft wurde.

redis-cli SLOWLOG GET -1 | grep -A 3 "KEYS\|SORT\|FLUSHALL"
# 1) (integer) 22
# 2) (integer) 1690001845
# 3) (integer) 812340
# 4) 1) "KEYS"
#    2) "cache:product:*"
# -- 812ms blocking the entire event loop for a single KEYS scan

# Reproduce and confirm with a temporary, aggressive threshold
redis-cli CONFIG SET slowlog-log-slower-than 0
redis-cli KEYS "cache:product:*"
redis-cli SLOWLOG GET 1
redis-cli CONFIG SET slowlog-log-slower-than 1000

6. Slowlog-Eintraege interpretieren: Timestamp, Dauer, Client

Der Unix-Timestamp jedes Eintrags erlaubt die zeitliche Korrelation mit anderen Ereignissen wie Deployments, Cron-Jobs oder Backup-Prozessen. Wiederholt sich derselbe Befehl zu aehnlichen Uhrzeiten an mehreren Tagen, deutet das auf einen periodischen Job hin, der gezielt untersucht werden sollte, statt auf ein zufaelliges, einmaliges Ereignis. Die Dauer in Mikrosekunden sollte immer im Verhaeltnis zur Komplexitaet des Befehls bewertet werden: 5 Millisekunden fuer ein HGETALL auf einem Hash mit 50000 Feldern sind weniger alarmierend als dieselbe Dauer fuer ein einfaches GET.

Die Client-Informationen, IP-Adresse und Client-Name, sind seit Redis 4.0 verfuegbar und machen es moeglich, einen problematischen Befehl direkt einem Microservice oder einer Anwendungskomponente zuzuordnen, sofern die Anwendung ihre Redis-Verbindungen mit CLIENT SETNAME sinnvoll benennt. Ohne diese Namensgebung bleibt oft nur die IP-Adresse als Anhaltspunkt, was bei mehreren Instanzen derselben Anwendung hinter einem Load Balancer die Zuordnung erschwert.

7. Von der Diagnose zum Fix: SCAN statt KEYS und SORT-Alternativen

Der Ersatz fuer KEYS ist praktisch immer SCAN, das denselben Keyspace inkrementell mit einem Cursor durchlaeuft und dabei jeweils nur eine kleine, mit COUNT steuerbare Anzahl von Keys pro Aufruf zurueckgibt. Das verteilt die Last ueber mehrere Aufrufe statt sie in einem einzigen blockierenden Schritt zu buendeln, und garantiert zwar keine exakte Konsistenz ueber die gesamte Iteration hinweg, ist dafuer aber fuer nahezu alle praktischen Anwendungsfaelle wie Cache-Invalidierung oder Wartungsskripte vollkommen ausreichend.

Fuer SORT auf grossen Datenstrukturen hilft entweder eine LIMIT-Klausel, um nur einen Teilbereich zu sortieren, oder die Verlagerung der Sortierung auf die Anwendungsseite nach einem einfachen, unsortierten Abruf. Fuer FLUSHALL und FLUSHDB loest die ASYNC-Option das Blockierungsproblem strukturell, indem das eigentliche Freigeben des Speichers in einem Hintergrund-Thread erfolgt, waehrend der Hauptthread sofort wieder fuer andere Befehle verfuegbar ist.

# WRONG: KEYS blocks the entire event loop until the full scan completes
redis-cli KEYS "session:*"

# RIGHT: SCAN iterates incrementally with a cursor, non-blocking
redis-cli --scan --pattern "session:*" --count 100

# WRONG: FLUSHALL blocks until every key is freed synchronously
redis-cli FLUSHALL

# RIGHT: memory reclaim happens in a background thread
redis-cli FLUSHALL ASYNC

# WRONG: HGETALL on a hash with hundreds of thousands of fields
redis-cli HGETALL big:hash

# RIGHT: HSCAN paginates through fields incrementally
redis-cli HSCAN big:hash 0 COUNT 100

8. Slowlog in die Monitoring-Pipeline integrieren

Ein Cron-Job, der in regelmaessigen Abstaenden SLOWLOG GET abfragt, neue Eintraege anhand der monoton steigenden ID von bereits verarbeiteten unterscheidet und diese in ein Log- oder Metrik-System schreibt, macht das Slowlog zu einem aktiven statt einem rein reaktiven Werkzeug. Da jeder Eintrag eine eindeutige ID besitzt, laesst sich zuverlaessig feststellen, welche Eintraege seit der letzten Abfrage neu hinzugekommen sind, ohne Duplikate zu erzeugen.

Eine sinnvolle Alerting-Regel loest aus, sobald innerhalb eines Zeitfensters mehr als eine bestimmte Anzahl neuer Slowlog-Eintraege auftritt, oder sobald ein einzelner Eintrag eine Dauer im zweistelligen Millisekundenbereich ueberschreitet. Diese Automatisierung verhindert, dass ein durch den begrenzten Ringpuffer bereits ueberschriebener Eintrag unbemerkt bleibt, weil niemand rechtzeitig manuell nachgesehen hat.

#!/usr/bin/env bash
# slowlog-watch.sh , poll new slowlog entries since the last run, no extra tools
set -euo pipefail

STATE_FILE="/var/tmp/redis-slowlog-last-id"
LAST_ID=$(cat "$STATE_FILE" 2>/dev/null || echo -1)

ENTRIES=$(redis-cli SLOWLOG GET -1)
NEWEST_ID=$(redis-cli SLOWLOG GET 1 | head -1)

# In practice: parse entries, filter id > LAST_ID, alert if duration > 10000us
# or if more than N new entries appeared since the last poll interval
echo "$NEWEST_ID" > "$STATE_FILE"

9. Grenzen des Slowlog und der Latency Monitor als Ergaenzung

Das Slowlog erfasst ausschliesslich die reine Befehlsausfuehrungszeit innerhalb der Redis-Engine, nicht aber andere Latenzquellen wie langsames Forking fuer RDB-Snapshots, AOF-Rewrite-Operationen, Expiry-Zyklen oder Betriebssystem-seitiges Swapping. Fuer diese Faelle liefert der LATENCY-Befehlsfamilie, insbesondere LATENCY HISTORY und LATENCY LATEST, zusaetzliche Einblicke in Latenz-Ereignisklassen, die im Slowlog gar nicht erst auftauchen, weil sie nicht als einzelner Befehl, sondern als interner Vorgang klassifiziert werden.

Eine vollstaendige Performance-Diagnose kombiniert deshalb beide Werkzeuge: Das Slowlog fuer konkrete, einem Befehl zuordenbare Latenz, den Latency Monitor fuer strukturelle und interne Latenzquellen, die sich nicht auf einen einzelnen Client-Befehl zurueckfuehren lassen. Wer sich ausschliesslich auf das Slowlog verlaesst, uebersieht systematisch eine ganze Klasse von Performance-Problemen, die genauso real, aber anders geartet sind.

10. Zusammenfassung

Das Slowlog ist das direkteste Werkzeug, um Redis-Latenzprobleme auf einen konkreten Befehl zurueckzufuehren, statt bei vagen Vermutungen zu bleiben. SLOWLOG GET, SLOWLOG LEN und SLOWLOG RESET bilden das Grundwerkzeug, waehrend slowlog-log-slower-than und slowlog-max-len festlegen, wie empfindlich und wie umfangreich protokolliert wird. Klassiker unter den blockierenden Befehlen sind KEYS, ungebremstes SORT und synchrones FLUSHALL, die sich fast immer durch SCAN, LIMIT-Klauseln und die ASYNC-Option entschaerfen lassen.

Eine automatisierte Auswertung des Slowlog per Cron-Job verwandelt es von einem reaktiven in ein proaktives Werkzeug, das Alerts ausloest, bevor ein Nutzer die Latenzspitze bemerkt. Da das Slowlog ausschliesslich reine Befehlsausfuehrungszeit erfasst, gehoert der Latency Monitor mit LATENCY HISTORY als Ergaenzung dazu, um auch strukturelle Latenzquellen wie Forking oder AOF-Rewrites abzudecken, die im Slowlog gar nicht erst auftauchen.

11. FAQ: Das Slowlog fuer Performance-Diagnose