Metric: Add total http time

[roidelapluie]

HA-Proxy version 2.1.0 2019/11/25 - https://haproxy.org/
Status: stable branch - will stop receiving fixes around Q1 2021.
Known bugs: http://www.haproxy.org/bugs/bugs-2.1.0.html
Build options :                                                      
  TARGET  = linux-glibc                                              
  CPU     = generic
  CC      = gcc                  
  CFLAGS  = -O2 -g -fno-strict-aliasing -Wdeclaration-after-statement -fwrapv -Wno-unused-label -Wno-sign-compare -Wno-unused-parameter -Wn
o-old-style-declaration -Wno-ignored-qualifiers -Wno-clobbered -Wno-missing-field-initializers -Wtype-limits
  OPTIONS = USE_PCRE=1 USE_REGPARM=1 USE_LINUX_TPROXY=1 USE_CRYPT_H=1 USE_GETADDRINFO=1 USE_OPENSSL=1 USE_LUA=1 USE_ZLIB=1 USE_SYSTEMD=1
                                                                     
Feature list : +EPOLL -KQUEUE -MY_EPOLL -MY_SPLICE +NETFILTER +PCRE -PCRE_JIT -PCRE2 -PCRE2_JIT +POLL -PRIVATE_CACHE +THREAD -PTHREAD_PSHAR
ED +REGPARM -STATIC_PCRE -STATIC_PCRE2 +TPROXY +LINUX_TPROXY +LINUX_SPLICE +LIBCRYPT +CRYPT_H -VSYSCALL +GETADDRINFO +OPENSSL +LUA +FUTEX +
ACCEPT4 -MY_ACCEPT4 +ZLIB -SLZ +CPU_AFFINITY +TFO +NS +DL +RT -DEVICEATLAS -51DEGREES -WURFL +SYSTEMD -OBSOLETE_LINKER +PRCTL +THREAD_DUMP 
-EVPORTS                   

Default settings : 
  bufsize = 16384, maxrewrite = 1024, maxpollevents = 200
                                  
Built with multi-threading support (MAX_THREADS=64, default=2).
Built with OpenSSL version : OpenSSL 1.0.2k-fips  26 Jan 2017
Running on OpenSSL version : OpenSSL 1.0.2k-fips  26 Jan 2017
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes 
OpenSSL library supports : SSLv3 TLSv1.0 TLSv1.1 TLSv1.2
Built with Lua version : Lua 5.3.4 
Built with network namespace support.
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Built with PCRE version : 8.32 2012-11-30
Running on PCRE version : 8.32 2012-11-30
PCRE library supports JIT : no (USE_PCRE_JIT not set)
Encrypted password support via crypt(3): yes
Built with zlib version : 1.2.7
Running on zlib version : 1.2.7
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with the Prometheus exporter as a service

Available polling systems :
      epoll : pref=300,  test result OK
       poll : pref=200,  test result OK
     select : pref=150,  test result OK
Total: 3 (3 usable), will use epoll.

Available multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
              h2 : mode=HTTP       side=FE|BE     mux=H2
            fcgi : mode=HTTP       side=BE        mux=FCGI
       <default> : mode=HTTP       side=FE|BE     mux=H1
       <default> : mode=TCP        side=FE|BE     mux=PASS

Available services :
        prometheus-exporter

Available filters :
        [SPOE] spoe
        [CACHE] cache
        [FCGI] fcgi-app
        [TRACE] trace
        [COMP] compression

Linux x.local 3.10.0-957.21.3.el7.x86_64 #1 SMP Fri Jun 14 02:54:29 EDT 2019 x86_64 x86_64 x86_64 GNU/Linux

What should haproxy do differently? Which functionality do you think we should add?

Expose the total http response time to prometheus metrics

haproxy_backend_http_request_time_second_total
haproxy_frontend_http_request_time_second_total
haproxy_backend_http_responses_time_second_total
haproxy_frontend_http_responses_time_second_total

What are you trying to do?

I try to calculate the average response time of http queries.

