Problems with HTTP/2 priority processing #5836
Description
I have spent time this week working with HTTP/2 priority processing. PR #5835 came from that effort. In addition I am seeing some odd things in the priority tree. I am using the webpagetest.org http2priorities.html test page that @shukitchan found. https://github.com/pmeenan/http2priorities/tree/master/stand-alone.
In this test, you provide an image URL and the http2priorities pages creates a page that fetches the image 2 times sequentially. Then issues 30 low priority requests in parallel. Then issues two high priority requests in series after two of the low priority pages finish. If you don't have too much buffering between the CDN and the client, the high priority requests will preempt the earlier low priority requests. And indeed that is what I see with my results with the fix from PR #5835 applied. On my server I'm using cachekey so the image comes from the ATS cache. http://webpagetest.org/result/190816_HF_6186ba053b188c8f6c2488912ea2e05c/1/details/
But after the two high priority requests are answered, the remainder of the responses come back very slowly. One oddity from looking at the debug messages, is that after the higher priority requests, come in the priority tree appears to be somewhat corrupted. In the debug messages we dump the tree before each stream delete. When we get ready to delete the first high priority stream 65, the tree is
[Aug 16 22:41:40.669] {0x2b078f902700} [ET_NET 29] DEBUG: <Http2ConnectionState.cc:1258 (delete_stream)> (http2_con) [39] [65] Delete stream
[Aug 16 22:41:40.669] {0x2b078f902700} [ET_NET 29] DEBUG: <Http2ConnectionState.cc:1269 (delete_stream)> (http2_priority) [39] { "id":"0/15/0/1/d", "c":[{ "id":"65/219/1467216/1/d", "c":[{ "id":"23/15/9577943/0/d", "c":[{ "id":"25/15/9577945/1/a", "c":[{ "id":"27/146/27/1/a", "c":[{ "id":"29/146/29/1/a", "c":[{ "id":"31/146/31/1/a", "c":[{ "id":"33/146/33/1/a", "c":[{ "id":"35/146/35/1/a", "c":[{ "id":"37/146/37/1/a", "c":[{ "id":"39/146/39/1/a", "c":[{ "id":"41/146/41/1/a", "c":[{ "id":"43/146/43/1/a", "c":[{ "id":"45/146/45/1/a", "c":[{ "id":"47/146/47/1/a", "c":[{ "id":"49/146/49/1/a", "c":[{ "id":"51/146/51/1/a", "c":[{ "id":"53/146/53/1/a", "c":[{ "id":"55/146/55/1/a", "c":[{ "id":"57/146/57/1/a", "c":[{ "id":"59/146/59/1/a", "c":[{ "id":"61/146/61/1/a", "c":[{ "id":"63/146/63/1/a", "c":[] },] },] },] },] },] },] },] },] },] },] },] },] },] },] },] },] },] },] },] },] },] },] }
This is a chrome requests, so the tree is really a list. The problem is node 23 and 25. 23/15/9577943/0/d and 25/15/9577945/1/a. They both came in with weight 146 as all the other low priority requests did. But here they are showing with weight of 15. At this point both streams 23 and 25 are done and should have been removed.
Not clear this is what is causing the slow down, but it does seem odd.