4、应用服务器日志：Tomcat / Jetty / Nginx 访问日志与错误日志

上一章我们聊了操作系统日志，那一层更像是“地基”。

现在咱们把视角往上提一级，来到应用服务器。说白了，你的 Java 应用跑在 Tomcat 或者 Jetty 上，前面可能还挡着一个 Nginx 做反向代理。接口超时了，请求到底卡在哪一步？是压根没到应用服务器，还是到了服务器但没响应？

想回答这个问题，就得看懂这三类服务器的日志。我个人习惯把它们的日志分成两个阵营：访问日志（Access Log）和 错误日志（Error Log / Catalina Log）。访问日志记录“谁、什么时候、要了什么、结果怎样”；错误日志则在出问题的时候告诉你“哪里坏了”。

4.1 访问日志：请求的“电子眼”

访问日志是排查超时问题的第一站。我见过不少同事一遇到超时就去翻代码，说实话，效率不高。先看一眼访问日志，经常能直接定位问题范围。

4.1.1 Tomcat 访问日志

Tomcat 的访问日志由 AccessLogValve 控制。在 server.xml 的 <Host> 或 <Engine> 下配置。

关键配置项我列一下：

最关键的字段：%T 和 %D

• %T：处理请求的时间，单位秒。
• %D：处理请求的时间，单位毫秒。

我个人更倾向于用 %D，精度更高。如果你发现某条日志的 %D 值超过了接口的超时阈值，比如 30000（30秒），那恭喜你，接口慢的证据找到了。但这只是“现象”，根因还得往下挖。

# 推荐的自定义 pattern
pattern="%h %l %u %t "%r" %s %b %D "%{Referer}i" "%{User-Agent}i""

4.1.2 Jetty 访问日志

Jetty 的访问日志配置和 Tomcat 很像。通常通过 jetty.xml 或代码方式配置 RequestLog 实现。

Jetty 的默认日志格式可能不包含处理时间，需要手动加上。配置方式我贴一下：

<Configure class="org.eclipse.jetty.server.Server">
  <Set name="RequestLog">
    <New class="org.eclipse.jetty.server.handler.RequestLogHandler">
      <Set name="Handler">
        <New class="org.eclipse.jetty.server.NCSARequestLog">
          <Set name="filename">/var/log/jetty/access-yyyy_mm_dd.log</Set>
          <Set name="append">true</Set>
          <Set name="extended">true</Set>
          <Set name="logTimeZone">GMT</Set>
          <Set name="logLatency">true</Set>  <!-- 这一行就是关键，记录处理耗时 -->
        </New>
      </Set>
    </New>
  </Set>
</Configure>

注意这里的 logLatency 属性，设置为 true 后，Jetty 会在每条访问日志的末尾追加处理耗时（单位毫秒）。你看，和 Tomcat 的 %D 异曲同工。

4.1.3 Nginx 访问日志

Nginx 的访问日志格式通过 log_format 定义。排查超时问题，我建议你至少包含以下变量：

log_format timed_combined '$remote_addr - $remote_user [$time_local] '
                          '"$request" $status $body_bytes_sent '
                          '"$http_referer" "$http_user_agent" '
                          '$request_time $upstream_response_time';

• $request_time：Nginx 从收到请求到发送完响应的总时间。
• $upstream_response_time：Nginx 与上游服务器（你的 Tomcat/Jetty/Java 应用）建立连接到接收完响应的时间。

举个例子。假设你看到一条 Nginx 日志：

• $request_time = 30.5s
• $upstream_response_time = 30.4s

你看，几乎是重合的。这说明绝大部分时间都花在了上游服务器处理上。这时候你应该去查 Tomcat 或 Jetty 的日志。

反过来，如果：

• $request_time = 30.5s
• $upstream_response_time = 0.5s

那就有意思了。上游只花了 0.5 秒，但 Nginx 总耗时是 30.5 秒。这多出来的 30 秒去哪了？多半是卡在了 Nginx 和客户端的网络传输上，或者 Nginx 自身的缓冲区配置不当。

4.2 错误日志：服务器“喊救命”的地方

访问日志告诉你“慢了”，错误日志告诉你“为什么慢”。嗯，至少是部分原因。

4.2.1 Tomcat 错误日志（Catalina.out / Localhost.log）

超时相关的典型异常，我总结一下：

4.2.2 Jetty 错误日志

Jetty 的错误日志默认输出到 stderr，很多容器环境下会被重定向到文件。模式上和 Tomcat 很像，只是异常堆栈里的包名变化了。

你要关注的几个类：

• org.eclipse.jetty.server.HttpConnection
• org.eclipse.jetty.io.ChannelEndPoint

超时相关的异常通常包装在 TimeoutException 或 SocketTimeoutException 里。Jetty 的日志会比较啰嗦，我建议你耐心看完堆栈的前几行，找到你自己的业务代码调用点。

4.2.3 Nginx 错误日志

Nginx 的错误日志配置在 nginx.conf 的 error_log 指令里。排查超时，重点看这几个关键字：

4.3 知识框架：从日志到定位

说了这么多，我把应用服务器日志排查超时的整体思路画成一张图，你看着会更直观。