<div dir="ltr">Hi<div><br><div>Thank you so much. Valentin.</div><div>My understanding:</div><div>Though <span style="font-size:14px">clinklittle128.png has higher priority, the server wants to send it first to the client. But because of flow control, the </span><span style="font-size:14px">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, </span><span style="font-size:14px">preloadjs.min.js etc. When the server received the window update frame, it will send the </span><span style="font-size:14px">clinklittle128.png once again. Am I right?</span></div><div><span style="font-size:14px"><br></span></div><div><span style="font-size:14px">BTW: could you please locate the related source code for me. I want to have a deep research on it. Many Thanks</span></div><div><span style="font-size:14px"><br></span></div><div><span style="font-size:14px">Best Regards</span></div><div><span style="font-size:14px">Muhui Jiang</span></div></div></div><div class="gmail_extra"><br><div class="gmail_quote">2015-10-13 22:14 GMT+08:00 Valentin V. Bartenev <span dir="ltr"><<a href="mailto:vbart@nginx.com" target="_blank">vbart@nginx.com</a>></span>:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><span class="">On Tuesday 13 October 2015 16:05:16 Muhui Jiang wrote:<br>
> Hi<br>
><br>
> move the debug to the main level; And the error.log below: a little bit long. Thanks<br>
><br>
</span>[..]<br>
<span class="">> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806728 was sent<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806728 sid:1 bl:0 len:8192<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806990 was sent<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806990 sid:1 bl:0 len:8192<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806A98 was sent<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806A98 sid:1 bl:0 len:8192<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806BA0 was sent<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806BA0 sid:1 bl:0 len:8192<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806CA8 was sent<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806CA8 sid:1 bl:0 len:8192<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806DB0 was sent<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806DB0 sid:1 bl:0 len:8192<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806EB8 was sent<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806EB8 sid:1 bl:0 len:8192<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2:1 DATA frame 00007F9422806FC0 was sent<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http2 frame sent: 00007F9422806FC0 sid:1 bl:0 len:8191<br>
> 2015/10/13 15:55:58 [debug] 904#0: *20 http write filter 00007F9422806850<br>
<br>
</span>Here nginx has sent 32k of data, and the "/img/clink/clinklittle128.png?" window is exhausted<br>
as well as the connection window.<br>
<br>
[..]<br>
<span class="">> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 HEADERS frame sid:3 on 1 excl:0 weight:256<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F9421803E00:4096 @16<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F9421806000:4096 @16<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 7<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 2<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 64<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header: 4<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 hpack encoded string length: 15<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 add header to hpack table: ":path: /js/preloadjs.min.js"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 hpack table account: 57 free:3876<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http uri: "/js/preloadjs.min.js"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http args: ""<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http exten: "js"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 63<br>
> 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"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 http request line: "GET /js/preloadjs.min.js HTTP/2.0"<br>
<br>
<br>
</span>Here nginx has received the "preloadjs.min.js" request, but cannot proceed with response<br>
since the connection window is exhausted.<br>
<br>
[..]<br>
<span class="">> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 HEADERS frame sid:5 on 1 excl:0 weight:256<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F9420C0ED80:256 @16<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F942100FC00:4096 @16<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 posix_memalign: 00007F9421010C00:4096 @16<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 7<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 2<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 65<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 5<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http uri: "/index.html"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http args: ""<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http exten: "html"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 get indexed header name: 63<br>
> 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"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 http request line: "GET /index.html HTTP/2.0"<br>
<br>
</span>The same as above, but with the "/index.html" request.<br>
<br>
<br>
<br>
[..]<br>
<span class="">> 2015/10/13 15:55:59 [debug] 904#0: *20 process http2 frame type:8 f:0 l:4 sid:0<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 WINDOW_UPDATE frame sid:0 window:32768<br>
<br>
</span>Client sent WINDOW_UPDATE for the connection window.<br>
<br>
[..]<br>
<div><div class="h5">> 2015/10/13 15:55:59 [debug] 904#0: *20 http run request: "/js/preloadjs.min.js?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer handler: "/js/preloadjs.min.js?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http output filter "/js/preloadjs.min.js?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http copy filter: "/js/preloadjs.min.js?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http postpone filter "/js/preloadjs.min.js?" 0000000000000000<br>
> 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<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter: l:1 f:0 s:30839<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter limit 0<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 create DATA frame 00007F9421806720: len:8192 flags:0<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 create DATA frame 00007F9421806988: len:8192 flags:0<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 create DATA frame 00007F9421806A90: len:8192 flags:0<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 create DATA frame 00007F9421806B98: len:6263 flags:1<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F9421806B98 sid:3 bl:0 len:6263<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F9421806A90 sid:3 bl:0 len:8192<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F9421806988 sid:3 bl:0 len:8192<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F9421806720 sid:3 bl:0 len:8192<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 8192<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 7727<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL to write: 16384<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL_write: 16384<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 465<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 8192<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 6263<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL to write: 14938<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL_write: 14938<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 DATA frame 00007F9421806720 was sent<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F9421806720 sid:3 bl:0 len:8192<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 DATA frame 00007F9421806988 was sent<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F9421806988 sid:3 bl:0 len:8192<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 DATA frame 00007F9421806A90 was sent<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F9421806A90 sid:3 bl:0 len:8192<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:3 DATA frame 00007F9421806B98 was sent<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F9421806B98 sid:3 bl:0 len:6263<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter 0000000000000000<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http copy filter: 0 "/js/preloadjs.min.js?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer output filter: 0, "/js/preloadjs.min.js?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer done: "/js/preloadjs.min.js?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http finalize request: 0, "/js/preloadjs.min.js?" a:1, c:1<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http request count:1 blk:0<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 close stream 3, queued 0, processing 4<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http close request<br>
<br>
</div></div>Since nginx cannot process "clinklittle128.png" (its window is still exhausted),<br>
it sends "preloadjs.min.js" response data.<br>
<span class=""><br>
<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http log handler<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 run cleanup: 00007F9421806488<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 file cleanup: fd:9<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 free: 00007F9421008200<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 free: 00007F9421803E00, unused: 2<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 free: 00007F9421806000, unused: 782<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http run request: "/index.html?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer handler: "/index.html?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http output filter "/index.html?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http copy filter: "/index.html?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http postpone filter "/index.html?" 0000000000000000<br>
> 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<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter: l:1 f:0 s:8214<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter limit 0<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:5 create DATA frame 00007F94210112E8: len:1929 flags:0<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame out: 00007F94210112E8 sid:5 bl:0 len:1929<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 9<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL buf copy: 1929<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL to write: 1938<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 SSL_write: 1938<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2:5 DATA frame 00007F94210112E8 was sent<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame sent: 00007F94210112E8 sid:5 bl:0 len:1929<br>
<br>
</span>And using the rest of the connection window, nginx sends "/index.html?".<br>
<span class=""><br>
<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http write filter 00007F9421011410<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http copy filter: -2 "/index.html?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http writer output filter: -2, "/index.html?"<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 frame complete pos:000000010873300D end:000000010873301A<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 process http2 frame type:8 f:0 l:4 sid:1<br>
> 2015/10/13 15:55:59 [debug] 904#0: *20 http2 WINDOW_UPDATE frame sid:1 window:32768<br>
<br>
</span>Only at this moment we have WINDOW_UPDATE on the "clinklittle128.png" stream.<br>
<br>
So nginx behaves absolutely correct here, and tries to utilize the connection<br>
as much as possible.  But the client's behavior results in exhausting flow<br>
control windows and even blocking output (when the connection window is<br>
exhausted).<br>
<div class="HOEnZb"><div class="h5"><br>
  wbr, Valentin V. Bartenev<br>
<br>
_______________________________________________<br>
nginx mailing list<br>
<a href="mailto:nginx@nginx.org">nginx@nginx.org</a><br>
<a href="http://mailman.nginx.org/mailman/listinfo/nginx" rel="noreferrer" target="_blank">http://mailman.nginx.org/mailman/listinfo/nginx</a><br>
</div></div></blockquote></div><br></div>