ข้ามไปยังเนื้อหา

Tooling & Monitoring

ทดสอบบน Redis 8.10.2 (redis:8.10.2-alpine), redis-cli และ redis-benchmark 8.10.2, ioredis 6.0.0, Node 24 บน Mac (Apple silicon, Docker) transcript แบบ # cli/... คือ session เดียวเรียงตามเอกสารที่ harness ของคอร์สรันซ้ำ output อื่นทั้งหมดด้านล่างเป็นของจริงจากคอนเทนเนอร์ชั่วคราวของผมเอง: --bigkeys และ --keystats รันบน 126 529 key (โหลดด้วย redis-benchmark -t set -r บวก key ชนิดละหนึ่งตัว) ส่วน SLOWLOG, MONITOR และการวัด latency รันบนราว 1 ล้าน key ตัวเลขมาจาก Mac เครื่องนี้และจะต่างในเครื่องของคุณ

redis-cli มีโหมดวินิจฉัยที่ไม่ต้องใช้ซอฟต์แวร์เพิ่ม: --bigkeys, --keystats, --memkeys, --scan, --latency, --latency-history, --latency-dist บวกคำสั่งฝั่งเซิร์ฟเวอร์ INFO, SLOWLOG, MEMORY, LATENCY, MONITOR และ CLIENT ด้านล่างคือแต่ละอย่างพร้อมสิ่งที่มันพิมพ์จริง

INFO รับชื่อ section (server, memory, stats, commandstats, keyspace, clients, threads, …) field ที่ควรจับตา ค่าจริงจากคอนเทนเนอร์ของผม:

# INFO server
redis_version:8.10.2
redis_mode:standalone
os:Linux 6.12.76-linuxkit aarch64
tcp_port:6379
# INFO memory
used_memory_human:61.33M
used_memory_peak_human:83.19M
maxmemory_human:0B # 0B = no limit
mem_fragmentation_ratio:1.42
number_of_cached_scripts:0
# INFO stats
total_commands_processed:8284131
instantaneous_ops_per_sec:1
keyspace_hits:3506741
keyspace_misses:2
expired_keys:0
evicted_keys:0
# INFO commandstats (one line per command)
cmdstat_config|get:calls=18,usec=127,usec_per_call=7.06,rejected_calls=0,failed_calls=0
cmdstat_hset:calls=1,usec=17,usec_per_call=17.00,rejected_calls=0,failed_calls=0
# INFO keyspace
db0:keys=994505,expires=0,avg_ttl=0,subexpiry=0

keyspace_hits และ keyspace_misses ให้อัตรา cache hit, evicted_keys และ expired_keys แสดงแรงกดดันของหน่วยความจำ, commandstats บอกว่าคำสั่งไหนร้อนและแต่ละครั้งเฉลี่ยกี่ไมโครวินาที, และ mem_fragmentation_ratio เกินราว 1.4 คือสิ่งที่ MEMORY DOCTOR บ่นด้านล่าง

INFO server
INFO memory
INFO keyspace

Redis บันทึกคำสั่งที่ เวลารัน เกิน slowlog-log-slower-than ไมโครวินาที (ค่าเริ่มต้น 10000 = 10 ms) ในวงแหวน slowlog-max-len entry (ค่าเริ่มต้น 128) เวลาที่รอในคิวหรือเขียนคำตอบลง socket ไม่นับ ผมบังคับให้เกิด entry โดยรัน KEYS * กับราวหนึ่งล้าน key:

$ redis-cli SLOWLOG RESET
$ redis-cli KEYS '*' > /dev/null
$ redis-cli SLOWLOG GET 1
1) 1) (integer) 1 <- entry id
2) (integer) 1790753365 <- unix time
3) (integer) 150614 <- execution time in microseconds (150 ms)
4) 1) "KEYS" <- the command and its arguments
2) "*"
5) "127.0.0.1:57960" <- client address
6) "" <- client name (CLIENT SETNAME)
7) (integer) 2 <- number of original arguments

