【问题标题】：Discrepancies between response time in server logs and chrome developer tools服务器日志中的响应时间与 chrome 开发者工具之间的差异
【发布时间】：2016-08-17 04:47:36
【问题描述】：

我正在对一个网站进行负载测试，并注意到我从 Web 服务器（在本例中为 tornado web server）和 Chrome 开发人员工具收到的时间信息之间存在相当大的差异。 Web 服务器提供了一个服务，作为 nginx 后面的一个进程（实际上是由 supervisor 管理的几个进程）运行。还有一个 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_time 和 upstream_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.110 秒。但是，查看日志，Web 服务器报告 0.044s 和来自 nginx 的 request_time 同意（0.045s）。此外，我认为应该是延迟的 curl 输出中的 time_connect 并没有那么大（0.062 秒）。

有趣的是time_starttransfer - time_connect*2 = 0.048 与 nginx 或 tornado 报告的时间相似（0.048 vs 0.044）。但这个计算不应该是正确的。有谁知道证明 chrome 开发人员工具/curl 与 Web 服务器/nginx 响应时间之间差异的正确方法是什么？

【问题讨论】：

开发人员工具还包括响应时间延迟，但服务器日志不包括。找出客户端和服务器之间的延迟，然后交叉检查这些值。
有趣。我应该如何测量延迟？平？
ping 应该让您接近实际数字，因为它使用 smtp 而不是 http。我认为像 firebug 或 yslow 这样的浏览器插件可以为您提供延迟数字。
太棒了。我会检查萤火虫。谢谢。
不幸的是，Firebug 提供了一个“等待”时间，包括从客户端发送请求到服务器的时间+服务器处理请求的时间。我认为我无法使用该信息确认服务器的测量值。 Yslow 由于某种原因不能作为 Firefox 插件正常工作。

标签： performance nginx tornado timing

【解决方案1】：

TL;博士

您正在将苹果与橙子进行比较...使用ping 检查您的 RTD。

HTTP 请求处理

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

客户端执行 DNS 查找以解析 URL 中的主机名。
客户端与主机服务器建立 TCP 连接。
客户端可选择通过 TLS 协商（仅适用于 HTTPS 连接）。
客户端最终通过连接发送请求 - 此阶段的开始是客户端即将发送第一个字节时。
Web 服务器收到请求并开始处理它。
Web 服务器开始发送响应。
客户端开始接收它 - 即它接收到响应的第一个字节。
服务器继续将数据流式传输到服务器，直到响应结束。
客户端收到最后的数据。

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

网络延迟

任何请求或响应都必须通过网络（通常是公共服务的 Internet）传输，因此在数据从机器传输到机器时会产生延迟。两台机器之间（从一台到另一台再返回）所花费的最短时间称为往返时间 (RTT) 或 往返延迟 (RTD)。这会影响所有通信，通常使用ping 等工具来衡量。

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

净结果

综上所述，您应该会发现curl 已经为您测量了第 1-4 步（嗯，从第 4 步开始），正如time_pretransfer 返回的那样。此外，它还为您测量了 1-7（同样是 7 的开头）为time_starttransfer。但是，服务器已经测量了 5-6 的时间。

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

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

【讨论】：

谢谢。我明白你的意思。基本上，我忘记在计算中包括 RTD。顺便说一句，您概述的步骤与 curl 测量的变量不完全匹配。例如，time_pretransfer 指的是“从开始到文件传输即将开始所用的时间”（在 Web 服务器处理请求之前），time_starttransfer 指的是“从开始所用的时间”直到第一个字节即将被传输”（在 Web 服务器生成响应之后。），这并不完全是步骤 1-4 和 1-7 的意思。
(cont) 另一个问题：我认为 time_pretransfer 和 time_starttransfer 包含 RTT，但您的计算不支持该想法。它是否正确？ curl 中有什么东西可以用作 RTT 的近似值吗？
对不起 - 我过于简化了。我已经按照the curl docs 阐明了关键时间安排。在回答您的问题时，如果没有服务器的合作，就不可能计算 RTD，ping 就是这样做的。因此，我不知道（如果有的话，我会感到惊讶）这样做的任何 curl 选项。
没问题。我想我误解了time_pretransfer 的定义。我将time_pretransfer 定义中的“......直到文件传输即将开始”解释为服务器开始接收请求之前的那一刻，并且“......直到第一个字节即将开始time_starttransfer 定义中的“转移”是指服务器开始发送响应后的时刻。这个explanation 及其图形表示强化了这个想法。
(cont) 但是，如果我使用该解释，则无需添加 RTD 时间，因为 time_pretransfer 应该包括从客户端到服务器的延迟，而 time_starttransfer 不应该包括从服务器的延迟给客户。这是非常令人困惑的部分。

【解决方案2】：

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

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

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

【讨论】：

谢谢。我想这更像是一般性评论而不是答案。请注意，我的问题的最新更新专门处理服务器端的测量。