On Thu, Aug 27, 2020 at 11:45:13AM +0200, Tim Düsterhus, WoltLab GmbH wrote: > 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.
In the stream output yes, but not in the h1 or h2 output, which do not necessarily have a stream above them (e.g.: checks). However if we had it in the stream output, enabling traces at both levels would be enough to trace them. What I'm missing in both is the conn_stream, which joins the h1/h2 stream and the application layer stream, but that shouldn't be hard to add. For the request counter, same problem. I'm trying to think of an identifier that would be present everywhere but can't think of any. Maybe we could try to attack the issue the other way around and enable the production of a trace_id when traces are enabled, and this trace_id would be passed as much as possible between layers and could also be logged. The problem with muxed connections is that it would have to be generated on a new request, and that for a number of issues, that's already too late. Thus maybe a composite trace ID would help instead, i.e. front connection ID, front stream ID, back stream ID, back connection ID. Missing some of these parts would then not be a problem because it would just mean that we didn't reach that stage. > > 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. Cool! I do imagine that it has been painful, so thanks for doing it! > 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 :-) No problem. > There's even a PHP request within there with an 800ms difference between > nginx and HAProxy. Ah excellent! We'll have something to study at least. I'm suddenly thinking about something: there is a known case of head-of-line blocking in H2 when stream windows are larger than buffers: a slow stream could cause some of its data to block into the connection's buffer for some time. It could very well be what's happening to you: merge two clients on the same backend connection, have one slowly read its data and sometimes the other may experience some hiccups. This should be significantly reduced by reducing the number of concurrent streams however. One way to alleviate this is to reduce the tune.h2.initial-window-size to 16kB but it's used on both sides so it would also mean very slow posts. The other solution is to increase the default buffer size to 64kB so that all of an H2 incoming data's stream window can be flushed into a client's buffer. It may increase your memory consumption a bit if you're mostly dealing with slow clients. A test could consist in setting it to 32kB which will generally be enough as you have one buffer in the mux and another one in the channel ;-) > > 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. Yes I know, that's always the same for me as well. That's the reason why the unique-id feature was implemented so long ago! > 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. Usually with patience it does work. There's still a lot of room for improvement but I often tend to imagine what it would have been without and that helps me be tolerant :-) Regards, Willy