rate(haproxy_backend_http_responses_time_second_total[5m])
/
rate(haproxy_backend_http_responses_total[5m])  

haproxy_backend_response_time_average_seconds is not helpful as the last 1024 connections could happen in the last second or the last 5 minutes.

[roidelapluie]

I would make sense to use histograms:

haproxy_backend_http_request_time_second_sum
haproxy_backend_http_request_time_second_bucket
haproxy_backend_http_request_time_second_total

buckets being configurable globally:

global
  option prometheus-duration-histograms-buckets 0.125,0.25,0.5,1

[clwluvw]

@roidelapluie Will you please add HTTP methods for haproxy_server_http_responses_total?

[wtarreau]

No, please no. You seem to have to idea how much memory and CPU the current metrics already take, adding more is even worse. A long time ago I intended to add some histograms and more buckets in general in the stats. Nowadays we see huge configs and people want even more performance, there is simply ZERO excuse for asking a load balancer to compute the myriad of stats each user wants while all of these can be trivially extracted from the logs using existing standard tools.

Stats were made for monitoring purposes. I think adding native support for prometheus was a very bad idea because it resulted in fooling people into thinking it's up to the low-level process itself to produce and keep such stats. I'm now convinced it was a huge mistake and that we instead ought to have created a sidecar process to produce such specific stats based on a copy of the logs. With such a architecture, it would become easy to have such an agent run on a different CPU socket or even a different machine, and use all the resources it needs without destroying performance nor adding latency.

[capflam]

To collect data from logs and expose them to Prometheus, you can use mtail or fluentd. Keep in mind that the prometheus exporter is stateless. It only exposes existing internal stats. So each addition comes with a cost, for everyone, not only for Prometheus users. As far as possible, try to use existing info. You can already add so many information in logs on each request. With the right tool, these info can be easily extracted and collected.

[roidelapluie]

Well we do get those data from logs.

The point of this message is that the current metrics (response time of the last X connections) are not helpful and could be replaced by total response time.

[wtarreau]

Probably. Maybe we should simply remove a number of useless metrics that have been accumulating over time and been used as partial indicators instead of direct ones, and see if some of them could be replaced with better ones. I mean, haproxy has adopted stats extremely early because it was critical to fix application and infrastructure issues where it was deployed. Many of them are still HTTP-1.0 centric. There's still some ambiguity between request and connection sometimes. For example the ctime metric is the average connect time per *request*. So when you have server-side keep-alive with connection reuse, it gets smoothed. At the very least it should be per connection and the connection-to-request ratio should be reported. These are just examples of course. Similarly, halog has learned very early to compute the average response time on valid responses only, because 504 and friends were significantly degrading the mean value. We probably ought to do something similar natively with the stats metrics. Reorganizing metrics between those indicating user experience and those indicating infrastructure stability would be nice as well. The backend connect time these days has little effect on user experience thanks to connection reuse, caching etc but is a huge indicator of network health. Conversely the application's response time is an indicator of user experience and not of the network's health. And the total time which cumulates the two is an indicator of nothing. That's something to discuss in order to attack it for 2.3 now. However if we can fix some documentation or slightly readjust a few very confusing metrics before 2.2 gets released, it might still be doable.

[clwluvw]

@wtarreau Promethus exporter is an option that came with build options. when I (user) build HAProxy with this option it means that I want a full and reasonable metrics from HAProxy and also I accept the performance reduction by enabling this option. If it is concern to me and even I don't want it I will switch to another solutions like fluentd or.. and won't build HAProxy with prometheus.
This is completely depend on user and as a feature I think it should be a complete solution for fully monitoring HAProxy when I decide to enable and use prometheus exporter feature!

[wtarreau]

I have nothing against your use of prometheus with haproxy, what I mean is that just having a new way to export metrics doesn't automatically mean that new metrics will born out of nowhere. The main problem with your request for "full and reasonable metrics" is that everyone has a different definition of this, and this is a never-ending story. Strangely before we had the prometheus exporter, everyone used to praise haproxy for its extremely comprehensive metrics which was far more than reasonable. Now it seems that suddenly a small set of users would like their LB to compute and store all the stuff that normally ought to be done on a stats aggregation system, possibly from time-series DB. And what next ? The same people will probably expect stats to be kept across reloads ? Then synced among cluster nodes ? Please don't try to confuse your load balancer with a database.

