Http2 Priority

Valentin V. Bartenev vbart at nginx.com
Tue Oct 13 14:14:03 UTC 2015 

On Tuesday 13 October 2015 16:05:16 Muhui Jiang wrote:
> Hi
> 
> move the debug to the main level; And the error.log below: a little bit long. Thanks
> 
[..]
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806728 was sent
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806728 sid:1 bl:0 len:8192
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806990 was sent
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806990 sid:1 bl:0 len:8192
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806A98 was sent
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806A98 sid:1 bl:0 len:8192
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806BA0 was sent
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806BA0 sid:1 bl:0 len:8192
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806CA8 was sent
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806CA8 sid:1 bl:0 len:8192
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806DB0 was sent
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806DB0 sid:1 bl:0 len:8192
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806EB8 was sent
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806EB8 sid:1 bl:0 len:8192
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806FC0 was sent
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806FC0 sid:1 bl:0 len:8191
> 2015/10/13 15:55:58 [debug] 904#0: *20 http write filter 00007F9422806850

Here nginx has sent 32k of data, and the "/img/clink/clinklittle128.png?" window is exhausted
as well as the connection window.

[..]
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 HEADERS frame sid:3 on 1 excl:0 weight:256
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F9421803E00:4096 @16
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F9421806000:4096 @16
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 7
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 2
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 64
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header: 4
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 hpack encoded string length: 15
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 add header to hpack table: ":path: /js/preloadjs.min.js"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 hpack table account: 57 free:3876
> 2015/10/13 15:55:59 [debug] 904#0: *20 http uri: "/js/preloadjs.min.js"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http args: ""
> 2015/10/13 15:55:59 [debug] 904#0: *20 http exten: "js"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 63
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 http header: "user-agent: org.eclipse.jetty.http2.client.HTTP2Client/9.3.z-SNAPSHOT"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 http request line: "GET /js/preloadjs.min.js HTTP/2.0"


Here nginx has received the "preloadjs.min.js" request, but cannot proceed with response
since the connection window is exhausted.

[..]
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 HEADERS frame sid:5 on 1 excl:0 weight:256
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F9420C0ED80:256 @16
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F942100FC00:4096 @16
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F9421010C00:4096 @16
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 7
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 2
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 65
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 5
> 2015/10/13 15:55:59 [debug] 904#0: *20 http uri: "/index.html"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http args: ""
> 2015/10/13 15:55:59 [debug] 904#0: *20 http exten: "html"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 63
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 http header: "user-agent: org.eclipse.jetty.http2.client.HTTP2Client/9.3.z-SNAPSHOT"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 http request line: "GET /index.html HTTP/2.0"

The same as above, but with the "/index.html" request.

 

[..]
> 2015/10/13 15:55:59 [debug] 904#0: *20 process http2 frame type:8 f:0 l:4 sid:0
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 WINDOW_UPDATE frame sid:0 window:32768

Client sent WINDOW_UPDATE for the connection window.

[..]
> 2015/10/13 15:55:59 [debug] 904#0: *20 http run request: "/js/preloadjs.min.js?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer handler: "/js/preloadjs.min.js?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http output filter "/js/preloadjs.min.js?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http copy filter: "/js/preloadjs.min.js?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http postpone filter "/js/preloadjs.min.js?" 0000000000000000
> 2015/10/13 15:55:59 [debug] 904#0: *20 write old buf t:1 f:1 00007F9421008200, pos 00007F9421008200, size: 30839 file: 0, size: 30839
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter: l:1 f:0 s:30839
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter limit 0
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 create DATA frame 00007F9421806720: len:8192 flags:0
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 create DATA frame 00007F9421806988: len:8192 flags:0
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 create DATA frame 00007F9421806A90: len:8192 flags:0
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 create DATA frame 00007F9421806B98: len:6263 flags:1
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F9421806B98 sid:3 bl:0 len:6263
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F9421806A90 sid:3 bl:0 len:8192
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F9421806988 sid:3 bl:0 len:8192
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F9421806720 sid:3 bl:0 len:8192
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 8192
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 7727
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL to write: 16384
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL_write: 16384
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 465
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 8192
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 6263
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL to write: 14938
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL_write: 14938
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 DATA frame 00007F9421806720 was sent
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F9421806720 sid:3 bl:0 len:8192
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 DATA frame 00007F9421806988 was sent
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F9421806988 sid:3 bl:0 len:8192
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 DATA frame 00007F9421806A90 was sent
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F9421806A90 sid:3 bl:0 len:8192
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 DATA frame 00007F9421806B98 was sent
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F9421806B98 sid:3 bl:0 len:6263
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter 0000000000000000
> 2015/10/13 15:55:59 [debug] 904#0: *20 http copy filter: 0 "/js/preloadjs.min.js?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer output filter: 0, "/js/preloadjs.min.js?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer done: "/js/preloadjs.min.js?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http finalize request: 0, "/js/preloadjs.min.js?" a:1, c:1
> 2015/10/13 15:55:59 [debug] 904#0: *20 http request count:1 blk:0
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 close stream 3, queued 0, processing 4
> 2015/10/13 15:55:59 [debug] 904#0: *20 http close request

Since nginx cannot process "clinklittle128.png" (its window is still exhausted),
it sends "preloadjs.min.js" response data.


> 2015/10/13 15:55:59 [debug] 904#0: *20 http log handler
> 2015/10/13 15:55:59 [debug] 904#0: *20 run cleanup: 00007F9421806488
> 2015/10/13 15:55:59 [debug] 904#0: *20 file cleanup: fd:9
> 2015/10/13 15:55:59 [debug] 904#0: *20 free: 00007F9421008200
> 2015/10/13 15:55:59 [debug] 904#0: *20 free: 00007F9421803E00, unused: 2
> 2015/10/13 15:55:59 [debug] 904#0: *20 free: 00007F9421806000, unused: 782
> 2015/10/13 15:55:59 [debug] 904#0: *20 http run request: "/index.html?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer handler: "/index.html?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http output filter "/index.html?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http copy filter: "/index.html?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http postpone filter "/index.html?" 0000000000000000
> 2015/10/13 15:55:59 [debug] 904#0: *20 write old buf t:1 f:1 00007F9421011C00, pos 00007F9421011C00, size: 8214 file: 0, size: 8214
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter: l:1 f:0 s:8214
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter limit 0
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:5 create DATA frame 00007F94210112E8: len:1929 flags:0
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F94210112E8 sid:5 bl:0 len:1929
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 1929
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL to write: 1938
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL_write: 1938
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:5 DATA frame 00007F94210112E8 was sent
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F94210112E8 sid:5 bl:0 len:1929

And using the rest of the connection window, nginx sends "/index.html?".


> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter 00007F9421011410
> 2015/10/13 15:55:59 [debug] 904#0: *20 http copy filter: -2 "/index.html?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer output filter: -2, "/index.html?"
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame complete pos:000000010873300D end:000000010873301A
> 2015/10/13 15:55:59 [debug] 904#0: *20 process http2 frame type:8 f:0 l:4 sid:1
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 WINDOW_UPDATE frame sid:1 window:32768

Only at this moment we have WINDOW_UPDATE on the "clinklittle128.png" stream.

So nginx behaves absolutely correct here, and tries to utilize the connection
as much as possible.  But the client's behavior results in exhausting flow
control windows and even blocking output (when the connection window is
exhausted).

  wbr, Valentin V. Bartenev

More information about the nginx mailing list