diff --git a/.github/workflows/redis_long_run.yml b/.github/workflows/redis_long_run.yml new file mode 100644 index 00000000..6fbd5620 --- /dev/null +++ b/.github/workflows/redis_long_run.yml @@ -0,0 +1,80 @@ +name: Redis Long Run + +on: + workflow_dispatch: + inputs: + rounds: + description: "Number of Redis traffic rounds after warmup" + required: false + default: "8" + batch_size: + description: "Redis commands per round" + required: false + default: "2000" + growth_limit_mb: + description: "Allowed heap growth after warmup in MB" + required: false + default: "64" + +permissions: + contents: read + +jobs: + redis-long-run: + runs-on: ubuntu-22.04 + timeout-minutes: 90 + steps: + - uses: actions/checkout@v4.2.2 + with: + submodules: recursive + + - name: Set up Go + uses: actions/setup-go@v5.3.0 + with: + go-version: '1.23.3' + + - name: Build + run: | + /bin/bash init_env.sh + make clean && make build-bpf && make + + - name: Provision LVH VM + uses: cilium/little-vm-helper@v0.0.28 + with: + test-name: redis-long-run + image-version: '5.15-20240912.022020' + cpu: 2 + mem: '4G' + host-mount: ./ + install-dependencies: 'true' + cmd: | + chmod +x /host/kyanos + + - name: Install VM dependencies + uses: cilium/little-vm-helper@v0.0.28 + with: + provision: 'false' + cmd: | + apt-get update + apt-get install -y redis-tools python3 curl + + - name: Run Redis long-run test + uses: cilium/little-vm-helper@v0.0.28 + env: + REDIS_LONG_RUN_ROUNDS: ${{ github.event.inputs.rounds || '8' }} + REDIS_LONG_RUN_BATCH_SIZE: ${{ github.event.inputs.batch_size || '2000' }} + REDIS_LONG_RUN_GROWTH_LIMIT_MB: ${{ github.event.inputs.growth_limit_mb || '64' }} + REDIS_LONG_RUN_OUTPUT_DIR: /host/testdata/output/redis-long-run + with: + provision: 'false' + cmd: | + set -euxo pipefail + mkdir -p /host/testdata/output/redis-long-run + bash /host/testdata/test_redis_long_run.sh 'sudo /host/kyanos' + + - name: Upload long-run artifacts + if: always() + uses: actions/upload-artifact@v4.6.1 + with: + name: redis-long-run-artifacts + path: testdata/output/redis-long-run diff --git a/agent/agent.go b/agent/agent.go index ce1762f3..289a7a42 100644 --- a/agent/agent.go +++ b/agent/agent.go @@ -17,6 +17,7 @@ import ( "kyanos/bpf/loader" "kyanos/common" "kyanos/version" + "net/http" "os" "os/exec" "os/signal" @@ -26,7 +27,7 @@ import ( "syscall" "time" - _ "net/http/pprof" + "net/http/pprof" "github.com/cilium/ebpf/rlimit" gops "github.com/google/gops/agent" @@ -70,6 +71,7 @@ func SetupAgent(options ac.AgentOptions) { context.Background(), syscall.SIGINT, syscall.SIGTERM, ) options.Ctx = ctx + startPprofServer(options) defer stopFunc() @@ -252,3 +254,49 @@ func startGopsServer(opts ac.AgentOptions) { } } } + +func startPprofServer(opts ac.AgentOptions) { + if !opts.EnablePprof { + return + } + + addr := opts.GetPprofAddr() + displayAddr := addr + if strings.HasPrefix(addr, ":") { + displayAddr = "localhost" + addr + } + + mux := http.NewServeMux() + mux.HandleFunc("/debug/pprof/", pprof.Index) + mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline) + mux.HandleFunc("/debug/pprof/profile", pprof.Profile) + mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol) + mux.HandleFunc("/debug/pprof/trace", pprof.Trace) + mux.HandleFunc("/debug/pprof/{name}", pprof.Index) + + server := &http.Server{ + Addr: addr, + Handler: mux, + ReadHeaderTimeout: 10 * time.Second, + IdleTimeout: 120 * time.Second, + } + + go func() { + common.AgentLog.Infof("Starting pprof server on http://%s/debug/pprof/", displayAddr) + common.AgentLog.Info("pprof endpoints: /debug/pprof/heap, /debug/pprof/profile, /debug/pprof/goroutine") + if err := server.ListenAndServe(); err != nil && err != http.ErrServerClosed { + common.AgentLog.Errorf("Failed to start pprof server: %v", err) + } + }() + + go func() { + <-opts.Ctx.Done() + shutdownCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + if err := server.Shutdown(shutdownCtx); err != nil { + common.AgentLog.Errorf("Failed to shutdown pprof server: %v", err) + } else { + common.AgentLog.Info("pprof server shutdown gracefully") + } + }() +} diff --git a/agent/common/options.go b/agent/common/options.go index f9d6288d..533b89c1 100644 --- a/agent/common/options.go +++ b/agent/common/options.go @@ -50,6 +50,8 @@ type AgentOptions struct { ConntrackCloseWaitTimeMills int MaxAllowStuckTimeMills int StartGopsServer bool + EnablePprof bool + PprofAddr string FilterComm string ProcessExecEventChannel chan *bpf.AgentProcessExecEvent @@ -74,6 +76,13 @@ type AgentOptions struct { FirstPacketEventMapPageNum int } +func (o AgentOptions) GetPprofAddr() string { + if o.PprofAddr == "" { + return "localhost:6060" + } + return o.PprofAddr +} + func (o AgentOptions) FilterByContainer() bool { return o.ContainerId != "" || o.ContainerName != "" || o.PodName != "" } diff --git a/agent/protocol/common.go b/agent/protocol/common.go index 1eb6726d..a82ca2d3 100644 --- a/agent/protocol/common.go +++ b/agent/protocol/common.go @@ -4,6 +4,11 @@ import ( "kyanos/agent/buffer" ) +const ( + maxPendingParsedMessages = 1024 + maxPendingParsedMessagesBytes = 16 * 1024 * 1024 +) + func matchByTimestamp(reqStream *ParsedMessageQueue, respStream *ParsedMessageQueue) []Record { if len(*reqStream) == 0 || len(*respStream) == 0 { return nil @@ -36,6 +41,41 @@ func matchByTimestamp(reqStream *ParsedMessageQueue, respStream *ParsedMessageQu return records } +func trimPendingParsedMessages(queue *ParsedMessageQueue, maxCount int, maxBytes int) { + if queue == nil || len(*queue) == 0 { + return + } + + start := len(*queue) + keptCount := 0 + keptBytes := 0 + for i := len(*queue) - 1; i >= 0; i-- { + msgBytes := max(1, (*queue)[i].ByteSize()) + if keptCount > 0 && (keptCount+1 > maxCount || keptBytes+msgBytes > maxBytes) { + break + } + start = i + keptCount++ + keptBytes += msgBytes + } + + if start > 0 { + *queue = (*queue)[start:] + } +} + +func trimPendingParsedMessagesForStream(streams map[StreamId]*ParsedMessageQueue, streamID StreamId) { + queue, ok := streams[streamID] + if !ok || queue == nil { + return + } + + trimPendingParsedMessages(queue, maxPendingParsedMessages, maxPendingParsedMessagesBytes) + if len(*queue) == 0 { + delete(streams, streamID) + } +} + func CreateFrameBase(streamBuffer *buffer.StreamBuffer, readBytes int) (FrameBase, bool) { seq := streamBuffer.Head().LeftBoundary() ts, ok := streamBuffer.FindTimestampBySeq(seq) diff --git a/agent/protocol/redis..go b/agent/protocol/redis..go index 4a1199a4..7b69b67c 100644 --- a/agent/protocol/redis..go +++ b/agent/protocol/redis..go @@ -382,9 +382,14 @@ func (r *RedisStreamParser) Match(reqStreams map[StreamId]*ParsedMessageQueue, r reqStream, ok1 := reqStreams[0] respStream, ok2 := respStreams[0] if !ok1 || !ok2 { + trimPendingParsedMessagesForStream(reqStreams, 0) + trimPendingParsedMessagesForStream(respStreams, 0) return []Record{} } - return matchByTimestamp(reqStream, respStream) + records := matchByTimestamp(reqStream, respStream) + trimPendingParsedMessagesForStream(reqStreams, 0) + trimPendingParsedMessagesForStream(respStreams, 0) + return records } func ParseSize(decoder *BinaryDecoder) (int, error) { str, err := decoder.ExtractStringUntil(kTerminalSequence) diff --git a/agent/protocol/redis_test.go b/agent/protocol/redis_test.go new file mode 100644 index 00000000..f91a4338 --- /dev/null +++ b/agent/protocol/redis_test.go @@ -0,0 +1,71 @@ +package protocol + +import ( + "fmt" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func newTestRedisMessage(seq uint64, timestamp uint64, byteSize int, isReq bool) *RedisMessage { + return &RedisMessage{ + FrameBase: NewFrameBase(timestamp, byteSize, seq), + payload: fmt.Sprintf("payload-%d", seq), + command: "GET", + isReq: isReq, + } +} + +func TestRedisMatchTrimsPendingRequestsWithoutResponses(t *testing.T) { + reqQueue := ParsedMessageQueue{} + for i := 0; i < maxPendingParsedMessages+128; i++ { + reqQueue = append(reqQueue, newTestRedisMessage(uint64(i+1), uint64(i+1), 64, true)) + } + + parser := RedisStreamParser{} + reqStreams := map[StreamId]*ParsedMessageQueue{0: &reqQueue} + + records := parser.Match(reqStreams, map[StreamId]*ParsedMessageQueue{}) + + require.Empty(t, records) + require.Contains(t, reqStreams, StreamId(0)) + assert.Len(t, *reqStreams[0], maxPendingParsedMessages) + assert.Equal(t, uint64(129), (*reqStreams[0])[0].Seq()) +} + +func TestRedisMatchTrimsPendingResponsesWithoutRequests(t *testing.T) { + respQueue := ParsedMessageQueue{} + for i := 0; i < maxPendingParsedMessages+64; i++ { + respQueue = append(respQueue, newTestRedisMessage(uint64(i+1), uint64(i+1), 64, false)) + } + + parser := RedisStreamParser{} + respStreams := map[StreamId]*ParsedMessageQueue{0: &respQueue} + + records := parser.Match(map[StreamId]*ParsedMessageQueue{}, respStreams) + + require.Empty(t, records) + require.Contains(t, respStreams, StreamId(0)) + assert.Len(t, *respStreams[0], maxPendingParsedMessages) + assert.Equal(t, uint64(65), (*respStreams[0])[0].Seq()) +} + +func TestRedisMatchRemovesEmptyQueuesAfterSuccessfulMatch(t *testing.T) { + reqQueue := ParsedMessageQueue{ + newTestRedisMessage(1, 100, 16, true), + } + respQueue := ParsedMessageQueue{ + newTestRedisMessage(2, 200, 16, false), + } + + parser := RedisStreamParser{} + reqStreams := map[StreamId]*ParsedMessageQueue{0: &reqQueue} + respStreams := map[StreamId]*ParsedMessageQueue{0: &respQueue} + + records := parser.Match(reqStreams, respStreams) + + require.Len(t, records, 1) + assert.NotContains(t, reqStreams, StreamId(0)) + assert.NotContains(t, respStreams, StreamId(0)) +} diff --git a/cmd/root.go b/cmd/root.go index 783f050e..6612ee42 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -105,6 +105,8 @@ func init() { rootCmd.PersistentFlags().IntVar(&options.MaxAllowStuckTimeMills, "max-allow-stuck-time-mills", 1000, "--max-allow-stuck-time-mills 100") rootCmd.PersistentFlags().BoolVar(&options.StartGopsServer, "gops", false, "start gops server") + rootCmd.PersistentFlags().BoolVar(&options.EnablePprof, "pprof", false, "enable pprof HTTP endpoint for profiling (WARNING: exposes sensitive profiling data; do not use on untrusted networks)") + rootCmd.PersistentFlags().StringVar(&options.PprofAddr, "pprof-addr", "127.0.0.1:6060", "pprof HTTP server address (WARNING: binding to non-loopback addresses, e.g. \":6060\" or \"0.0.0.0:6060\", will expose profiling data to the network)") rootCmd.PersistentFlags().MarkHidden("default-log-level") rootCmd.PersistentFlags().MarkHidden("agent-log-level") diff --git a/docs/cn/debug-tips.md b/docs/cn/debug-tips.md index a20cfe54..adb9cae2 100644 --- a/docs/cn/debug-tips.md +++ b/docs/cn/debug-tips.md @@ -85,6 +85,50 @@ VSCODE 直接打开项目即可,.vscode/launch.json 添加配置如下: 注意添加 `--debug-output` 参数。 +## 性能分析(Profiling) + +Kyanos 提供了 pprof 端点用于运行时性能分析和调试。你可以使用 `--pprof` 标志启用 pprof HTTP 服务器: + +```bash +./kyanos watch --pprof +``` + +默认情况下,pprof 服务器监听 `localhost:6060`。你可以使用 `--pprof-addr` 标志自定义监听地址: + +```bash +./kyanos watch --pprof --pprof-addr="0.0.0.0:9090" +``` + +可用的 pprof 端点: + +| 端点 | 说明 | +|------|------| +| `/debug/pprof/` | 索引页面,显示所有可用的 profile | +| `/debug/pprof/heap` | 内存堆 profile | +| `/debug/pprof/profile` | CPU profile(默认 30 秒) | +| `/debug/pprof/goroutine` | Goroutine 堆栈信息 | +| `/debug/pprof/allocs` | 内存分配 profile | +| `/debug/pprof/block` | 阻塞 profile | +| `/debug/pprof/mutex` | 锁竞争 profile | + +使用示例: + +```bash +# 采集 CPU profile +curl -o cpu.pprof http://localhost:6060/debug/pprof/profile?seconds=30 +go tool pprof cpu.pprof + +# 查看堆内存 profile +go tool pprof http://localhost:6060/debug/pprof/heap + +# 查看 goroutine 堆栈 +curl http://localhost:6060/debug/pprof/goroutine?debug=1 +``` + +> [!TIP] +> +> pprof 端点对于诊断 Kyanos 自身的性能问题、内存泄漏或 goroutine 泄漏非常有用。 + ## 源码结构 ``` diff --git a/docs/debug-tips.md b/docs/debug-tips.md index 089bd4e6..31874b32 100644 --- a/docs/debug-tips.md +++ b/docs/debug-tips.md @@ -94,6 +94,50 @@ Make sure to add the `--debug-output` parameter. Protocol inference code can be debugged by printing logs using `bpf_printk`, refer to: https://nakryiko.com/posts/bpf-tips-printk/. +## Profiling + +Kyanos provides pprof endpoints for runtime profiling and debugging. You can enable the pprof HTTP server using the `--pprof` flag: + +```bash +./kyanos watch --pprof +``` + +By default, the pprof server listens on `localhost:6060`. You can customize the address using the `--pprof-addr` flag: + +```bash +./kyanos watch --pprof --pprof-addr="0.0.0.0:9090" +``` + +Available pprof endpoints: + +| Endpoint | Description | +|----------|-------------| +| `/debug/pprof/` | Index page with all available profiles | +| `/debug/pprof/heap` | Memory heap profile | +| `/debug/pprof/profile` | CPU profile (30 seconds by default) | +| `/debug/pprof/goroutine` | Goroutine dump | +| `/debug/pprof/allocs` | Allocation profile | +| `/debug/pprof/block` | Block profile | +| `/debug/pprof/mutex` | Mutex contention profile | + +Example usage: + +```bash +# Capture CPU profile +curl -o cpu.pprof http://localhost:6060/debug/pprof/profile?seconds=30 +go tool pprof cpu.pprof + +# View heap profile +go tool pprof http://localhost:6060/debug/pprof/heap + +# View goroutine dump +curl http://localhost:6060/debug/pprof/goroutine?debug=1 +``` + +> [!TIP] +> +> The pprof endpoint is useful for diagnosing performance issues, memory leaks, or goroutine leaks in Kyanos itself. + ## Source Code Structure ``` diff --git a/testdata/test_redis_long_run.sh b/testdata/test_redis_long_run.sh new file mode 100644 index 00000000..acf5ddfd --- /dev/null +++ b/testdata/test_redis_long_run.sh @@ -0,0 +1,183 @@ +#!/usr/bin/env bash +. "$(dirname "$0")/common.sh" +set -euo pipefail + +CMD="${1:-}" +DOCKER_REGISTRY="${2:-}" + +if [ -z "$CMD" ]; then + echo "usage: $0 '' [docker_registry]" >&2 + exit 1 +fi + +REDIS_LONG_RUN_ROUNDS="${REDIS_LONG_RUN_ROUNDS:-8}" +REDIS_LONG_RUN_BATCH_SIZE="${REDIS_LONG_RUN_BATCH_SIZE:-2000}" +REDIS_LONG_RUN_GROWTH_LIMIT_MB="${REDIS_LONG_RUN_GROWTH_LIMIT_MB:-64}" +REDIS_LONG_RUN_PPROF_ADDR="${REDIS_LONG_RUN_PPROF_ADDR:-127.0.0.1:6060}" +REDIS_LONG_RUN_OUTPUT_DIR="${REDIS_LONG_RUN_OUTPUT_DIR:-/tmp/kyanos-redis-long-run}" +REDIS_LONG_RUN_USE_LOCAL_SERVER="${REDIS_LONG_RUN_USE_LOCAL_SERVER:-0}" + +FILE_PREFIX="${REDIS_LONG_RUN_OUTPUT_DIR}/redis_long_run" +WATCH_LOG="${FILE_PREFIX}.watch.log" +REDIS_PIPE_LOG="${FILE_PREFIX}.redis.log" +HEAP_BASELINE="${FILE_PREFIX}.baseline.pb.gz" +HEAP_FINAL="${FILE_PREFIX}.final.pb.gz" +REDIS_PID_FILE="${FILE_PREFIX}.redis.pid" + +mkdir -p "${REDIS_LONG_RUN_OUTPUT_DIR}" + +if [ -z "$DOCKER_REGISTRY" ]; then + IMAGE_NAME="redis:7.0.14" +else + IMAGE_NAME="${DOCKER_REGISTRY}/library/redis:7.0.14" +fi + +cname='test-redis-long-run' +KYANOS_PID="" +REDIS_SERVER_MODE="" + +cleanup() { + if [ -n "${KYANOS_PID}" ] && kill -0 "${KYANOS_PID}" >/dev/null 2>&1; then + kill "${KYANOS_PID}" >/dev/null 2>&1 || true + wait "${KYANOS_PID}" >/dev/null 2>&1 || true + fi + if [ "${REDIS_SERVER_MODE}" = "docker" ]; then + docker rm -f "${cname}" >/dev/null 2>&1 || true + elif [ "${REDIS_SERVER_MODE}" = "local" ] && [ -f "${REDIS_PID_FILE}" ]; then + kill "$(cat "${REDIS_PID_FILE}")" >/dev/null 2>&1 || true + rm -f "${REDIS_PID_FILE}" + fi +} +trap cleanup EXIT + +wait_for_pprof() { + local attempts=0 + until curl -fsS "http://${REDIS_LONG_RUN_PPROF_ADDR}/debug/pprof/" >/dev/null; do + attempts=$((attempts + 1)) + if [ "${attempts}" -ge 30 ]; then + echo "pprof endpoint did not become ready" >&2 + exit 1 + fi + sleep 1 + done +} + +collect_heap_profile() { + local target_file="$1" + curl -fsS "http://${REDIS_LONG_RUN_PPROF_ADDR}/debug/pprof/heap?gc=1" -o "${target_file}" +} + +profile_total_bytes() { + local target_file="$1" + PROFILE_PATH="${target_file}" python3 - <<'PY' +import os +import re +import subprocess +import sys + +profile = os.environ["PROFILE_PATH"] +cmd = ["go", "tool", "pprof", "-sample_index=inuse_space", "-top", "-nodecount=1", profile] +output = subprocess.check_output(cmd, text=True, stderr=subprocess.STDOUT) +match = re.search(r" of ([0-9.]+)([A-Za-z]+) total", output) +if not match: + sys.stderr.write(output) + raise SystemExit("failed to parse pprof total") + +value = float(match.group(1)) +unit = match.group(2) +unit_table = { + "B": 1, + "kB": 1000, + "KB": 1000, + "MB": 1000 ** 2, + "GB": 1000 ** 3, + "TB": 1000 ** 4, +} +if unit not in unit_table: + raise SystemExit(f"unknown pprof unit: {unit}") +print(int(value * unit_table[unit])) +PY +} + +generate_redis_traffic_round() { + local round="$1" + : > "${REDIS_PIPE_LOG}" + for i in $(seq 1 "${REDIS_LONG_RUN_BATCH_SIZE}"); do + local key="kyanos:longrun:${round}:${i}" + printf 'SET %s value-%s-%s\n' "${key}" "${round}" "${i}" + printf 'GET %s\n' "${key}" + printf 'DEL %s\n' "${key}" + done | redis-cli --pipe > "${REDIS_PIPE_LOG}" +} + +start_redis_server() { + if [ "${REDIS_LONG_RUN_USE_LOCAL_SERVER}" = "1" ]; then + if ! command -v redis-server >/dev/null 2>&1; then + echo "redis-server is required when REDIS_LONG_RUN_USE_LOCAL_SERVER=1" >&2 + exit 1 + fi + redis-server --save "" --appendonly no --bind 127.0.0.1 --port 6379 --daemonize yes --pidfile "${REDIS_PID_FILE}" + REDIS_SERVER_MODE="local" + return + fi + + if docker pull "${IMAGE_NAME}"; then + docker rm -f "${cname}" >/dev/null 2>&1 || true + docker run --name "${cname}" -p 6379:6379 -d "${IMAGE_NAME}" >/dev/null + REDIS_SERVER_MODE="docker" + return + fi + + if command -v redis-server >/dev/null 2>&1; then + echo "docker pull failed, falling back to local redis-server" >&2 + redis-server --save "" --appendonly no --bind 127.0.0.1 --port 6379 --daemonize yes --pidfile "${REDIS_PID_FILE}" + REDIS_SERVER_MODE="local" + return + fi + + echo "failed to start redis server with docker and no local redis-server fallback is available" >&2 + exit 1 +} + +main() { + start_redis_server + + ${CMD} watch --json-output stdout redis --remote-ports 6379 --pprof --pprof-addr "${REDIS_LONG_RUN_PPROF_ADDR}" \ + > "${WATCH_LOG}" 2>&1 & + KYANOS_PID=$! + + wait_for_pprof + sleep 5 + + generate_redis_traffic_round "warmup" + collect_heap_profile "${HEAP_BASELINE}" + + for round in $(seq 1 "${REDIS_LONG_RUN_ROUNDS}"); do + generate_redis_traffic_round "${round}" + sleep 1 + done + + collect_heap_profile "${HEAP_FINAL}" + if [ ! -s "${HEAP_BASELINE}" ] || [ ! -s "${HEAP_FINAL}" ]; then + echo "heap profiles were not captured correctly" >&2 + exit 1 + fi + + local baseline_bytes + local final_bytes + local growth_limit_bytes + baseline_bytes="$(profile_total_bytes "${HEAP_BASELINE}")" + final_bytes="$(profile_total_bytes "${HEAP_FINAL}")" + growth_limit_bytes=$((REDIS_LONG_RUN_GROWTH_LIMIT_MB * 1024 * 1024)) + + echo "baseline_bytes=${baseline_bytes}" + echo "final_bytes=${final_bytes}" + echo "growth_limit_bytes=${growth_limit_bytes}" + + if [ $((final_bytes - baseline_bytes)) -gt "${growth_limit_bytes}" ]; then + echo "heap usage grew beyond threshold during redis long-run test" >&2 + exit 1 + fi +} + +main