SLOWLOG LEN นับ entry และ SLOWLOG RESET ล้าง บน Mac เครื่องนี้ KEYS * บน 126 529 key ต่ำกว่าเกณฑ์ 10 ms และไม่ถูกบันทึกเลย นี่คือเหตุที่ KEYS “ไม่เป็นอันตราย” ตอนพัฒนากลายเป็นเหตุการณ์เมื่อข้อมูลโต

cli/tsl-tooling-1.redis
127.0.0.1:6379> CLIENT SETNAME reporter
OK
127.0.0.1:6379> CLIENT GETNAME
"reporter"
127.0.0.1:6379> SET user:2:name ada
OK
127.0.0.1:6379> SET user:2:age 36
OK
127.0.0.1:6379> MEMORY USAGE user:2:name
(integer) 40
127.0.0.1:6379> MEMORY USAGE user:2:age
(integer) 29
127.0.0.1:6379> HSET user:1 name ada age 36
(integer) 2
127.0.0.1:6379> OBJECT ENCODING user:1
"listpack"
127.0.0.1:6379> MEMORY USAGE user:1
(integer) 50
127.0.0.1:6379> OBJECT FREQ user:1
(error) ERR An LFU maxmemory policy is not selected, access frequency not tracked. Please note that when switching between policies at runtime LRU and LFU data will take some time to adjust.
127.0.0.1:6379> CONFIG GET slowlog-log-slower-than
1) "slowlog-log-slower-than"
2) "10000"
127.0.0.1:6379> CONFIG GET slowlog-max-len
1) "slowlog-max-len"
2) "128"
127.0.0.1:6379> CONFIG GET busy-reply-threshold
1) "busy-reply-threshold"
2) "5000"
  • CLIENT SETNAME ติดชื่อให้ connection เพื่อให้จำได้ใน CLIENT LIST และใน SLOWLOG (field ที่ 6)
  • MEMORY USAGE key คือจำนวนไบต์ที่ key ใช้ รวม overhead object สอง field แบบ hash ใช้ 50 ไบต์; แบบสอง string key ใช้ 40 + 29 = 69 นั่นคือฐานที่วัดได้ของ “hash ถูกกว่าหนึ่ง key ต่อ field” สำหรับ object เล็ก (hash เป็น listpack แบบกะทัดรัดที่นี่)
  • OBJECT FREQ ต้องใช้ maxmemory-policy แบบ LFU; บน policy เริ่มต้นมัน error ดังที่แสดง
CLIENT LIST
CLIENT GETNAME
CLIENT INFO

ทั้งคู่รันจาก shell และเดินไปทั่ว keyspace ด้วย SCAN จึงไม่บล็อกเซิร์ฟเวอร์ (ยังใช้ CPU และเครือข่าย เพิ่ม -i 0.1 เพื่อหน่วงระหว่าง batch) --bigkeys output จริง:

# Scanning the entire keyspace to find biggest keys as well as
# average sizes per key type. You can use -i 0.1 to sleep 0.1 sec
# per 100 SCAN commands (not usually needed).
[00.00%] Biggest string found so far "key:000000142688" with 3 bytes
[08.20%] Biggest hash found so far "user:profile:1" with 4 fields
[65.20%] Biggest string found so far "session:heavy" with 5000 bytes
[81.40%] Biggest stream found so far "events" with 1 entries
-------- summary -------
Sampled 126529 keys in the keyspace!
Total key length in bytes is 2024420 (avg len 16.00)
Biggest list found "log:events" has 10 items
Biggest hash found "user:profile:1" has 4 fields
Biggest stream found "events" has 1 entries
Biggest string found "session:heavy" has 5000 bytes
Biggest set found "tags" has 3 members
Biggest zset found "board" has 4 members
1 lists with 10 items (00.00% of keys, avg size 10.00)
126524 strings with 384569 bytes (100.00% of keys, avg size 3.04)

