长稳测试与故障注入:构建可信赖的日志系统
深入分析 Seastar Log Engine 的长稳测试方法论,包括 bench_soak.sh 和 test_soak_and_fault.sh 脚本的实现,以及如何通过持续测试发现潜在问题。
为什么要长稳测试?
短期测试的盲区
短期压测只能验证峰值性能,无法发现以下问题:
短期测试能发现:
✅ 峰值吞吐量
✅ P99 延迟
✅ 基本的正确性
短期测试无法发现:
❌ 内存泄漏(需要数小时才能显现)
❌ 资源泄漏(文件描述符、内存池)
❌ 热退化(长时间运行的性能衰减)
❌ 边界条件(极端情况下的行为)
❌ 并发问题(竞态条件、死锁)
长稳测试的目标
- 发现资源泄漏:内存、文件描述符、线程等
- 验证性能稳定性:长时间运行后性能是否衰减
- 检测热退化:硬件在高负载下的性能衰减
- 模拟真实场景:长时间运行的服务行为
测试框架架构
核心测试脚本
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 # 输出文件前缀
参数详解
| 参数 | 类型 | 默认值 | 说明 |
|---|---|---|---|
--target | string | log_engine | 目标引擎:log_engine/spdlog/glog |
--duration-seconds | int | 60 | 测试持续时间(秒) |
--messages | int | 50000 | 每次运行的日志条数 |
--payload-size | int | 2048 | 每条日志的字节大小 |
--batch-size | int | 8192 | 批量提交大小 |
--inflight | int | 1 | 最大并发写入数 |
--shards | int | 1 | Seastar shard 数量 |
--ack-mode | string | write_ack | 确认模式 |
--flush-ms | int | 0 | 定时 flush 间隔 |
--checkpoint-enabled | int | 0 | 是否启用 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-6 | checkpoint 损坏时无法恢复 |
| 查询崩溃 | Phase 7 | gzip 损坏导致 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
总结
长稳测试是保证系统可靠性的关键环节:
- 发现隐藏问题:内存泄漏、资源耗尽等短期测试无法发现的问题
- 验证恢复能力:故障注入测试确保系统在各种异常情况下的行为正确
- 建立性能基准:为性能回归检测提供参考数据
- 提升信心:通过持续的长稳测试,确保系统满足生产环境的要求
最佳实践:
- 定期运行长稳测试(至少每天一次)
- 每次发布前运行完整的故障注入测试
- 建立性能基准,持续监控性能漂移
- 分析测试结果,及时发现潜在问题
相关阅读:
源码位置:
script/bench_soak.shscript/test_soak_and_fault.shsrc/bench.ccsrc/verify.cc