服务器日志中的响应时间与 chrome 开发人员工具之间存在差异

Discrepancies between response time in server logs and chrome developer tools

我正在对一个站点进行负载测试,并注意到我从 Web 服务器(在本例中为 tornado web server)和 Chrome 开发人员工具收到的计时信息之间存在相当大的差异。 Web 服务器在 nginx 后面提供一个服务 运行 作为一个进程(实际上,是由 supervisor 管理的几个进程)。还有一个 Web 界面可以与该服务进行交互。这个龙卷风 Web 服务器检索查询的速度相当快(平均 30 毫秒)。但是,Chrome 开发人员工具的响应时间要慢得多(大约 240 毫秒)。

每次查询都会检索一些信息,需要查询额外的资源(主要是图片)。我认为这是造成如此大差异的主要原因,但我尝试使用 curl 和 time_starttransfer 测量 172 毫秒。

另一方面,对 nginx 使用此日志记录指令:

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 $pipe';

我能够检查 request_timeupstream_response_time 实际上非常小(45 毫秒)。

响应时间出现这种差异的原因可能是什么?

更新

这是来自 Firebug 的屏幕截图:

我认为我无法通过有限的信息计算出延迟时间。

更新 2

我能够通过 curl 获得更好的信息。不过,我不确定它是否准确:

    time_namelookup:  0.000
       time_connect:  0.062
    time_appconnect:  0.000
   time_pretransfer:  0.062
      time_redirect:  0.000
 time_starttransfer:  0.172
                    ----------
         time_total:  0.240

据我所知,time_starttransfer - time_pretransfer = content_generation,所以 0.172 - 0.062 = 0.110s。但是,查看日志,Web 服务器报告 0.044s 并且 nginx 的 request_time 同意(0.045s)。此外,我认为应该是延迟的 curl 输出中的 time_connect 并没有那么大 (0.062s)。

有趣的是,time_starttransfer - time_connect*2 = 0.048 与 nginx 或 tornado 报告的时间相似(0.048 对 0.044)。但是这个计算应该是不正确的。有谁知道证明 chrome 开发人员 tools/curl 与网络 server/nginx 响应时间差异的正确方法是什么?

客户端不知道服务器上发生了什么。它不知道请求何时到达另一端,以及另一端何时开始发送响应。

您正在尝试比较从两个端点测量的数字,但它们之间存在明显的延迟并且它们的通信受到限制。

如果你真的想详细了解这种延迟,你应该了解 TCP 的工作原理。我只是注意到连接动作不是立即发生的,也不是一个动作,它涉及在服务器和客户端之间交换数据包。传输数据也是如此。

TL;博士

您正在比较苹果和橙子...用 ping 检查您的 RTD。

HTTP 请求处理

针对单个 HTTP(S) 请求发生的一组简化(但仍然相当复杂)的步骤如下:

  1. 客户端执行 DNS 查找以解析 URL 中的主机名。
  2. 客户端与主机服务器建立 TCP 连接。
  3. 客户端可选择进行 TLS 协商(仅适用于 HTTPS 连接)。
  4. 客户端最终通过连接发送请求 - 这个阶段的开始是客户端即将发送第一个字节时。
  5. 网络服务器收到请求并开始处理它。
  6. 网络服务器开始发送响应。
  7. 客户端开始接收它 - 即它接收响应的第一个字节。
  8. 服务器继续将数据流式传输到服务器,直到到达响应末尾。
  9. 客户端收到最后一个数据。

如您所见,网络服务器只真正知道步骤 5 到 8(因为许多初始连接设置将超出其控制范围)并且只能测量 5-6 和 5-8。但是,客户端知道步骤 1 到 9。此外,它可以测量完全相反的数据点列表。

网络延迟

任何请求或响应都必须通过网络传输(对于 public 服务通常是互联网),因此在机器与机器之间传输数据时会产生延迟。两台机器之间(从一台机器到另一台机器再返回)所需的最短时间称为 往返时间 (RTT) 往返延迟 (RTD) 。这会影响所有通信,通常使用 ping.

等工具进行测量

这个RTD影响所有通信,HTTP请求也不例外,所以会非常接近上述步骤中步骤4-5和6-7之间延迟的总和。

最终结果

将所有这些放在一起,您应该会发现 curl 已经为您测量了 time_pretransfer 返回的第 1-4 步(好吧,到第 4 步的开头)。此外,它还为你测量了1-7(也是7的开头)为time_starttransfer。然而,服务器已经测量了5-6的时间。

你错过了4-5和6-7之间的时间,我们上面看到的基本上是RTD。

因此您应该发现 time_starttransfer = time_pretransfer + request_time + RTD