我的开源
curl时间统计参数time_starttransfer含义以及在文件上传场景下可能的误解
平时大家会使用curl来进行请求时间的测量. 比如:
curl -s -o /dev/null -w "dns: %{time_namelookup}\ntime_connect: "%{time_connect}"\ntime_appconnect: "%{time_appconnect}"\ntime_pretransfer: "%{time_pretransfer}"\ntime_starttransfer: "%{time_starttransfer}"\ntime_redirect: "%{time_redirect}"\ntime_total: "%{time_total}"\n" www.baidu.com
以上的命令执行后可以得到结果:
dns: 0.007615
time_connect: 0.008320
time_appconnect: 0.000000
time_pretransfer: 0.008409
time_starttransfer: 0.045689
time_redirect: 0.000000
time_total: 0.045882
但是对于其中的参数: time_starttransfer 的理解,并不是那么容易. 这个有一张来自于别人总结的图:
这里的每一个参数的值都是一个偏移量. 比如 time_appconnect 从字面含义是为了测量应用层的协议握手时间.比如HTTPS. 但是其记录的值是从开始请求到应用层协议握手完成的时间. 也就是从0开始的一个时间偏移量. 如果想要知道:SSL Handshake 也就是time_appconnect发生的时间. 需要把前一个时间点进行相减. 这就是:
appconnectTime = time_appconnect - time_connect
我们再查阅一下curl的手册,印证下我们的想法. 否则可能出错:
time_appconnect
The time, in seconds, it took from the start until the SSL/SSH/etc connect/handshake to the remote host was completed. (Added in 7.19.0)
这个没有问题, 与我们的想法一致. 下面再看一下我们这篇文章要说明的参数: time_starttransfer , 我们也先看一下其含义:
time_starttransfer
The time, in seconds, it took from the start until the first byte was just about to be transferred. This includes time_pretransfer and also the time the server needed to calculate the result.
最主要的信息:
- 从最开始的时间点开始计数.
- 服务端返回的第一个字节.为结束. 英文原文为:
the first byte was just about to be transferred - 包含服务端计算结果的时间. 这点很重要.
下面,我们的疑问的核心终于要出场了. 请看下面的一段Demo代码.我专门写了一段demo来演示这个问题.
/**
* <pre>
* 用于测试一个curl的时延相关的参数:
* 测试命令: curl -w "@./debug/curl-format.txt" -s -v -o a.txt -X POST -T "./doc/img/fake_ic_mem.jpeg" http://localhost:8080/demo_async_servlet_war_exploded/postFile/curlTest?delay=5
* </pre>
* @author lijianhong Date: 2023/1/27 Time: 7:56 PM
* @version $
*/
@WebServlet(urlPatterns = "/postFile/curlTest", asyncSupported = false)
public class ServletInputStreamReadServletWithDelay extends HttpServlet {
@Override
protected void doPost(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
ServletInputStream reqInputStream = req.getInputStream();
byte[] buf = new byte[1024*64];
int nRead = 0;
while (!reqInputStream.isFinished() && (nRead = reqInputStream.read(buf)) != -1) {
System.out.println("nRead = " + nRead);
//System.out.println("readBytes:" + Arrays.toString(buf));
}
String delay = req.getParameter("delay");
if (delay != null && !delay.isEmpty()) {
try {
System.out.println("begin to sleep " + delay + "s");
TimeUnit.SECONDS.sleep(Long.parseLong(delay));
System.out.println("finish");
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
}
resp.getWriter().write("OK");
}
}
代码很简单. 一个简单的文件上传demo. 上传后并没有进行处理. 只是简单打印了每次分包读取的字节数. 同时在接收完成之后. 从req中取了一个delay参数用于控制模拟服务端的处理时间.
使用curl命令:
curl -w "@./debug/curl-format.txt" -s -o a.txt -X POST -T "./doc/img/fake_ic_mem.jpeg" http://localhost:8080/demo_async_servlet_war_exploded/postFile/curlTest?delay=5
测试后,我们得到了如下的返回:
time_namelookup: 0.003024
time_connect: 0.003327
time_appconnect: 0.000000
time_pretransfer: 0.003428
time_starttransfer: 0.036557
time_redirect: 0.000000
-----------------
time_total: 5.226700
这里发现time_starttransfer记录的值大概只有 36ms. 而我们的总耗时的确是有5.22秒, 同时我们上面也明显看了这个时间应该包含处理时间的. 为什么处理时间的延时5秒的时间没有算到time_starttransfer呢? 这就是这篇文章要解决的问题.
如果上面的man参数说明是正确的话. 那这里为什么不包含响应时间在内. 如果不是正确的. 为何
curl的官方命令手册会这样写呢? 这似乎是一个矛盾.
下面我们求助于chatGPT 看看AI大神是怎么回答这个问题的.
这里chatGPT明确的告诉了我们. time_starttransfer的时间是: 发送第一个字节到到返回第一个字节之间的时间. 看来这个应该是没有问题的.
那问题又出在哪呢. 我们来加一个-v参数. 遇事不决加-v 我们看看这个文件上传的请求有什么不一样.
命令:
curl -w "@./debug/curl-format.txt" -s -v -o a.txt -X POST -T "./doc/img/fake_ic_mem.jpeg" http://localhost:8080/demo_async_servlet_war_exploded/postFile/curlTest?delay=5
我们注意到, 这个请求有些特别. 他居然返回了两次. 就是传说中的一次请求,两次返回. 那这样,是不是因为两次返回中的第一次返回的 100被curl认为是了服务端的返回. 那这样, 服务端就在完全没有做任何处理时候. 返回了一个空header. 并且状态码是100. 那按定义: 从发送完第一个字节到接收到服务端的第一个字节,那的确收到了第一个Header的时候. 我理论上就可以认为服务端已经完成: calculate了. 后面的真实的计算时间就被记录到了下载或者total时间中去了. 为了印证这个, 我们写一个普通的一次请求一次返回的代码来看看.
这里给出一个普通的GET请求的server端代码,同样可以在请求的时候指定delay的时间来模拟服务端的处理时间.
@WebServlet(urlPatterns = "/curl/echoWithDelay", asyncSupported = false)
public class CurlEchoDelayServlet extends HttpServlet {
@Override
protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
String delay = req.getParameter("delay");
if (delay != null && !delay.isEmpty()) {
try {
System.out.println("begin to sleep " + delay + "s");
TimeUnit.SECONDS.sleep(Long.parseLong(delay));
System.out.println("finish");
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
}
resp.getWriter().write("OK");
}
}
我们用下面的请求进行处理看看:
curl -w "@./debug/curl-format.txt" -s -v -o a.txt http://localhost:8080/demo_async_servlet_war_exploded/curl/echoWithDelay?delay=5
这次的结果很正常. 也和我们预期的时间对应了起来. 这样也就印证了我们的文件上传时的两次返回导致了时间测量不准确.
关于 100状态码的说明可以参考这个:
https://blog.csdn.net/weixin_44798320/article/details/123560430
HTTP/1.1 协议 Expect: 100 -continue 分析与禁用
1、基础知识背景
1.1 “Expect: 100-continue”的是什么：
HTTP/1.1 协议里，设计 100 - continue HTTP 状态码的，目的是为了在 client 发送 Request Message 之前， HTTP/1.1 协议允许 client 判定服务器是否愿意 接受 client 的消息主体(基于 Request Message )。
如果 client 预期等待 100-continue 应答，那么它发送的请求必须包含一个 Expect: 100 -continue 的头域。
2、Expect: 100-continue 来龙去脉
2.1 libcurl 发送大于1024字节数据时启用“Expect:100-continue‘特性：
2.2 这也就是 Laruence 在 2011 年撰文所写的：
在使用 curl 做 POST 的时候，当要POST 的数据大于 1024 字节的时候，curl 并不会直接就发起 POST 请求，而是会分为两步：
发送一个请求，包含一个 “Expect:100-continue” 头域，询问 Server 是否愿意接收数据；
接收到 Server 返回的100-continue 应答以后，才把数据 POST 给Server；
这是 libcurl 的行为。
2.3 zxgfa在 2012年补充说：
libcurl在发送大于1024 字节的 POST 请求时采用了这种方法，但是相对的，它会引起请求延迟的加大。
并不是所有的 web server 都能正确处理并应答“100-continue”，比如 lighttpd，就会返回417”Expectation Failed “，造成请求逻辑出错。
（ 注1：lighttpd 1.4 版本有此严重问题，于1.5版本修复。注2：Resin 于 3.0.5 版本增加了对 Expect: 100-continue 的支持。）
这里就完全弄明白了.为什么 在上传文件的时候会有这样一个奇怪的现象. 实际上并不只是上传文件会这样. 我们使用表单(form/multipart)时,也会出现这样的情况.