从日志入手定位 Ubuntu 上 JS 性能问题的实用流程
一 准备可观测性
- 结构化与分级日志：在 Node.js 中使用Winston/Bunyan/Log4js输出JSON格式，区分info/warn/error，并加入关键维度（如route、method、statusCode、durationMs、userId、traceId）。示例：
- 使用console.time/console.timeEnd或process.hrtime记录关键路径耗时。
- 记录process.memoryUsage()与event loop lag（见下文）以补充资源视角。
- 系统侧日志采集：服务化场景用journalctl -u your-service-name跟踪进程日志；必要时查看**/var/log/syslog与dmesg**获取内核/系统级线索。
- 运行监控：用PM2启动与观测（如pm2 monit），便于同时看到日志与CPU/内存；前端或 Node 服务可接入New Relic/Datadog/ELK/Graylog做聚合、检索与告警。
二 日志中识别性能瓶颈
- 响应时间异常：在日志中检索高耗时区间，例如：
- 统计平均耗时：tail -f app.log | grep ‘durationMs’ | awk ‘{sum+=$NF; n++;} END {print “avg=” sum/n}’
- 找出 TopN 慢请求：… | sort -kNFnr | head
- 错误与重试风暴：统计5xx/ERROR与重试次数，结合traceId还原调用链，确认是否为下游故障放大。
- 外部依赖慢：关注upstream_response_time、db_query_time、cache_hit等字段，定位是数据库/缓存/第三方 API瓶颈。
- 内存与泄漏迹象：对比rss/heapUsed随时间的增长趋势；若持续增长且不回落，优先排查闭包、全局缓存、定时未清理等。
- 事件循环阻塞：在日志中打印loop lag（见下文代码），若持续偏高，说明有同步阻塞/CPU 密集任务。
- 网络与连接：服务端日志配合netstat/ss/lsof检查TIME_WAIT/CLOSE_WAIT堆积；前端/网络侧用curl/wget或浏览器DevTools Network查看TTFB、传输大小、失败率。
三 结合系统与前端工具验证
- 系统资源：用top/htop/atop观察CPU/内存；用iostat/vmstat/free排查I/O 与内存压力；必要时用perf/strace定位系统调用与热点路径。
- Node 运行时剖析：
- node --inspect/–inspect-brk连接Chrome DevTools做CPU/内存采样与火焰图分析。
- node --prof配合**–prof-process生成V8日志，识别热点函数/脚本**。
- 前端性能：浏览器DevTools Performance面板录制交互，查看CPU、布局/重绘、长任务与帧率；检查Network中的Waterfall与TTFB。
- 数据库与慢查询：开启慢查询日志，用EXPLAIN分析索引/扫描方式，必要时加索引或改写查询。
四 可复制的落地方案与命令清单
- 结构化日志最小示例（Node.js）
- 安装：npm i winston
- 代码示例：
- const winston = require(‘winston’);
const { createHash } = require(‘crypto’);
const logger = winston.createLogger({
level: ‘info’,
format: winston.format.combine(
winston.format.timestamp(),
winston.format.json()
),
transports: [new winston.transports.File({ filename: ‘combined.log’ })]
});
function withTiming(fn, label) {
return async (…args) => {
const start = process.hrtime.bigint();
const result = await fn(…args);
const end = process.hrtime.bigint();
const durationMs = Number(end - start) / 1e6;
logger.info({ event: ‘timing’, label, durationMs });
return result;
};
}
// 事件循环延迟（粗略）
let last = Date.now(); setInterval(() => {
const lag = Date.now() - last - 1000;
if (lag > 50) logger.warn({ event: ‘event_loop_lag’, lagMs: lag });
last = Date.now();
}, 1000).unref();
- 常用命令清单
- 实时看日志：tail -f app.log | grep --color ‘durationMs|statusCode’
- TopN 慢请求：… | sort -kNFnr | head
- 统计错误率：… | awk ‘$NF ~ /5[0-9]{2}/ {err++; total++} END {print “errRate=” err/total}’
- 连接状态检查：ss -tan | awk ‘{print $1}’ | sort | uniq -c
- 系统资源：top/htop；iostat -x 1；vmstat 1；free -m
- Node 剖析：node --inspect app.js 与 chrome://inspect；node --prof app.js && node --prof-process isolate-*.log
- 日志轮转与保留
- 使用logrotate管理体积，示例：
- /var/log/myapp/*.log { daily; rotate 7; missingok; notifempty; compress; delaycompress; sharedscripts; postrotate killall -USR1 node || true; endscript }
- 或在 Node 侧用winston-daily-rotate-file按天切分。
五 常见症状 日志特征 快速验证 修复方向
- 高 TTFB/首包慢：日志中durationMs高、路由日志集中；前端Waterfall长；后端netstat连接正常。验证：wrk/curl 对比；修复：CDN/压缩/上游优化/连接复用。
- 事件循环阻塞：日志中event_loop_lag持续偏大；CPU 单核打满；DevTools 长任务。验证：–prof 看热点；修复：移除同步阻塞、拆分CPU 密集任务、用Worker Threads/队列。
- 内存泄漏：日志heapUsed/rss单调增；GC 后不回落；堆快照对象数持续增长。验证：heapdump + DevTools Memory；修复：清理全局缓存/定时器/闭包引用。
- 数据库慢：日志db_query_time高；慢查询日志命中；EXPLAIN 显示全表扫描。验证：加索引/改写 SQL；修复：索引、分页、连接池、缓存。
