从日志入手定位瓶颈,再用配置与代码优化响应时间
一 日志采集与关键字段配置
- 启用并校准访问日志,记录请求耗时,便于量化慢请求。编辑 $CATALINA_HOME/conf/server.xml 的 AccessLogValve,推荐包含耗时字段 %D(ms) 与 %F(ms),并保留真实客户端 IP(如有反向代理,使用 %{X-Real-IP}i):
<Valve className="org.apache.catalina.valves.AccessLogValve"
directory="logs"
prefix="localhost_access_log."
suffix=".txt"
pattern="%h %l %u [%{yyyy-MM-dd HH:mm:ss}t] \"%r\" %s %b %D %F %{X-Real-IP}i"/>
- 日志目录通常为 $CATALINA_HOME/logs 或 /var/log/tomcat[0-9]/,核心文件包括:catalina.out、localhost_access_log.*。
- 打开 GC 日志以发现由垃圾回收引起的停顿:在 catalina.sh/catalina.bat 的 JAVA_OPTS 中加入
- -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:$CATALINA_HOME/logs/gc.log
- 建议同时配置 -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M,便于长期保留与轮转。
- 日志轮转与精简:访问日志可按时间切割(如按天),避免单文件过大;生产环境将 logging.properties 的级别控制在 WARN/ERROR,减少 DEBUG 输出对磁盘与 I/O 的压力。
二 用命令行快速定位慢请求与异常
- 找出响应时间超过阈值的请求(示例阈值 800 ms,字段 %D 为毫秒):
awk -F'QTime:' '$2+0 > 800 {print}' /var/log/tomcat*/localhost_access_log.*.txt
awk '$NF > 800 {print}' /var/log/tomcat*/localhost_access_log.*.txt
awk -F'QTime:' '{n=$2+0; if(n>800) print $0}' /var/log/tomcat*/localhost_access_log.*.txt \
| awk '{uri[$7]++; time[uri]+=n; cnt[uri]++}
END {for(u in time) printf "%.0f ms %d %s\n", time[u]/cnt[u], cnt[u], u}' \
| sort -nr | head
- 关联错误与慢请求:先定位 ERROR 时间点,再回溯同一时间窗的慢请求,判断是否为异常导致阻塞。
grep -n "ERROR" /var/log/tomcat*/catalina.out
- 辅助排查系统资源:结合 top/htop、vmstat、iostat 观察 CPU、内存、I/O 在慢请求时段的异常波动,帮助确认是计算密集、内存回收还是磁盘/网络瓶颈。
三 用可视化平台做趋势与分布分析
- 集中采集与解析:使用 ELK(Elasticsearch + Logstash + Kibana) 或 Graylog 汇聚 access log、catalina.out、gc.log。
- Logstash 示例(解析 access log 并写入 ES):
input { file { path => "/var/log/tomcat*/localhost_access_log.*.txt"
start_position => "beginning"
sincedb_path => "/dev/null" } }
filter {
grok {
match => { "message" => "%{IPORHOST:client} %{NOTSPACE:ident} %{NOTSPACE:auth} \[%{HTTPDATE:timestamp}\] \"%{DATA:request}\" %{NUMBER:status:int} %{NUMBER:bytes:int} %{NUMBER:duration_ms:int} %{NUMBER:commit_ms:int} %{IPORHOST:real_ip}" }
}
date { match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss Z" ] }
mutate { convert => { "duration_ms" => "integer" "commit_ms" => "integer" } }
}
output { elasticsearch { hosts => ["localhost:9200"] index => "tomcat-access-%{+YYYY.MM.dd}" } }
- 在 Kibana 构建仪表盘:按 URI、status、client、real_ip 维度查看 P95/P99 延迟、吞吐(RPS)、错误率;对 duration_ms 做直方图与分位数,对 gc.log 做 GC 次数与停顿时长趋势,定位长尾与 GC 抖动对响应时间的影响。
四 从日志洞察到配置与代码优化
- 连接与线程瓶颈
- 现象:访问日志显示大量并发请求且 %D 拉长;错误日志出现 “Too many open files” 或 “unable to create new native thread”。
- 处置:在 server.xml 调整连接器/线程池(如 maxThreads、minSpareThreads),并检查 ulimit -n 与系统 file-max;必要时优化应用以减少连接占用时间。
- 内存与 GC 瓶颈
- 现象:catalina.out/gc.log 出现频繁 Full GC 或长暂停;访问日志整体 P95/P99 随 GC 周期性抬升。
- 处置:合理设置 -Xms/-Xmx,选择合适的 GC(如 G1 适合大堆、低延迟场景),减少对象生命周期与缓存压力,验证后滚动发布。
- 数据库与后端依赖
- 现象:少数 URI 的 %D 显著高于同类请求,且错误日志无异常。
- 处置:结合应用日志/SQL 监控确认慢查询或连接池不足;为高频查询建立合适索引、优化 SQL、使用连接池合理参数(如 maxActive、maxIdle),并在日志中增加业务关键路径耗时以联动分析。
- 传输与压缩
- 处置:在 server.xml 启用 HTTP 压缩(如 compression=“on”),对文本类响应(JSON/HTML/CSS/JS)显著降低传输耗时,尤其对高 RTT 场景有效。
五 可复用的分析流程与落地清单
- 流程
- 采集:开启 AccessLogValve(含 %D/%F)、GC 日志,统一落盘与轮转。
- 告警:对 ERROR、5xx、P95/P99 突增、Full GC 增多 建立阈值告警。
- 定位:命令行快速筛出慢请求与异常时段;可视化平台看分布与趋势。
- 优化:按“连接/线程 → 内存/GC → 数据库/后端 → 传输”顺序逐项验证与回放。
- 回归:对比优化前后 P50/P95/P99、吞吐、错误率,固化配置并纳入日常巡检。
- 落地清单
- 访问日志包含 %D/%F 与 X-Real-IP;日志按天轮转,保留至少 7–30 天。
- GC 日志开启并轮转;Kibana 建立 P50/P95/P99、RPS、错误率、Top URI 面板。
- 每周巡检一次慢请求榜单与 GC 趋势,重大变更前在测试环境验证。