启用HTTP/2后，request_time 远远大于 upstream_response_time

[level077]

hi all:

    启用HTTP/2后，经常发现nginx的request_time远远大于upstream_response_time,如下图：

    用h2load做压测时也会有这种问题。

    做了相关排查后，确认：

    1）后端业务响应时间和upstream_response_time一致

    2）在nginx上抓取upstream流量确认nginx第一时间将请求发给了upstream，upstream也非常快的发回响应，即排除了nginx转发请求慢的可能

    3）关闭HTTP/2，改回HTTP/1.1后，没有发现该问题，request_time与upstream_response_time一致

    不知大家有没遇到过？或者提供些排查思路。

    

    相关版本： 

    openresty: 1.11.2.1

    openssl: 1.0.2h

    http2使用的是默认配置

[Zexuan Luo]

看上去似乎是 HTTP2 多路复用 的问题？
request_time 是从读取 Client 请求的时候开始计时的。
而一个 HTTP2 请求，由于多路复用，可能包含多个实际的请求。

换句话说，request_time 此时计量的是整个 HTTP2 请求的用时，而 upstream_response_time 计量的应该是解包之后，单个 HTTP1 请求花费的时间。
所以二者间才会有这么多的差距。

[level077]

按照这么理解的话，同一个连接里的request_time越来越大？但是在做压力测试的时候，特别的只设一个并发的情况，并不是这样的。

在 2017年6月12日星期一 UTC+8上午10:12:48，Zexuan Luo写道：

[Zexuan Luo]

同一个连接并不代表从头到尾只有一个请求。
> 但是在做压力测试的时候，特别的只设一个并发的情况，并不是这样的。
这里具体是什么情况？

在 2017年6月14日星期三 UTC+8上午12:06:09，level077写道：

[level077]

> 换句话说，request_time 此时计量的是整个 HTTP2 请求的用时

这里不是很明白。这里的“整个HTTP2请求用时”是指单个流里的请求还是单个HTTP2链接的时间？

问题应该是HTTP2多路复用的问题，但是不是很理解。

HTTP/1.1时一个连接一个请求，或者一个连接多个请求，但是是顺序的。这时request_time记录的是每个请求的用时。

HTTP/2一个连接可以同时发起多个请求，即多个流。这时request_time不是每个请求的了？

在 2017年6月12日星期一 UTC+8上午10:12:48，Zexuan Luo写道：

看上去似乎是 HTTP2 多路复用 的问题？

[Zexuan Luo]

嗯嗯，之前我的说法里面没有区分 TCP 连接 和 HTTP 连接，所以很容易误导人。

request_time 计算方式是 当前时间 - 接收客户端请求内容的时间

HTTP2 中，请求首行是公共的，之后才有多路复用，即多个请求内容合并到一起。（当然如果以请求首行为界，只会有一个 HTTP2 请求，需要经服务器解包之后，才会衍生出多个请求）
换句话说，request_time 计算的是 当前时间 - 收到 HTTP2 请求时间。如果你所说的请求是指被 HTTP2 协议打包的请求们，request_time 记录的时间跟请求的用时没什么关系。

前面说到的 “同一个连接并不代表从头到尾只有一个请求”，是指同一个 TCP 连接中，可能先后有多个 HTTP2 请求。如果我的想法是对的，应该会出现 request_time 逐渐增大，然后又变成一个较小的值的情况。

--
--
邮件来自列表“openresty”,专用于技术讨论!
订阅: 请发空白邮件到 openresty+subscribe@googlegroups.com
发言: 请发邮件到 open...@googlegroups.com
退订: 请发邮件至 openresty+unsubscribe@googlegroups.com
归档: http://groups.google.com/group/openresty
官网: http://openresty.org/
仓库: https://github.com/agentzh/ngx_openresty
教程: http://openresty.org/download/agentzh-nginx-tutorials-zhcn.html

[level077]

开启了一台HTTP/2，经常会看到下图这种情况：

出现问题其实都是同一用户的并发请求多（图中省去了用户IP）。

但是如果说request_time大是没关系的话，应该不会出现status:499的情况，从这里看，用户肯定是受影响了。

还是刚开始说的，从前后端日志及抓包来看，nginx是第一时间把请求发给了上游业务服务器，业务服务器也是第一时间把响应发给了nginx，所以不知道这里的request_time这么大，且status:499是什么情况。换回HTTP/1.1就不会有这种日志记录。

在 2017年6月15日星期四 UTC+8下午3:26:00，Zexuan Luo写道：

嗯嗯，之前我的说法里面没有区分 TCP 连接 和 HTTP 连接，所以很容易误导人。

request_time 计算方式是 当前时间 - 接收客户端请求内容的时间

HTTP2 中，请求首行是公共的，之后才有多路复用，即多个请求内容合并到一起。（当然如果以请求首行为界，只会有一个 HTTP2 请求，需要经服务器解包之后，才会衍生出多个请求）
换句话说，request_time 计算的是 当前时间 - 收到 HTTP2 请求时间。如果你所说的请求是指被 HTTP2 协议打包的请求们，request_time 记录的时间跟请求的用时没什么关系。

前面说到的 “同一个连接并不代表从头到尾只有一个请求”，是指同一个 TCP 连接中，可能先后有多个 HTTP2 请求。如果我的想法是对的，应该会出现 request_time 逐渐增大，然后又变成一个较小的值的情况。