[capflam]

@clwluvw, You should not see the Prometheus exporter other than as a tool to expose internal stats. As said, it is stateless. So when you ask for new metrics in Prometheus, it means in reality adding new counters in the HAProxy core. For everyone. Without a complete refactoring of the stats mechanism to make it modular, we must be careful when a new counter should be added (In fact, we should always be careful for every addition).

I don't know if we will ever have time to refactor the stats (and the will to do it). But, As Willy said, some existing counters are quite old and not really accurate nowadays. So a dusting is possible but we should think to all users and external tools relying on existing stats (and as always, we need time). It is a sensitive subject.

At short term, it is possible to add a filter to collect specific stats. Filters are stream-centric, so some stats won't be collected this way. But it is probably a good compromise. However, because it already exists some solutions to get more metrics from the logs, I doubt such filter will be quickly inserted in our todo-list.

[primeroz]

The main problem with your request for "full and reasonable metrics" is that everyone has a different definition of this, and this is a never-ending story.

Over the past years, especially in the cloud native / kubernetes world, a consensus on what reasonable metrics are have been reached, and that is the prometheus standard.
For example Histograms rather than averages is absolutely one of them.

Strangely before we had the prometheus exporter, everyone used to praise haproxy for its extremely comprehensive metrics which was far more than reasonable. Now it seems that suddenly a small set of users would like their LB to compute and store all the stuff that normally ought to be done on a stats aggregation system, possibly from time-series DB.

Again different time and different era.\
On my on-prem legacy infrastructure i would agree with you 100% percent, but this small set of users does not run in such an environment anymore and extracting those stats from the logs to then expose to prometheus is just not scalable

The bottom line is that if haproxy want to stay relevant in this new type of infrastructure it needs to address the current set of challenges that this small set of users face. Also because the number of this users will increase exponentially very fast.
You simply can't run an haproxy ingress in kubernetes without those metrics.

And what next ? The same people will probably expect stats to be kept across reloads ? Then synced among cluster nodes ?

All those statements are incorrect.\
The reason why prometheus did become the standard for monitoring is because of is reasonable design especially for dynamic environments like kubernetes, indeed all these points you bring up are addressed at the scraping layer and are not an issue to the metrics provider

You seem to have to idea how much memory and CPU the current metrics already take, adding more is even worse

Just one more note on this. While this is probably true ( i honestly have no idea ) , i personally run multiple Envoy proxies with tens of clusters ( backends ) exposing way more metrics than haproxy does including histograms for each of them and so on and the memory / cpu overhead of it is negligible.

Please don't try to confuse your load balancer with a database.

Again wrong perspective, nobody wants those metrics to be stored on the load balancer, and actually some could argue that some of the metrics currently exposed ( like averages over 1024 requests ) are exactly what you are pointing out .. not the job of a load balancer.
What some of us expect / wish for is to actually get insight into the raw data of the load balancer and have a separate dedicated system to work with the data

[danielbeardsley]

The point of this message is that the current metrics (response time of the last X connections) are not helpful and could be replaced by total response time.

Yes please. I'm sure this is easier to do in haproxy than the current avg response time of the last 1024 requests which is both not useful and likely harder to do for haproxy than just total response time.

Inside prometheus for example, it'd be easy to then do increase(requests) / inscrease(response time) and get the average response time in any given interval.

[UrBnW]

Keeping the max variant (max queue time, max total time) could be a good idea, as it can help troubleshooting.
In addition, they can easily be reset thanks to the operator clear counters command (even automatically triggered).

But I agree that the 1024-last-connections average counters are (totally) useless...
Replacing them by a total variant (total queue time, total total time) would be much more useful.
Here we're grabbing numbers from the JSON stats page export, feeding InfluxDB with them.
And can't do nothing with the "1024" variants...

Thank you very much 👍

