Performance regression between 0.5.0 and 0.11.0 #270
Comments
|
0.5.0 was compiled with go1.8.3, while 0.11.0 was compiled with go1.9.2. I'll try to recompile both with the same version to see how it looks. |
|
0.11.0 compiled with go1.8.3 looks pretty much the same as compiled with go1.9.2:
Total CPU usage is also the same. |
|
Looks like something happened between 0.5.0 and 0.6.0, flamegraphs are the same from 0.6.0 up. On 0.5.0 I see messages in the logs:
Distribution of errors looks roughly like this: There is nothing like that in the logs starting from 0.6.0. |
|
I wonder if we hit the bug that @vkrasnov described here:
On 0.5.0 with On 0.11.0 I see this: |
|
0.5.0 doesn't have pprof enabled, but 0.11.0 has the following:
Zoomed in:
|
|
That was loadtested at the time and had no impact. |
|
You can see 0.5.0, then 7abdf05 from 04:32 to 04:44, then 5cfd105 from 04:55. @brian-brazil it looks like there is impact after all. |
|
I've tested locally with the two commits you have referenced and noticed a ~15% increase in CPU time used. (Tested by issuing 1000 probes to a target and checking the Blackbox exporter's process_cpu_seconds_total metric) |
|
I see lots of GC and lots of memory allocated in gzip. It looks like 7abdf05 started using probobuf + gzip, while 5cfd105 is doing plaintext responses. I validated this by passing this header to curl:
0.5.0 -> 0.11.0 -> 0.11.0 with Even with that, still not 15% increase. I'm measuring with cgroup metrics from cadvisor. |
|
Can you share your full config? I don't plan on switching away from the Go client, creating the text format by hand was only a stopgap while the client lacked a feature needed for this exporter. |
|
Not a full config, but this exporter is mostly doing My test is:
0.196s user + 0.190s sys = 0.386s total
0.776s user + 0.290s sys = 1.066s total Totals: 1.066s / 0.386s = 2.76x slower. It's not as tragic as I see with real exporter pinging local stuff, but still not great. Keep in mind that it's 32 core machine, so |
|
ICMP is going to be one of the cheaper probes, so the impact of other parts of the code will be seen more. That's still 1k probes/core/second which I think is reasonable performance. I don't think there's much we can do on our side, but if you've specific suggestions to improve client_golang you can file them there. |
|
Somehow I forgot to pass
2.402s / 0.378s = 6.35x |
package gzip
import (
"io/ioutil"
"net/http"
"net/http/httptest"
"testing"
"github.com/prometheus/client_golang/prometheus"
"github.com/prometheus/client_golang/prometheus/promhttp"
)
const acceptHeader = "application/vnd.google.protobuf;proto=io.prometheus.client.MetricFamily;encoding=delimited;q=0.7,text/plain;version=0.0.4;q=0.3,*/*;q=0.1"
func handler() http.HandlerFunc {
registry := prometheus.NewRegistry()
metric := prometheus.NewGauge(prometheus.GaugeOpts{
Name: "probe_success",
Help: "Displays whether or not the probe was a success",
})
metric.Inc()
registry.MustRegister(metric)
return promhttp.HandlerFor(registry, promhttp.HandlerOpts{}).(http.HandlerFunc)
}
func TestPromHTTP(t *testing.T) {
handler := handler()
request := httptest.NewRequest("GET", "http://example.com/foo", nil)
w := httptest.NewRecorder()
handler(w, request)
response := w.Result()
body, err := ioutil.ReadAll(response.Body)
if err != nil {
t.Fatalf("Error reading body: %s", err)
}
if err = response.Body.Close(); err != nil {
t.Fatalf("Error closing body: %s", err)
}
if response.StatusCode != http.StatusOK {
t.Errorf("Unexpected non-200 status: %d", response.StatusCode)
}
if len(body) == 0 {
t.Errorf("Unexpected zero length response")
}
}
func BenchmarkPromHTTPEmptyHeaders(b *testing.B) {
benchmarkPromHTTP(b, map[string]string{})
}
func BenchmarkPromHTTPAccept(b *testing.B) {
benchmarkPromHTTP(b, map[string]string{
"Accept": acceptHeader,
})
}
func BenchmarkPromHTTPAcceptAndAcceptEncoding(b *testing.B) {
benchmarkPromHTTP(b, map[string]string{
"Accept": acceptHeader,
"Accept-Encoding": "gzip",
})
}
func benchmarkPromHTTP(b *testing.B, headers map[string]string) {
handler := handler()
for n := 0; n < b.N; n++ {
request := httptest.NewRequest("GET", "http://example.com/foo", nil)
for k, v := range headers {
request.Header.Add(k, v)
}
w := httptest.NewRecorder()
handler(w, request)
response := w.Result()
_, err := ioutil.ReadAll(response.Body)
if err != nil {
b.Fatalf("Error reading body: %s", err)
}
if err = response.Body.Close(); err != nil {
b.Fatalf("Error closing body: %s", err)
}
}
}Definitely looks like compression is dominating CPU usage for intensively queried blackbox exporters. |
|
Also, higher
|
|
Definitely looks like golang/go#22743. This is after bumping |
|
There's nothing to be done here, this is a Go problem at this stage. |
|
I think you can provide a way to disable gzip compression. |
|
This is now implemented by @prymitive: prometheus/prometheus#12319 |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
We upgraded from 0.5.0 to 0.11.0 and saw this in CPU usage:
Before and after flamegraphs from 120s of runtime are below.
If you zoom into
main.ProbeHandlerin both, you can see the following:This seems like a severe enough regression worth looking into.
The text was updated successfully, but these errors were encountered: