Willy, Am 27.08.20 um 10:29 schrieb Willy Tarreau: >> 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 :-/
The unique-id is a property of the the stream (struct stream).unique_id. So that one should technically be available, no? I would also be happy with using the internal request_counter (the %rt log value), because that one is part of my unique ID format anyway. >> 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. Okay, that works sufficiently well for me. I've extracted the relevant parts, redacted any private information and will check with a coworker to see if I missed anything. I'll send you the traces + logs in private after the contents have been ACKed :-) There's even a PHP request within there with an 800ms difference between nginx and HAProxy. > 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. Nothing else for now. grepping for the pointers worked sufficiently well. The bigger issue is identifying the request in question in the first place. I was lucky that the file in this case was fairly low-trafficked so that I was able to accurately identify it based on the timestamp and path. Best regards Tim Düsterhus Developer WoltLab GmbH -- WoltLab GmbH Nedlitzer Str. 27B 14469 Potsdam Tel.: +49 331 96784338 [email protected] www.woltlab.com Managing director: Marcel Werk AG Potsdam HRB 26795 P