[wtarreau]

Hi @UrBnW

I hadn't seen @danielbeardsley's explanation of his use case for the total time above, which matches yours, and seen like this I understand the mathematical reasoning and agree with you. Also it's way more reasonable than computing historgrams on the fly! There may of course be a problem of units there because it's within reach to wrap a 64-bit counter, though not trivial. It could sustain 3 years at 100k req/s 24x7 with a 2s response time. That's obviously not everyone's use case. On the other hand other counters already wrap and all properly designed monitoring systems already deal with that cleanly so that should not be an issue.

I'll see where we can stuff this total time in the server and backend struct (and maybe frontend, I'll see). I'll check with @capflam next week how this could be done in the prometheus exporter, if anything needs to be done there at all. Thanks for the explanation!

[Tristan971]

There may of course be a problem of units there because it's within reach to wrap a 64-bit counter, though not trivial

Prometheus corrects for monotonicity so that’s not a problem in this case 👍

[UrBnW]

One additional thought, if I may, while we are in stat counters.

In mode tcp, we have following duration counters : qtime, ctime and ttime (and their max variants).

We could think about relying on qtime to measure impact of queuing on clients.
But the big issue with qtime is that it is impacted by clients themselves.
For example, if client takes time to send its SNI Hello message, qtime inscreases accordingly.

We can then have quite "huge" qtime counters, even if qmax remains at 0 (which is then rather strange in terms of consistency).

Not sure how we could handle this, but I suspect qtime should only reflect time in the queue waiting for a session / backend slot.
And should then not include the client related part.

Perhaps then we need a new qwaitingtime counter in addition to a qtotaltime counter (the current qtime version).

Of course feel free :)

[wtarreau]

Oh I remember about that one, that I already wanted to address in 2.4 then 2.6, then... Every time we forget about it. The reason is totally stupid: originally there was no way to wait for anything, so the qtime was what was left once you deduced the request time, connect time and response time from the total time. Nowadays it's totally wrong and I would like to introduce a processing time (think about Lua scripts) and maybe even later a comptuation time that would be part of this. The processing time is impacted by multiple factors, computation, DNS resolution, waiting for more data from the client etc. So maybe later it could be refined, but in the mean time at least that would allow us to fix this qtime once for all. And to be clear, I consider the current behavior a bug.

[UrBnW]

Glad to hear from you @wtarreau, and thank you for your detailed answer, really appreciated 👍

So as per my understanding, if processing time is also deduced from the total time (in addition to the req/conn/resp times), then qtime will be accurate (and should stick to 0, until waiting for a session/ backend slot).

I just wonder whether or not it will also solve this qtime bug in such a mode tcp configuration :

frontend https
    mode tcp
    bind 10.10.10.10:443
    tcp-request inspect-delay 2500
    tcp-request content reject unless { req.ssl_hello_type 1 }
    use_backend foo-ssl if { req_ssl_sni -m beg foo }
    use_backend bar-ssl if { req_ssl_sni -m beg bar }

Currently, with such a configuration, qtime is impacted by the time the client needs/consumes to send its SNI Hello message.
Would this time (finally, the time between the first byte and the backend selection) be part of the processing time ? And as a result would guarantee that qtime is truly time spent in queue waiting for a backend slot ?

While here in stats, here's an improvement proposal.
We currently have some stat URL options such as ?json, ?csv...
Would be nice to add ?clear (and ?clearall ?) to reset max (all ?) counters as soon as they have been grabbed. So that we have relevant max values for the requested periods.

Thank you again 👍

[wtarreau]

Yes the goal is that your config above doesn't affect qtime. Also regarding your stats proposal, please do not deviate from the original topic or it becomes impossible to follow issues. It's already amazingly complicated to context-switch between tens at a time, but if multiple topics are opened in each it's impossible. And to make a long story short, no, we should really not allow the clear operation to be done by URL like this because it means anyone could do it. You can do it over the CLI however ("clear counters" I think). We could possibly think about this only for authenticated users, in "stats admin" mode but few people use it, and it'd remain extremely low on the priority list.