(ตัดบรรทัด progress และตารางต่อชนิดบางส่วน) สังเกตรูปแบบ: Biggest string found "session:heavy" has 5000 bytes (key ในเครื่องหมายคำพูดคู่ ขนาดเป็นไบต์สำหรับ string และจำนวนรายการสำหรับชนิดอื่น) ซึ่งต่างจากตัวอย่าง output ที่บทเวอร์ชันก่อนแสดง --bigkeys วัด ความยาว/cardinality ไม่ใช่หน่วยความจำ set 3 สมาชิกอาจใหญ่กว่า string ก็ได้ --keystats ของ Redis 8 เพิ่มมุมมองหน่วยความจำและการกระจาย:

--- Top 10 key sizes ---
1 5.03K string "session:heavy"
2 286B stream "events"
3 66B list "log:events"
4 60B hash "user:profile:1"
5 51B zset "board"
...
--- Top size per type ---
string "session:heavy" is 5.03K
stream "events" is 286B
Key size Percentile Total keys
-------- ---------- -----------
39B 0.0008% 1
48B 99.9960% 126524
5.03K 100.0000% 126529
Type Total keys Keys % Tot size Avg size Total length/card Avg ln/card
--------- ------------ ------- -------- -------- ------------------ -----------
string 126524 100.00% 5.80M 48B 375.56K 3B

redis-cli --memkeys แนวคิดเดียวกันโดยใช้ MEMORY USAGE ต่อ key (Biggest string found "session:heavy" has 5152 bytes) ใช้ --keystats เมื่ออยากได้ percentile ของขนาด

scripts/tsl-tooling-scan.sh
# keys matching a pattern (SCAN under the hood)
redis-cli --scan --pattern 'session:*'
# count matching keys
redis-cli --scan --pattern 'key:0000001*' | wc -l

output จริง: session:heavy สำหรับอันแรก และ 86436 สำหรับอันที่สองบนข้อมูลราว 1 ล้าน key การเรียก SCAN แต่ละครั้งแตะ keyspace เพียงส่วนที่มีขอบเขต (Keys and SCAN)

KEYS เป็น O(N) ตามจำนวน key ใน database และรันใน command thread ดังนั้นทุกอย่างอื่นต้องรอ ผมวัดว่า client อื่นรอนานเท่าไรขณะ KEYS * รันกับ 994 505 key เทียบกับการเดินแบบเดียวกันด้วย SCAN:

src/tsl-tooling-keys-latency.ts
import { Redis } from 'ioredis';
const url = process.env.REDIS_URL!;
const admin = new Redis(url);
const probe = new Redis(url);
// A second connection pings every 5 ms and records the worst round trip while the admin connection works.
async function worstPing<T>(work: () => Promise<T>) {
let worst = 0;
let running = true;
const loop = (async () => {
while (running) {
const t = performance.now();
await probe.ping();
worst = Math.max(worst, performance.now() - t);
await new Promise((r) => setTimeout(r, 5));
}
})();
const t0 = performance.now();
const result = await work();
const took = performance.now() - t0;
running = false;
await loop;
return { result, took, worst };
}
const size = await admin.dbsize();
const k = await worstPing(() => admin.keys('*'));
console.log(`KEYS * : ${size} keys, ${(k.result as string[]).length} returned in ${k.took.toFixed(0)} ms, worst PING from another client: ${k.worst.toFixed(0)} ms`);
const s = await worstPing(async () => {
let n = 0;
for await (const batch of admin.scanStream({ count: 1000 })) n += (batch as string[]).length;
return n;
});
console.log(`SCAN COUNT 1000: ${s.result} keys in ${s.took.toFixed(0)} ms, worst PING from another client: ${s.worst.toFixed(0)} ms`);
admin.disconnect();
probe.disconnect();

output จริง (Mac เครื่องนี้, ~1 ล้าน key):

KEYS * : 994505 keys, 994505 returned in 583 ms, worst PING from another client: 210 ms
SCAN COUNT 1000: 994505 keys in 1902 ms, worst PING from another client: 3 ms

KEYS * จบเร็วกว่าโดยรวม (583 ms) แต่ทำให้ client อื่นทุกตัวค้างนานถึง 210 ms; SCAN ใช้เวลานานกว่า (1902 ms ใน 995 round trip) และไม่เคยทำให้ client อื่นล่าช้าเกิน 3 ms นั่นคือการแลกเปลี่ยน: SCAN ให้การหยุดที่มีขอบเขตต่อการเรียก แลกกับเวลารวมและโมเดลความสอดคล้องที่มีรายการซ้ำได้ (การรับประกันของ SCAN)

