长稳测试与故障注入:构建可信赖的日志系统

深入分析 Seastar Log Engine 的长稳测试方法论,包括 bench_soak.sh 和 test_soak_and_fault.sh 脚本的实现,以及如何通过持续测试发现潜在问题。

为什么要长稳测试?

短期测试的盲区

短期压测只能验证峰值性能,无法发现以下问题:

短期测试能发现:
✅ 峰值吞吐量
✅ P99 延迟
✅ 基本的正确性

短期测试无法发现:
❌ 内存泄漏(需要数小时才能显现)
❌ 资源泄漏(文件描述符、内存池)
❌ 热退化(长时间运行的性能衰减)
❌ 边界条件(极端情况下的行为)
❌ 并发问题(竞态条件、死锁)

长稳测试的目标

  1. 发现资源泄漏:内存、文件描述符、线程等
  2. 验证性能稳定性:长时间运行后性能是否衰减
  3. 检测热退化:硬件在高负载下的性能衰减
  4. 模拟真实场景:长时间运行的服务行为

测试框架架构

核心测试脚本

Seastar Log Engine 提供两套长稳测试框架:

脚本用途特点
bench_soak.sh纯长稳测试按时间循环压测,统计性能稳定性
test_soak_and_fault.sh综合测试长稳 + 故障注入 + 恢复验证

架构图

┌─────────────────────────────────────────────────────────────────────┐
│                    test_soak_and_fault.sh                            │
├─────────────────────────────────────────────────────────────────────┤
│  Phase 1: Timed Soak Loop (长稳循环)                               │
│  ├─ 循环运行 log_engine_demo                                        │
│  ├─ 周期性验证日志文件                                              │
│  ├─ 周期性查询 consistency check                                    │
│  └─ 周期性 reset (可配置)                                           │
├─────────────────────────────────────────────────────────────────────┤
│  Phase 2: Query Server + Status Check (查询验证)                    │
│  ├─ 启动 HTTP/gRPC 查询服务                                          │
│  └─ 验证 /v1/status 健康状态                                         │
├─────────────────────────────────────────────────────────────────────┤
│  Phase 3: Restart After Clean Stop (正常重启)                       │
│  ├─ 正常停止引擎                                                     │
│  └─ 重启验证数据完整性                                               │
├─────────────────────────────────────────────────────────────────────┤
│  Phase 4: Broken Tail (损坏日志尾部)                                 │
│  ├─ 追加垃圾数据到 shard-0.log                                      │
│  └─ 重启验证自动修复                                                 │
├─────────────────────────────────────────────────────────────────────┤
│  Phase 5: Bad Checkpoint (损坏 checkpoint)                            │
│  ├─ 重写 checkpoint (logical_size=999999)                           │
│  └─ 重启验证 fallback 恢复                                           │
├─────────────────────────────────────────────────────────────────────┤
│  Phase 6: Stale Checkpoint (过期 checkpoint)                         │
│  ├─ 修改 checkpoint (logical_size=1)                                │
│  └─ 重启验证正确恢复                                                  │
├─────────────────────────────────────────────────────────────────────┤
│  Phase 7: Broken Gzip + Query (损坏归档)                            │
│  ├─ 破坏 gzip 文件                                                   │
│  └─ 验证查询服务的容错能力                                           │
├─────────────────────────────────────────────────────────────────────┤
│  Phase 8: Multi-Shard Consistency (多 shard 一致性)                  │
│  └─ 验证多 shard 恢复后的数据完整性                                 │
└─────────────────────────────────────────────────────────────────────┘

bench_soak.sh 详解

核心参数

./script/bench_soak.sh \
  --target log_engine \           # 目标引擎
  --duration-seconds 300 \        # 测试时长
  --messages 50000 \             # 每次运行的消息数
  --payload-size 2048 \          # 消息大小
  --batch-size 8192 \           # 批量大小
  --inflight 1 \                # 并发数
  --shards 4 \                  # shard 数量
  --ack-mode write_ack \          # 确认模式
  --checkpoint-enabled 1 \         # 启用 checkpoint
  --output-prefix my-soak-test   # 输出文件前缀

参数详解

