在 云栈社区 看到有网友聊起一位前同事，45 岁，在外企被裁，赔偿拿的是 N+6。
刚被裁那阵，他状态相当好：不用开会，不用看老板脸色，不用半夜处理线上告警，还有一笔补偿金。“终于能歇了。”
结果躺了三个月，人开始烦躁。投简历没什么回音，在家也越来越坐不住，最后自己说了一句：快疯了，老婆看我的眼神都变了。
我倒认为，这事的本质不只是“中年人不能闲”。
真正难受的是，一个运行了二十年的生活系统，收入、反馈、社交、目标突然一起断流。钱能撑一阵，但系统没有新输入，状态迟早会变。
做技术其实也经常碰到这种问题：服务明明没挂，CPU 也不高，但流量一上来，整个系统像“失去工作能力”一样。
这种故障，我第一反应通常不是扩容，而是先找请求到底堵在哪。
接口没报错，P99 已经到 8 秒
假设订单查询接口突然变慢，监控是下面这样。数据只是为了说明排查过程：
GET /api/order/detail
QPS: 180 -> 420
P50: 92ms
P95: 2100ms
P99: 8300ms
CPU: 38%
Heap: 61%
GC Pause P99: 24ms
Error Rate: 0.3%
CPU 不高，GC 也正常。
这时候我不会先加机器。
先把一次请求拆开：
request
|
+-- servlet thread wait
|
+-- business execute
|
+-- acquire db connection
|
+-- execute SQL
|
+-- map result
很多接口监控只有一个总耗时：
long begin = System.nanoTime();
OrderView result = orderService.query(orderId);
log.info("query order cost={}ms",
(System.nanoTime() - begin) / 1_000_000);
这种日志只能证明“慢了”，不能证明慢在哪里。
我更愿意先把等待时间切开。
long acquireStart = System.nanoTime();
Connection conn = dataSource.getConnection();
long acquired = System.nanoTime();
OrderView result;
try {
result = loadOrder(conn, orderId);
} finally {
conn.close();
}
long finished = System.nanoTime();
log.info(
"orderId={}, acquire={}ms, execute={}ms",
orderId,
(acquired - acquireStart) / 1_000_000,
(finished - acquired) / 1_000_000
);
很快可能看到这样的样例：
orderId=82101, acquire=7ms, execute=81ms
orderId=82109, acquire=36ms, execute=93ms
orderId=82117, acquire=1840ms, execute=87ms
orderId=82122, acquire=3912ms, execute=90ms
SQL 根本没慢。
请求花 4 秒，不代表 SQL 执行了 4 秒。它可能有 3.9 秒都在等数据库连接。
问题到这里已经露头了。
看连接池：
HikariPool
maximumPoolSize = 30
active = 30
idle = 0
pending = 76
这时候最容易出现一个操作：
spring:
datasource:
hikari:
maximum-pool-size: 100
看到这里先别急着把 30 改成 100。
应用多拿 70 个连接，不代表数据库能多处理 70 份工作。如果数据库本来就在临界点，这么改只是把排队位置从 Java 连接池搬进了 MySQL。
继续查连接为什么一直不释放。
真正占住连接的，可能是一段不起眼的远程调用
项目里找到这样的代码：
@Transactional
public OrderResult confirm(long orderId){
Order order = orderRepository.lockById(orderId);
PricingResult price =
pricingClient.calculate(order.getSkuId());
order.confirm(price.getAmount());
orderRepository.update(order);
return OrderResult.from(order);
}
这段代码能跑，我在线上不太敢这么放。
@Transactional 开启事务后，查询拿到连接，后面却跑了一次 RPC。
假设数据库实际只用了 40ms，而价格服务偶尔需要 1.5 秒：
BEGIN
SELECT ... FOR UPDATE 18ms
RPC pricing-service 1530ms
UPDATE 21ms
COMMIT
数据库连接可能被占了一秒多。
30 个连接，只要并发稍微上来，很快全部卡住。
更麻烦的是这里还有：
SELECT id, sku_id, status
FROM orders
WHERE id = ?
FOR UPDATE;
现在占着的不只是连接，还有行锁。
另一个请求修改同一订单：
UPDATE orders
SET status = 'CANCELLED'
WHERE id = ?;
于是链条变成：
pricing RPC 抖动
↓
事务时间拉长
↓
连接释放变慢
↓
行锁持有时间变长
↓
Hikari active = max
↓
pending request 增加
↓
接口 P99 飙升
CPU 从头到尾可能都很漂亮。
所以我会先把 RPC 移出事务。
public OrderResult confirm(long orderId){
OrderSnapshot snapshot = orderRepository.snapshot(orderId);
PricingResult pricing =
pricingClient.calculate(snapshot.skuId());
return transactionTemplate.execute(status ->
applyConfirmation(
orderId,
snapshot.version(),
pricing.amount()
)
);
}
事务内部只做必须依赖数据库一致性的部分：
private OrderResult applyConfirmation(
long orderId,
long expectedVersion,
BigDecimal amount){
int affected = orderRepository.confirm(
orderId,
expectedVersion,
amount
);
if (affected != 1) {
throw new ConcurrentModificationException(
"order changed: " + orderId
);
}
return orderRepository.findResult(orderId);
}
SQL 也跟着改：
UPDATE orders
SET status = 'CONFIRMED',
amount = ?,
version = version + 1
WHERE id = ?
AND version = ?
AND status = 'CREATED';
这里我宁可处理一次版本冲突，也不愿意为了“写起来方便”，让数据库连接和锁陪着 RPC 一起等。
线程池也一样，别只看执行时间
还有一种很像的现场。
代码：
CompletableFuture<OrderView> future =
CompletableFuture.supplyAsync(
() -> queryOrder(orderId),
orderExecutor
);
监控发现 queryOrder() 平均只跑 120ms，于是有人说线程池肯定没问题。
不一定。
真正应该测的是：
submit -> start = queue wait
start -> end = execute
可以包一层任务：
public void execute(Runnable task){
long submitted = System.nanoTime();
executor.execute(() -> {
long started = System.nanoTime();
try {
task.run();
} finally {
long ended = System.nanoTime();
metrics.recordQueueWait(
started - submitted
);
metrics.recordExecute(
ended - started
);
}
});
}
最后看到的可能是：
executor=order-query
queueWait.p50 = 18ms
queueWait.p99 = 3200ms
execute.p50 = 91ms
execute.p99 = 180ms
active = 16
poolSize = 16
queueSize = 1847
业务代码执行 180ms，请求为什么 3 秒多？
因为它排队排了 3.2 秒。
如果线程池配置是：
new ThreadPoolExecutor(
16,
16,
60,
TimeUnit.SECONDS,
new LinkedBlockingQueue<>(5000),
factory,
new ThreadPoolExecutor.AbortPolicy()
);
这个 5000 我会重点看。
队列太大最大的麻烦，不只是占内存，而是它把过载隐藏了。
假设稳定处理能力是：
16 threads / 0.12s
≈ 133 tasks/s
上游突然灌进 300 tasks/s，剩下的请求只能进入队列。
5000 容量不是“安全”，而是允许大量请求先活着，然后慢慢超时。
如果业务允许快速失败，我反而更倾向于小队列：
new ThreadPoolExecutor(
16,
24,
30,
TimeUnit.SECONDS,
new ArrayBlockingQueue<>(200),
factory,
new ThreadPoolExecutor.AbortPolicy()
);
再把拒绝明确转成过载信号：
try {
orderExecutor.execute(task);
} catch (RejectedExecutionException e) {
throw new ServiceBusyException(
"order query overloaded"
);
}
配合指标：
executor_queue_wait_seconds
executor_execute_seconds
executor_queue_size
executor_rejected_total
hikari_connections_active
hikari_connections_pending
hikari_acquire_seconds
mysql_lock_wait_seconds
rpc_client_latency_seconds
一次接口慢，到这里才能拆得比较清楚：
8.3s
├─ 线程池排队 3.2s
├─ 获取DB连接 3.7s
├─ SQL执行 0.1s
├─ RPC 1.1s
└─ 其他 0.2s
看到这种数据，再谈加线程、加连接、扩机器才有意义。
否则参数改了一圈，可能只是让请求换个地方继续排队。
45 岁被裁之后那三个月之所以让人难受，也有点类似：表面上什么都没坏，原来的运行节奏却突然断了。
系统也是。真正危险的往往不是直接宕机，而是它看起来还活着，实际上所有请求都在等待。
发表于 昨天 23:45
|
查看: 6|
回复: 0