scripts/tsl-tooling-latency.sh
redis-cli --latency # continuous min / max / avg / samples
redis-cli --latency-history # a new line every 15 s (change with -i)
redis-cli --latency-dist # latency spectrum

output จริงของ --latency (หลัง 3 วินาที) และ --latency-history -i 2 (สามบรรทัด):

0.048 0.250 0.068 75 <- --latency: min max avg (milliseconds) and number of samples, redrawn in place
0.125 0.698 0.223 61 <- --latency-history: a fresh line per interval, same columns
0.125 0.698 0.229 62
0.125 0.698 0.230

--latency-dist ไม่ใช่ histogram แบบ ASCII: มันพิมพ์คำอธิบายสัญลักษณ์และ สเปกตรัมสี (พื้นหลัง ANSI 256 สีกับตัวอักษร . - * #) หนึ่งแถวต่อช่วงเวลา จึงต้องใช้เทอร์มินัลที่รองรับสี --latency วัด round trip ของ PING จึงรวมเครือข่ายและการรอคิว ไม่ใช่แค่เวลาของคำสั่ง

ภายในเซิร์ฟเวอร์ LATENCY DOCTOR รายงาน latency spike แต่การเฝ้าดู latency ปิดอยู่เป็นค่าเริ่มต้น:

$ redis-cli LATENCY DOCTOR
I'm sorry, Dave, I can't do that. Latency monitoring is disabled in this Redis instance. You may use "CONFIG SET latency-monitor-threshold <milliseconds>." in order to enable it. ...
$ redis-cli CONFIG SET latency-monitor-threshold 100 # record events slower than 100 ms
OK
$ redis-cli --no-raw LATENCY LATEST
(empty array)

รายงานปิดอยู่จนกว่าคุณจะตั้ง threshold เมื่อเปิดแล้ว LATENCY LATEST และ LATENCY HISTORY event แสดง spike ที่มันเห็น (ว่างที่นี่: ยังไม่มีอะไรเกิน 100 ms) Redis อธิบายฟีเจอร์นี้ทั้งหมดในคู่มือ latency monitor

$ redis-cli MEMORY DOCTOR
Sam, I detected a few issues in this Redis instance memory implants:
* High total RSS: This instance has a memory fragmentation and RSS overhead greater than 1.4 (this means that the Resident Set Size of the Redis process is much larger than the sum of the logical allocations Redis performed). ...

มันแปลง mem_fragmentation_ratio 1.42 (หลังโหลดข้อมูลจำนวนมากเข้าคอนเทนเนอร์นี้) เป็นคำวินิจฉัยภาษาคน ถือเป็นคำใบ้ ไม่ใช่คำตัดสิน: มันชี้ว่าต้องดูอะไรใน INFO memory

$ redis-cli MONITOR
OK
1790753481.575992 [0 127.0.0.1:54300] "SET" "foo" "bar"
1790753481.662979 [0 127.0.0.1:54316] "GET" "foo"
1790753481.732532 [0 127.0.0.1:54318] "HSET" "h" "a" "1"

แต่ละบรรทัดคือ Unix timestamp ระดับไมโครวินาที ตามด้วย database และ address ของ client แล้วจึงเป็นคำสั่ง มันแสดงสิ่งที่แอปส่งจริงๆ ซึ่งมีค่ามากสำหรับ session ดีบักสั้นๆ และมีต้นทุนด้วย เอกสาร Redis เตือนว่า “a single MONITOR client can reduce the throughput by more than 50%” ใน benchmark (ที่ไม่เป็นวิทยาศาสตร์) ของเขา (MONITOR) ผมวัดด้วย redis-benchmark -n 300000 -c 50 -t set,get ในคอนเทนเนอร์ ทั้งมีและไม่มี redis-cli MONITOR หนึ่งตัวต่ออยู่ (ทิ้ง output):

baseline SET 211 714 / 226 757 req/s GET 229 007 / 230 061 req/s p50 0.119 ms
one MONITOR client SET 188 323 / 166 389 req/s GET 196 979 / 158 311 req/s p50 0.151-0.183 ms
after disconnecting SET 227 790 req/s GET 225 903 req/s p50 0.119 ms

ในการตั้งค่านี้ MONITOR หนึ่งตัวกิน throughput ราว 10-30 % และดัน p50 latency จาก 0.119 ms เป็น 0.15-0.18 ms; throughput กลับมาทันทีหลังมันตัดการเชื่อมต่อ คำกล่าวเดิมที่ว่ามัน “เพิ่มโหลดการเขียนเป็นสองเท่า” ไม่ตรงกับที่ทั้งเอกสารและการวัดนี้บอก ต้นทุนเป็นของจริง โตขึ้นตามจำนวน monitor และ reader ที่ช้า (ที่ output buffer จะโต) และขนาดขึ้นกับ workload ของคุณ ดังนั้นอย่าปล่อยให้รันใน production

$ redis-cli CLIENT LIST
id=97 addr=127.0.0.1:46948 laddr=127.0.0.1:6379 fd=20 name= age=0 idle=0 flags=N db=0 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=26 qbuf-free=20448 argv-mem=10 multi-mem=0 rbs=16384 rbp=16384 obl=0 oll=0 omem=0 ...

หนึ่งบรรทัดต่อ connection: id, addr, name (ตั้งด้วย CLIENT SETNAME), age และ idle เป็นวินาที, flags, db ปัจจุบัน, sub/psub (subscription), multi (คำสั่งที่เข้าคิวใน MULTI), ขนาด buffer (qbuf, omem) และ cmd ล่าสุด ตัด connection ที่ค้างด้วย CLIENT KILL ID 97

Redis Insight คือ desktop client อย่างเป็นทางการ เอกสารอธิบายว่าเป็นเครื่องมือสำหรับแสดงภาพและปรับแต่งข้อมูลทั้งแบบ GUI และ CLI มันเป็น front end ที่สะดวกสำหรับสิ่งที่บทนี้ทำจาก shell รายละเอียดการดาวน์โหลดและฟีเจอร์อยู่ที่หน้า Redis Insight (ทั้งสองลิงก์เปิดได้ตอนที่ผมตรวจ)

AI เขียน endpoint ของแอดมิน “ตอนนี้มี session ใช้งานกี่ตัว?”:

🐛 หา bug ในโค้ดนี้

app.get('/admin/active-sessions', async (_req, res) => {
const keys = await redis.keys('session:*'); // "simple and correct"
res.json({ active: keys.length });
});
เฉลย

KEYS เป็น O(N) ทั่วทั้ง database และบล็อก command thread จนเสร็จ: ในการรันข้างบนมันใช้ 583 ms บนหนึ่งล้าน key และทำให้ PING พร้อมกันรอ 210 ms และที่ 150 ms มันปรากฏใน SLOWLOG เป็นคำสั่งช้า (บนชุดข้อมูลเล็กกว่าแปดเท่า 126 529 key มันไม่ถึงเกณฑ์ 10 ms ด้วยซ้ำ นั่นคือเหตุที่มัน “ทำงานได้” ตอนพัฒนา) วนด้วย SCAN (latency พร้อมกันที่แย่สุด 3 ms) หรือดีกว่านั้นคือเก็บคำตอบไว้ใน counter หรือ set เพื่อไม่ต้อง scan เลย:

let n = 0;
for await (const batch of redis.scanStream({ match: 'session:*', count: 1000 })) n += (batch as string[]).length;
res.json({ active: n });

การวินิจฉัย Redis มีสองแบบ: เครื่องมือวัด ที่อ่านมาตรวัดที่เซิร์ฟเวอร์เก็บอยู่แล้ว (INFO, SLOWLOG, MEMORY USAGE) และ หัววัดที่ให้เซิร์ฟเวอร์ทำงานเพิ่ม (KEYS, MONITOR, การรัน --scan ขนาดใหญ่) เครื่องมือวัดอ่านตามตารางเวลาได้อย่างปลอดภัย หัววัดเหมือนเอามือใส่เครื่องจักรที่กำลังเดิน จึงต้องสั้น เจาะจง และอยู่นอกเส้นทางที่ร้อน

ตัวเลือกข้อดีข้อเสีย
SLOWLOG + INFO statsเปิดตลอด overhead แทบเป็นศูนย์บันทึกเฉพาะเวลารันที่เกินเกณฑ์; ไม่มีสตรีมสด
MONITORเห็นทุกคำสั่งที่เข้ามาวัดได้ throughput หาย 10-30 % ที่นี่ (เอกสาร: มากกว่า 50% ในการทดสอบของเขา); โตตามจำนวน monitor และ reader ที่ช้า
--bigkeys / --keystats / --scanภาพรวมทั้ง keyspace โดยไม่บล็อกใช้ CPU และเครือข่ายขณะรัน; --bigkeys นับรายการ ไม่ใช่ไบต์
KEYS patternคำสั่งเดียว ได้ทุกอย่างพร้อมกันทำให้ client อื่นค้าง 210 ms บน 1M key
การเฝ้าดู LATENCYระบุชื่อ event ที่ก่อ spikeปิดเป็นค่าเริ่มต้น; ต้องตั้ง threshold
Redis Insightเห็นภาพ มี CLI ในตัวต้องติดตั้งเพิ่มและเข้าถึงเครือข่ายได้
  • “MONITOR เพิ่มโหลดการเขียนเป็นสองเท่า” เอกสารวัดว่า throughput ลดมากกว่า 50% ในการทดสอบของเขา ที่นี่ลด 10-30% ทั้งสองไม่ใช่ “สองเท่า” และแพงเกินกว่าจะเปิดทิ้งไว้
  • “--bigkeys แสดง key ใหญ่สุดตามหน่วยความจำ” มันแสดงความยาวและ cardinality; --memkeys และ --keystats แสดงไบต์
  • “--latency-dist วาด histogram แบบ ASCII” มันพิมพ์สเปกตรัมสีสำหรับเทอร์มินัลสี
  • “คำสั่งที่เร็วบนแล็ปท็อปของฉันจะเร็วใน production” KEYS * บน 126 529 key ไม่ถึงเกณฑ์ slowlog 10 ms ด้วยซ้ำ บนหนึ่งล้าน key ใช้เวลารัน 150 ms
  • “slowlog รวมเวลาเครือข่าย” มันบันทึกเวลารันเท่านั้น
  • KEYS * ในโค้ดแอป — มันบล็อกทุกคน (วัดได้ค้าง 210 ms)
  • เปิด MONITOR ทิ้งไว้ — ภาษี throughput ถาวร
  • ไม่ดู SLOWLOG หรือ INFO stats จนกว่าจะเกิดเหตุ — อ่านเป็นประจำ (commandstats บอกคำสั่งที่ร้อน)
  • อ่าน --bigkeys เป็นไบต์ — ใช้ --keystats/MEMORY USAGE
  • เชื่อ LATENCY DOCTOR โดยไม่เปิดการเฝ้าดู latency — ปิดเป็นค่าเริ่มต้น

Real-world example

เอกสารของ Redis เอง มีคู่มือวินิจฉัย latency ที่สร้างรอบ latency monitor และเตือนเรื่อง overhead ของ MONITOR ในหน้า MONITOR

คำสั่งใดแสดง N คำสั่งล่าสุดที่เวลารันเกินเกณฑ์?
MONITOR หนึ่งตัวที่ต่ออยู่กินอะไรในการรัน redis-benchmark?
flag ของ redis-cli ใดรายงาน key ที่ใหญ่สุดของแต่ละชนิดตามความยาวหรือ cardinality?
ทำไม redis.keys('session:*') ใน request handler จึงเป็น bug บน keyspace ใหญ่?
hash HSET user:1 name ada age 36 ใช้ 50 ไบต์ ขณะที่ข้อมูลเดียวกันแบบสอง string key ใช้ 40 + 29 นี่แสดงอะไร?
redis-cli --latency-dist พิมพ์อะไร?