参数类型默认值说明
--targetstringlog_engine目标引擎:log_engine/spdlog/glog
--duration-secondsint60测试持续时间(秒)
--messagesint50000每次运行的日志条数
--payload-sizeint2048每条日志的字节大小
--batch-sizeint8192批量提交大小
--inflightint1最大并发写入数
--shardsint1Seastar shard 数量
--ack-modestringwrite_ack确认模式
--flush-msint0定时 flush 间隔
--checkpoint-enabledint0是否启用 checkpoint

工作流程

# 1. 初始化
start_epoch=$(date +%s)
iteration=0

# 2. 按时间循环
while (( $(date +%s) - start_epoch < duration_seconds )); do
    iteration=$((iteration + 1))

    # 3. 清理数据目录
    cleanup_target_dirs

    # 4. 运行一次 benchmark
    run_once | tee "run-${iteration}.log"

    # 5. 提取指标并记录
    extract_metric "throughput_msg_per_sec"
    extract_metric "p99_submit_us"
    ...
done

# 6. 生成统计报告
generate_summary_report

输出文件

doc/
├── soak-log_engine-2048b-2026-05-15-143000.tsv   # 原始数据
├── soak-log_engine-2048b-2026-05-15-143000.md    # 统计报告
└── soak-log_engine-2048b-2026-05-15-143000-raw/  # 原始日志
    ├── run-1.log
    ├── run-2.log
    └── run-N.log

TSV 格式

iteration	target	ack_mode	messages	payload_size	batch_size	inflight	shards	flush_ms	checkpoint_enabled	elapsed_us	throughput_msg_per_sec	avg_submit_us	p50_submit_us	p95_submit_us	p99_submit_us
1	log_engine	write_ack	50000	2048	8192	1	1	0	0	123456	405342.12	2.47	2.01	5.12	12.34
2	log_engine	write_ack	50000	2048	8192	1	1	0	0	124567	401234.56	2.49	2.03	5.08	11.98
...

统计分析

# 生成 Markdown 统计报告
awk -F'\t' '
  NR == 1 { next }
  {
    runs += 1
    thr = $12 + 0
    p99 = $16 + 0
    thr_sum += thr
    p99_sum += p99
    if (runs == 1 || thr < thr_min) thr_min = thr
    if (runs == 1 || thr > thr_max) thr_max = thr
    if (runs == 1 || p99 > p99_max) p99_max = p99
  }
  END {
    printf "| %d | %.2f | %.2f | %.2f | %.4f | %.4f | %.4f | %.4f |\n",
      runs, thr_sum/runs, thr_min, thr_max,
      avg_sum/runs, p95_sum/runs, p99_sum/runs, p99_max
  }
' "${tsv_path}"

报告示例

# Soak Benchmark 2026-05-15

- target: `log_engine`
- ack_mode: `write_ack`
- duration_seconds: `300`
- messages_per_run: `50000`
- payload_size: `2048`
- batch_size: `8192`
- inflight: `1`
- shards: `1`

| Runs | Avg Throughput (msg/s) | Min Throughput | Max Throughput | Avg Submit (us) | Avg P95 (us) | Avg P99 (us) | Max P99 (us) |
| ---: | ---: | ---: | ---: | ---: | ---: | ---: | ---: |
| 42 | 401,234.56 | 398,123.45 | 405,678.90 | 2.48 | 5.10 | 12.16 | 15.23 |

test_soak_and_fault.sh 详解

8 阶段测试设计

# 阶段清单
declare -a phases=(
    "Soak Loop"
    "Query Server"
    "Clean Restart"
    "Broken Tail"
    "Bad Checkpoint"
    "Stale Checkpoint"
    "Broken Gzip"
    "Multi-Shard Consistency"
)

Phase 1: Timed Soak Loop

# 启动长稳循环
start_epoch=$(date +%s)
iteration=0

while (( $(date +%s) - start_epoch < SOAK_DURATION_SECONDS )); do
    iteration=$((iteration + 1))

    # 运行 demo
    run_demo

    # 验证日志文件
    verify_all_active_files

    # 周期性操作
    if (( iteration % QUERY_CHECK_INTERVAL == 0 )); then
        run_query_checks
    fi

    if (( iteration % ARCHIVE_RESET_INTERVAL == 0 )); then
        reset_data_dirs
    fi

    if (( iteration % RESTART_INTERVAL == 0 )); then
        inject_crash_and_recover
    fi
