joemiller
commented
4 years ago I may have spoken too soon. I am able to get a successful response after setting up an isolated instance of 0.14 that is not receiving any other traffic and changing maxBatchSize within the backend block to 0, albeit slower - about 60s compared to 10-15s.
I'll probably close this bug in a few minutes if I can replicate this success with the primary instance of carbonapi.
EDIT:
The next time I made the same request (after letting the 60s cache expire)it responded in ~2s with a 500:
{"level":"WARN","timestamp":"2020-08-04T00:02:47.373Z","logger":"zipper","message":"find request failed when resolving globs","type":"broadcastGroup","groupName":"root","metric_name":"foo.*.live.*.mysql_replica.lag_seconds.value","error":"timeout while fetching data"}
carbonapi-0-14-7b8dbf7cd-qbdsw carbonapi {"level":"WARN","timestamp":"2020-08-04T00:02:47.373Z","logger":"zipper","message":"errors occurred while getting results","type":"autoGroup","name":"http://go-carbon-1.go-carbon:8000","type":"protoV2Group","name":"http://go-carbon-1.go-carbon:8000_protobuf","type":"find","request":["foo.*.live.*.mysql_replica.lag_seconds.value"],"errors":"max tries exceeded: failed to fetch data from server/group: Get \"http://go-carbon-1.go-carbon:8000/metrics/find/?format=protobuf&query=foo.%2A.live.%2A.mysql_replica.lag_seconds.value\": context deadline exceeded","errorsVerbose":"max tries exceeded\n\ngithub.com/go-graphite/carbonapi/zipper/types.init\n\t/root/go/src/github.com/go-graphite/carbonapi/zipper/types/errors.go:21\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5420\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:190\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373\n\n\nCaused By: failed to fetch data from server/group\n\ngithub.com/go-graphite/carbonapi/zipper/types.init\n\t/root/go/src/github.com/go-graphite/carbonapi/zipper/types/errors.go:22\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5420\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:190\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373\n\n\nCaused By: Get \"http://go-carbon-1.go-carbon:8000/metrics/find/?format=protobuf&query=foo.%2A.live.%2A.mysql_replica.lag_seconds.value\": context deadline exceeded"}
{"level":"WARN","timestamp":"2020-08-04T00:02:47.373Z","logger":"zipper","message":"errors occurred while getting results","type":"autoGroup","name":"http://go-carbon-0.go-carbon:8000","type":"protoV2Group","name":"http://go-carbon-0.go-carbon:8000_protobuf","type":"find","request":["foo.*.live.*.mysql_replica.lag_seconds.value"],"errors":"max tries exceeded: failed to fetch data from server/group: Get \"http://go-carbon-0.go-carbon:8000/metrics/find/?format=protobuf&query=foo.%2A.live.%2A.mysql_replica.lag_seconds.value\": context deadline exceeded","errorsVerbose":"max tries exceeded\n\ngithub.com/go-graphite/carbonapi/zipper/types.init\n\t/root/go/src/github.com/go-graphite/carbonapi/zipper/types/errors.go:21\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5420\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:190\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373\n\n\nCaused By: failed to fetch data from server/group\n\ngithub.com/go-graphite/carbonapi/zipper/types.init\n\t/root/go/src/github.com/go-graphite/carbonapi/zipper/types/errors.go:22\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5420\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:5415\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:190\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373\n\n\nCaused By: Get \"http://go-carbon-0.go-carbon:8000/metrics/find/?format=protobuf&query=foo.%2A.live.%2A.mysql_replica.lag_seconds.value\": context deadline exceeded"}
{"level":"ERROR","timestamp":"2020-08-04T00:02:47.373Z","logger":"access","message":"request failed","data":{"handler":"render","carbonapi_uuid":"5127fb89-9f6a-458c-93eb-c32120974d0b","url":"/render/?from=-5minutes&target=currentAbove(foo.*.live.*.mysql_replica.lag_seconds.value,1200)","peer_ip":"10.48.5.1","host":"proxy","use_cache":true,"targets":["currentAbove(foo.*.live.*.mysql_replica.lag_seconds.value,1200)"],"cache_timeout":60,"runtime":2.00074282,"http_code":500,"reason":"error or no response: no metrics in the Response","from":1596499065,"until":1596499365,"from_raw":"-5minutes","uri":"/render/?from=-5minutes&target=currentAbove(foo.*.live.*.mysql_replica.lag_seconds.value,1200)","from_cache":false,"used_backend_cache":false,"request_headers":{}}}
{"level":"WARN","timestamp":"2020-08-04T00:02:47.373Z","logger":"slow","message":"Slow Request","time":2.000934282,"url":"https:///render/?from=-5minutes&target=currentAbove(foo.*.live.*.mysql_replica.lag_seconds.value,1200)","referer":""}Immediately after the failed 2nd request, the 3rd request succeeded in ~89seconds.
EDIT 2:
After analyzing the parsed config struct that is printed during startup I noticed there was a find timeout in the Upstreams/Backends section that was using a default of 2 seconds. I think I may have resolved the 500 error that finishes in 2 seconds by adding a find timeout in the global upstreams section:
upstreams:
buckets: 10
timeouts:
find: "300s"
global: "300s"
afterStarted: "120s"
connect: "500ms"It is difficult to know for sure, however, as the results have been a bit unpredictable overall.
EDIT 4:
It seems like the upstreams/timeout/find setting has helped resolve the intermittent 500s that occur after 2 seconds.
However the overall performance compared to 0.10 is lower. The fastest result I've achieved with 0.14 is ~45s with most between 60-120s. This is compared to often seeing 10-20s responses with 0.10. Not sure if there's any additional tuning I can do here though.
EDIT 5: sorry
From watching the queries coming into go-carbon via tcpdump, some observations:
With my 0.10 config I see a lot of small/fast queries for the individual timeseries, eg:
foo.A.a.valuefoo.A.b.valuefoo.B.a.valuefoo.B.b.value
With the 0.14 config I see batches of queries from the "parent", eg:
foo.A.a.value, foo.A.b.valuefoo.B.a.value, foo.B.b.value
I would think the batches would be faster but that doesn't seem to be the case from my observations thus far.
EDIT 6:
After observing the batched requests appear to be serial, one at a time, I took a look at netstat and
noticed there's only ever 1 connection from my caronbapi pod to the go-carbon backends for 0.14, whereas my 0.10 pods have many more connections. I've tried all sorts of combinations of the various concurrency settings including leaving the defaults.
Civil
reyjrar
BorisMan9
ganlvtech
Describe the bug We're seeing a consistent timeout on a specific query we run after upgrading from carbonapi 0.10 to 0.14 (running current master).
The query is (some redactions):
This query has high cardinality. There are ~50k metrics I think. I'm guessing this value based on some DEBUG output from carbonapi 0.10 with an attribute
zipper_requests: 49678.I have enabled debug logging with both carbonapi 0.10 and 0.14 but I don't see any particularly helpful output. I can look for some specific key words if pointed in the right direction.
Instead I've been tcpdumping on go-carbon's http port in order to identify any differences in the queries being sent by the different carbonapi version. My observations:
When running the query against carbonapi 0.10 I see mostly individual /render calls like:
And the query to carbonapi returns in ~10-15s usually.
When running the same query against carbonapi 0.14 I see lots of /metrics/find requests in addition to the /render requests to go-carbon like the following (from a glance it looks like 1 /metrics/find + 1 /render call for each timeseries in the glob):
In other words it appears that carbonapi 0.14 is sending a /metrics/find request + a /render request for every timeseries and eventually the query times out.
CarbonAPI Configuration:
0.10 configuration is:
Latest attempted 0.14 configuration is:
I have tried different variations of
maxBatchSizesuch as 0, 1, 2000 but the behavior of a timed out query remains in all cases.