Http2 Priority

Tue Oct 13 14:43:48 UTC 2015

Hi

Thank you so much. Valentin.
My understanding:
Though clinklittle128.png has higher priority, the server wants to send it
first to the client. But because of flow control, the clinklittle128.png is
blocked(waiting for the window update frame). But at this time the server
don't want to waste the resource, so it will send the index.html,
preloadjs.min.js
etc. When the server received the window update frame, it will send
the clinklittle128.png
once again. Am I right?

BTW: could you please locate the related source code for me. I want to have
a deep research on it. Many Thanks

Best Regards
Muhui Jiang

2015-10-13 22:14 GMT+08:00 Valentin V. Bartenev <vbart at nginx.com>:

> 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
>
> _______________________________________________
> nginx mailing list
> nginx at nginx.org
> http://mailman.nginx.org/mailman/listinfo/nginx
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20151013/e28072db/attachment.html>