在 2017年6月15日 下午2:44，level077 <leve...@gmail.com>写道：

> 换句话说，request_time 此时计量的是整个 HTTP2 请求的用时

这里不是很明白。这里的“整个HTTP2请求用时”是指单个流里的请求还是单个HTTP2链接的时间？

问题应该是HTTP2多路复用的问题，但是不是很理解。

HTTP/1.1时一个连接一个请求，或者一个连接多个请求，但是是顺序的。这时request_time记录的是每个请求的用时。

HTTP/2一个连接可以同时发起多个请求，即多个流。这时request_time不是每个请求的了？

在 2017年6月12日星期一 UTC+8上午10:12:48，Zexuan Luo写道：

看上去似乎是 HTTP2 多路复用 的问题？

request_time 是从读取 Client 请求的时候开始计时的。
而一个 HTTP2 请求，由于多路复用，可能包含多个实际的请求。

换句话说，request_time 此时计量的是整个 HTTP2 请求的用时，而 upstream_response_time 计量的应该是解包之后，单个 HTTP1 请求花费的时间。
所以二者间才会有这么多的差距。

--
--
邮件来自列表“openresty”,专用于技术讨论!

订阅: 请发空白邮件到 openresty...@googlegroups.com
发言: 请发邮件到 open...@googlegroups.com
退订: 请发邮件至 openresty+...@googlegroups.com

[level077]

图中的request_time好几个值都是一样也有点奇怪，感觉是和多路复用有关系

[Zexuan Luo]

该不会是客户端因为超时断开连接了吧？499 是 Nginx 自定义的状态码，表示客户端已断开连接。
可否计算下，所有并发请求用时加起来，是否跟 request_time 相似？

2017-06-15 16:59 GMT+08:00 level077 <leve...@gmail.com>:

图中的request_time好几个值都是一样也有点奇怪，感觉是和多路复用有关系

--
--
邮件来自列表“openresty”,专用于技术讨论!

订阅: 请发空白邮件到 openresty+subscribe@googlegroups.com
发言: 请发邮件到 open...@googlegroups.com
退订: 请发邮件至 openresty+unsubscribe@googlegroups.com

[level077]

将upstream_response_time加起来相差甚远。499我倒觉得是因为响应长时间不返回，客户端关闭连接了。再给个完整连接的请求记录：

在 2017年6月15日星期四 UTC+8下午5:25:32，Zexuan Luo写道：

该不会是客户端因为超时断开连接了吧？499 是 Nginx 自定义的状态码，表示客户端已断开连接。
可否计算下，所有并发请求用时加起来，是否跟 request_time 相似？

2017-06-15 16:59 GMT+08:00 level077 <leve...@gmail.com>:

图中的request_time好几个值都是一样也有点奇怪，感觉是和多路复用有关系

--
--
邮件来自列表“openresty”,专用于技术讨论!

订阅: 请发空白邮件到 openresty...@googlegroups.com
发言: 请发邮件到 open...@googlegroups.com
退订: 请发邮件至 openresty+...@googlegroups.com

[level077]

这个图比较典型：这4个请求是每个10秒发上来的，在后端日志里看到也是每隔10秒一个请求，在响应返回给nginx后，好像nginx缓存住了这4个响应，然后在同一个时间点发送出去了一样。用户网络问题？

在 2017年6月15日星期四 UTC+8下午5:25:32，Zexuan Luo写道：

该不会是客户端因为超时断开连接了吧？499 是 Nginx 自定义的状态码，表示客户端已断开连接。

可否计算下，所有并发请求用时加起来，是否跟 request_time 相似？

2017-06-15 16:59 GMT+08:00 level077 <leve...@gmail.com>:

图中的request_time好几个值都是一样也有点奇怪，感觉是和多路复用有关系

--
--
邮件来自列表“openresty”,专用于技术讨论!

订阅: 请发空白邮件到 openresty...@googlegroups.com
发言: 请发邮件到 open...@googlegroups.com
退订: 请发邮件至 openresty+...@googlegroups.com

[Zexuan Luo]

看来只好继续在 Nginx 上抓包看看服务器是怎么响应客户端的……

在 2017年6月15日星期四 UTC+8下午7:14:31，level077写道：

[level077]

恩，只是nginx端都是加密的，很难对上具体请求。

在 2017年6月15日星期四 UTC+8下午8:32:39，Zexuan Luo写道：

[Yaung Gao]

@level077

不知道你的499 问题解决没有，我也发现了这个问题，而且499 都是同一客户端同时出现的状态码，我感觉跟http2 的流机制有关系。

订阅: 请发空白邮件到 openresty+subscribe@googlegroups.com
发言: 请发邮件到 open...@googlegroups.com
退订: 请发邮件至 openresty+unsubscribe@googlegroups.com

[level077]

没有啊，切回http/1.1了

在 2017年8月3日星期四 UTC+8下午6:51:47，Yaung Gao写道：

[Tom]

我这开启http2也是发现很多request_time远大于upstream_response_time的情况，环境也是1.11.2，同时日志里也又少比例的408状态，初步判断http2实现的不好。你那有没有更新到1.13.6试试？现在是什么情况呢

在 2017年6月9日星期五 UTC+8下午1:38:53，level077写道：

[level077]

没用1.13.6.1试过，切回1.1后就没再切回2，你尝试了有结果说下:)

在 2018年2月7日星期三 UTC+8下午2:31:21，Tom写道：