Hi Tim, On Thu, Aug 27, 2020 at 10:05:08AM +0200, Tim Düsterhus, WoltLab GmbH wrote: > My definition of reproducible is "I can write up a list of steps that > makes the issue happen somewhat reliably".
OK, that's fine by me :-) > This morning I re-enabled H2 for the backend communication and then > plugged in the tracing. In the half of an hour since I reenabled H2 I'm > seeing 160 static requests taking longer than 45ms, with the worst ones > being > 800ms. So there's definitely something related to H2. > I now have the trace results and my HAProxy log where I can correlate > the slow requests using the timestamp and path. Unfortunately the trace > does not appear to contain the unique-id of the request. Sadly, due to the way HPACK works we can't decode the headers being sent. There's already a ugly hack being done for the URI and method. I seem to remember we peak them from the HTX's start line, but it could not reliably be done for all headers. I'd still like to improve this :-/ It's possible to also log the streams (at level developer) and get the full requests/responses but they will not necessarily correlate with the H2 traffic (though it could give you high enough confidence). > Can I somehow filter down the trace file to just the offending requests > + possible the requests within the same H2 connection? For privacy > reasons I would not like to provide the full trace log, even if it's in > a non-public email. Of course I understand. You can rely on the "h2c" pointer that appears in the trace, it's the H2 connection. For example below, I'm forwarding an H2 request from a frontend to a backend: <0>2020-08-27T10:23:26.117936+02:00 [01|h2|0|mux_h2.c:2541] rcvd H2 request : h2c=0x7f59f0026880(F,FRH) : [1] H2 REQ: GET http://127.0.0.1:4446/ HTTP/2.0 <0>2020-08-27T10:23:26.128922+02:00 [01|h2|0|mux_h2.c:5152] sent H2 request : h2c=0x7f59f00382a0(B,FRH) h2s=0x7f59f0037fa0(1,IDL) : [1] H2 REQ: GET http://mail.google.com/ HTTP/2.0 <0>2020-08-27T10:23:26.149012+02:00 [01|h2|0|mux_h2.c:2632] rcvd H2 response : h2c=0x7f59f00382a0(B,FRH) : [1] H2 RES: HTTP/2.0 301 <0>2020-08-27T10:23:26.149041+02:00 [01|h2|0|mux_h2.c:4790] sent H2 response : h2c=0x7f59f0026880(F,FRH) h2s=0x7f59f0027dc0(1,HCR) : [1] H2 RES: HTTP/2.0 301 You can see two h2c connections, one is on the frontend (hence the 'F') and the other one is on the backend. The h2s is the H2 stream, unique to a request (though it comes from a pool, so it will be reused for new streams on any connection once this one is finished). Thus bu just filtering on the h2 and correlating with what you see in the logs (with your source ports), and the date of course, you can quite reliably match connections, hence requests. Do not hesitate to let me know if you think of something that can be improved, traces are still quite young and under exploited, I'm quite open to studying potential improvements. Willy