done

Phase 2: Query Server

start_query_server() {
    ./build/log_engine_query_server \
        --log-dir ./logs \
        --archive-dir ./archive \
        --http-port 18080 \
        --grpc-port 19090 &

    QUERY_SERVER_PID=$!
    sleep 2  # 等待启动
}

verify_status_endpoint() {
    local status=$(curl -s http://localhost:18080/v1/status | jq -r '.health')

    if [[ "$status" != "healthy" ]]; then
        echo "Status check failed: health=$status"
        return 1
    fi

    echo "Status check passed: health=$status"
    return 0
}

Phase 3: Clean Restart

test_clean_restart() {
    echo "=== Phase 3: Clean Restart ==="

    # 1. 正常运行
    run_demo

    # 2. 记录消息数量
    local expected_records=$(count_records)
    echo "Expected records: $expected_records"

    # 3. 正常停止(SIGTERM)
    kill $DEMO_PID
    wait $DEMO_PID

    # 4. 重启
    run_demo

    # 5. 验证数据完整性
    local actual_records=$(count_records)
    if (( actual_records >= expected_records )); then
        echo "Clean restart passed: $actual_records >= $expected_records"
        return 0
    else
        echo "Clean restart FAILED: $actual_records < $expected_records"
        return 1
    fi
}

Phase 4-6: 故障注入

Broken Tail(损坏日志尾部)

inject_broken_tail() {
    echo "=== Phase 4: Broken Tail ==="

    # 1. 正常运行
    run_demo
    local expected_valid=$(count_valid_records)
    echo "Valid records before corruption: $expected_valid"

    # 2. 停止
    kill $DEMO_PID
    wait $DEMO_PID

    # 3. 追加垃圾数据
    dd if=/dev/urandom of=./logs/shard-0.log bs=1 seek=$(stat -c%s ./logs/shard-0.log) \
        count=1024 oflag=append conv=notrunc 2>/dev/null

    # 4. 重启并验证自动修复
    run_demo

    local actual_valid=$(count_valid_records)
    # 应该恢复到损坏前的状态
    echo "Valid records after recovery: $actual_valid (expected: $expected_valid)"

    if (( actual_valid == expected_valid )); then
        echo "Broken tail recovery PASSED"
        return 0
    else
        echo "Broken tail recovery FAILED"
        return 1
    fi
}

Bad Checkpoint(损坏的 checkpoint)

inject_bad_checkpoint() {
    echo "=== Phase 5: Bad Checkpoint ==="

    # 1. 正常运行
    run_demo

    # 2. 停止
    kill $DEMO_PID
    wait $DEMO_PID

    # 3. 破坏 checkpoint 文件
    cat > ./logs/shard-0.log.checkpoint <<'EOF'
logical_size=999999
sequence=999999
rotation_index=999
EOF

    # 4. 重启并验证 fallback 恢复
    echo "Restarting with corrupted checkpoint..."
    run_demo

    # 5. 验证从文件头恢复
    local valid_size=$(get_logical_size)
    if (( valid_size < 999999 )); then
        echo "Bad checkpoint fallback PASSED: logical_size=$valid_size"
        return 0
    else
        echo "Bad checkpoint fallback FAILED: logical_size=$valid_size"
        return 1
    fi
}

Stale Checkpoint(过期的 checkpoint)

inject_stale_checkpoint() {
    echo "=== Phase 6: Stale Checkpoint ==="

    # 1. 正常运行
    run_demo

    # 2. 停止
    kill $DEMO_PID
    wait $DEMO_PID

    # 3. 修改 checkpoint 为过期状态
    cat > ./logs/shard-0.log.checkpoint <<'EOF'
logical_size=1
sequence=1
rotation_index=0
EOF

    # 4. 重启并验证
    echo "Restarting with stale checkpoint..."
    run_demo

    # 5. 验证数据完整性
    local valid_size=$(get_logical_size)
    echo "Valid size after recovery: $valid_size"

    if (( valid_size > 1 )); then
        echo "Stale checkpoint recovery PASSED"
        return 0
    else
        echo "Stale checkpoint recovery FAILED"
        return 1
    fi
}

Phase 7: Broken Gzip

inject_broken_gzip() {
    echo "=== Phase 7: Broken Gzip + Query ==="

    # 1. 触发归档
    TRIGGER_ARCHIVE=1 run_demo

    # 2. 停止
    kill $DEMO_PID
    wait $DEMO_PID

    # 3. 找到 gzip 文件并破坏
    local gzip_file=$(find ./archive -name "*.gz" | head -1)
    if [[ -n "$gzip_file" ]]; then
        echo "Corrupting gzip file: $gzip_file"
        dd if=/dev/urandom of="$gzip_file" bs=1024 count=10 conv=notrunc 2>/dev/null
    fi

    # 4. 启动查询服务
    start_query_server

    # 5. 验证容错能力
    local query_result=$(query_with_archive 2>&1)
    if echo "$query_result" | grep -q "error\|fail"; then
        echo "Broken gzip handled gracefully: query returned error as expected"
        return 0
    else
        echo "Broken gzip FAILED: query should fail"
        return 1
    fi
}

Phase 8: Multi-Shard Consistency

test_multishard_consistency() {
    echo "=== Phase 8: Multi-Shard Consistency ==="

    local shards=4

    # 1. 运行多 shard 测试
    SHARDS=$shards run_demo

    # 2. 验证每个 shard 的数据
    local all_valid=true
    for (( i=0; i<$shards; i++ )); do
        local valid=$(verify_shard $i)
        if (( valid == 0 )); then
            echo "Shard $i: INVALID"
            all_valid=false
        else
            echo "Shard $i: $valid valid records"
        fi
    done

    # 3. 注入崩溃并重启
    kill -9 $DEMO_PID
    sleep 1
    run_demo

    # 4. 再次验证
    for (( i=0; i<$shards; i++ )); do
        local valid=$(verify_shard $i)
        if (( valid == 0 )); then
            echo "Shard $i after recovery: INVALID"
            all_valid=false
        fi
    done

    if $all_valid; then
        echo "Multi-shard consistency PASSED"
        return 0
    else
        echo "Multi-shard consistency FAILED"
        return 1
    fi
}

测试结果分析方法

发现的问题类型

通过长稳测试发现的问题:

问题类型发现阶段表现
内存泄漏Phase 1内存持续增长
文件描述符泄漏Phase 1达到 ulimit 上限
性能退化Phase 1吞吐逐渐下降
数据丢失Phase 3-4重启后记录数减少
恢复失败Phase 4-6checkpoint 损坏时无法恢复
查询崩溃Phase 7gzip 损坏导致 segfault

关键监控指标

# 监控命令
watch -n 1 'cat /proc/$(pgrep log_engine)/status | grep -E "VmRSS|VmSize|Fd"'

统计分析

#!/usr/bin/env python3
"""分析长稳测试结果"""
import sys
import pandas as pd

def analyze_soak_results(tsv_path):
    df = pd.read_csv(tsv_path, sep='\t')

    # 1. 性能稳定性分析
    print("=== 吞吐量稳定性 ===")
    print(f"平均值: {df['throughput_msg_per_sec'].mean():.2f} msg/s")
    print(f"标准差: {df['throughput_msg_per_sec'].std():.2f}")
    print(f"变异系数: {df['throughput_msg_per_sec'].std() / df['throughput_msg_per_sec'].mean():.4f}")

    # 2. 延迟稳定性分析
    print("\n=== 延迟稳定性 ===")
    print(f"平均 P99: {df['p99_submit_us'].mean():.2f} μs")
    print(f"最大 P99: {df['p99_submit_us'].max():.2f} μs")
    print(f"P99 标准差: {df['p99_submit_us'].std():.2f}")

    # 3. 趋势分析
    if len(df) > 10:
        df['iteration_num'] = range(len(df))
        slope = pd.Series(df['throughput_msg_per_sec']).diff().mean()
        print(f"\n=== 趋势分析 ===")
        print(f"吞吐趋势: {'下降' if slope < 0 else '上升'} {abs(slope):.2f} msg/s/iteration")

    # 4. 异常检测
    threshold = df['throughput_msg_per_sec'].mean() * 0.9
    anomalies = df[df['throughput_msg_per_sec'] < threshold]
    if len(anomalies) > 0:
        print(f"\n=== 异常检测 ===")
        print(f"发现 {len(anomalies)} 次异常(< {threshold:.0f} msg/s)")

if __name__ == '__main__':
    analyze_soak_results(sys.argv[1])

最佳实践

1. 测试时长选择

场景建议时长目的
快速回归5-10 分钟验证基本稳定性
日常测试30-60 分钟检测内存泄漏
发布前测试2-4 小时全面验证
压力测试8-24 小时检测热退化

2. 测试环境准备

# 1. 清理系统缓存
sync && echo 3 > /proc/sys/vm/drop_caches

# 2. 禁用 CPU 降频
cpupower frequency-set -g performance

# 3. 设置 ulimit
ulimit -n 1000000

# 4. 禁用 swap
swapoff -a

3. 测试参数矩阵

# 推荐测试矩阵
configs=(
    # 高吞吐场景
    "--target log_engine --shards 4 --inflight 16 --ack-mode write_ack",
    # 高可靠性场景
    "--target log_engine --shards 2 --inflight 4 --ack-mode sync_ack --checkpoint-enabled 1",
    # 对比测试
    "--target spdlog",
    "--target glog"
)

for config in "${configs[@]}"; do
    ./script/bench_soak.sh --duration-seconds 300 $config
done

4. 持续集成

# .github/workflows/soak-test.yml
name: Soak Test

on:
  schedule:
    - cron: '0 2 * * *'  # 每天凌晨 2 点

jobs:
  soak-test:
    runs-on: ubuntu-latest
    steps:
      - uses: actions/checkout@v2
      - name: Build
        run: ./script/build.sh
      - name: Run soak test
        run: ./script/bench_soak.sh --duration-seconds 3600
      - name: Run fault injection
        run: ./script/test_soak_and_fault.sh --duration-seconds 300
      - name: Upload results
        uses: actions/upload-artifact@v2
        with:
          name: soak-results
          path: doc/soak-*.tsv

常见问题与排查

1. 性能逐渐下降

症状:长稳测试中吞吐量逐渐下降

可能原因

  • 内存泄漏
  • 磁盘碎片
  • CPU 热降频

排查方法

# 监控内存
watch -n 1 'free -h'

# 监控 CPU 温度
sensors

# 监控 CPU 频率
watch -n 1 'cat /proc/cpuinfo | grep "cpu MHz"'

2. P99 延迟尖峰

症状:P99 延迟出现间歇性尖峰

可能原因

  • GC 暂停(如果有)
  • 内核调度延迟
  • 磁盘 I/O 抖动

排查方法

# 使用 perf 分析
perf record -g -p $(pgrep log_engine)
perf report

# 查看 iostat
iostat -x 1

3. 重启后数据丢失

症状:重启后日志记录数少于预期

可能原因

  • pending_messages 未刷新
  • checkpoint 丢失
  • 磁盘同步问题

排查方法

# 查看 pending_messages 统计
curl http://localhost:18080/v1/status | jq '.writer_stats'

# 检查 checkpoint 文件
cat ./logs/shard-0.log.checkpoint

# 验证日志文件
./build/log_engine_verify --path ./logs/shard-0.log

总结

长稳测试是保证系统可靠性的关键环节:

  1. 发现隐藏问题:内存泄漏、资源耗尽等短期测试无法发现的问题
  2. 验证恢复能力:故障注入测试确保系统在各种异常情况下的行为正确
  3. 建立性能基准:为性能回归检测提供参考数据
  4. 提升信心:通过持续的长稳测试,确保系统满足生产环境的要求

最佳实践

  • 定期运行长稳测试(至少每天一次)
  • 每次发布前运行完整的故障注入测试
  • 建立性能基准,持续监控性能漂移
  • 分析测试结果,及时发现潜在问题

相关阅读

源码位置

  • script/bench_soak.sh
  • script/test_soak_and_fault.sh
  • src/bench.cc
  • src/verify.cc