Victoriametrics: Query taking more than a minute to give the data

[bhavith]

Describe the bug
We are running the below queries using Grafana in a single panel.

sort_desc(avg by (container,namespace) (max by (app,kubernetes_cluster, namespace, container, pod) (rate(container_cpu_usage_seconds_total{pod=~"(api-.*)|(api.*)",pod!~"api-auth-.*”,app=~”app-01”}[1m]))/ ignoring(pod) group_left (app,kubernetes_cluster, namespace, container)(max by (app,kubernetes_cluster, namespace, container) (kube_pod_container_resource_limits_cpu_cores{pod=~"(api-.*)|(api.*)",pod!~"api-auth-.*”,app=~”app-01”}))))

sort_desc(max by (container,namespace) (max by (app,kubernetes_cluster, namespace, container, pod) (rate(container_cpu_usage_seconds_total{pod=~"(api-.*)|(api.*)",pod!~"api-auth-.*”,app=~”app-01”}[1m]))/ ignoring(pod) group_left (app,kubernetes_cluster, namespace, container)(max by (app,kubernetes_cluster, namespace, container) (kube_pod_container_resource_limits_cpu_cores{pod=~"(api-.*)|(api.*)",pod!~"api-auth-.*”,app=~”app-01”}))))

With Prometheus as the datasource, we are getting a response in 1-2 seconds. Victoriametrics is taking unusually long time to get the response (duration logged is 1m52.205813616s). At times I get a 504 response.

Expected behavior
The performance should be same or better than that of prometheus

Version
docker image tag: 1.26.0-cluster

Additional context

• We are running clustered victoriametrics in GKE.
• For vmstorage, the data is stored in a HDD persistent disk.
• There are 2pods running for each component
• RAM & CPU are as below:
  
  
  
  • vmstorage (3 cpu & 15 Gi memory) *2
  
  
  • vmselect (1 cpu & 10 Gi memory) * 2
  
  
  • vminsert (4 cpu & 6 Gi memory) * 2
  
  
• vm_cache_entries{type="storage/hour_metric_ids"}
  
  
  
  • vmstorage-0 : 1546807
  
  
  • vmstorage-1 : 1210255
  
  
• Graph for count(container_cpu_usage_seconds_total), count(kube_pod_container_resource_limits_cpu_cores) and count({pod=~"api.*"})
  
  
• count({app="app-01"})
  Prometheus : 636008
  VictoriaMetrics : 622515

[valyala]

The number of active time series - 1.5 million per vmstorage pod - and the number of unique time series touched by the query isn't so big - 636K for the label app="app-01". This means that the query should work much faster in general.

1. Which time range do you use for the query?
2. Could you post graphs for sum(vm_rows) by (type, instance) query?
3. Could you post CPU usage and disk usage graphs for vmstorage and vmselect pods?

[bhavith]

1. Its pretty slow even if I query data for the last 15 minutes

2. 

3. Resource usage
   vmstorage
   
   vmselect
   

[valyala]

@bhavith , thanks again for the detailed information. Sorry for late response - I was busy with other tasks.

Graphs show plenty of spare CPU time and RAM. Could you compare response times for the following queries executed on VictoriaMetrics and Prometheus?

1) avg(rate(container_cpu_usage_seconds_total{pod=~"(api-.*)|(api.*)",pod!~"api-auth-.*”,app=~”app-01”}[1m]))
2) avg(rate(container_cpu_usage_seconds_total{pod=~"api.*",app=~”app-01”}[1m]))
3) avg(rate(container_cpu_usage_seconds_total{app=~”app-01”}[1m]))
4) max(kube_pod_container_resource_limits_cpu_cores{pod=~"(api-.*)|(api.*)",pod!~"api-auth-.*”,app=~”app-01”})
5) max(kube_pod_container_resource_limits_cpu_cores{pod=~"(api-.*)|(api.*)",app=~”app-01”})
6) max(kube_pod_container_resource_limits_cpu_cores{app=~”app-01”})
7) max(kube_pod_container_resource_limits_cpu_cores)

I suspect that VictoriaMetrics could hit non-optimal path on certain label filters. Queries above could point to the slow path, so it can be fixed.

If all the queries above will remain slow on VictoriaMetrics comparing to Prometheus, then could you temporarily migrate vmstorage and vminsert to GCP instances with more vCPUs and verify whether this improves response times?

[bhavith]

Thanks @valyala
Will check and let you know the outcome.

[bhavith]

Hi @valyala All the queries are taking 4-5 seconds on Victoriemetrics. Same queries took only a few milliseconds while queried on Prometheus. I will discuss with the team about migrating VictoriaMetrics to GCP and get back to you.
(Sorry, took me a while to respond. was stuck with something else.)

[valyala]

Try building VictoriaMetrics from the latest commit at cluster branch according to these instructions. It contains certain performance improvements for queries over database with big number of unique time series. Could you upgrade all the cluster components to this build and verify query performance after a hour of warm-up?

[bhavith]

sure...i will try this. thanks!

[bhavith]

after deploying the new build, the vmstorage is highly unstable and its going OOM.

Error : panic: FATAL: cannot write 8635 bytes: write /storage/data/big/2019_09/tmp/15C715F869175308/values.bin: cannot allocate memory goroutine 28 [running]: github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.logMessage(0xa71944, 0x5, 0xc0f97a8280, 0x77, 0x3) github.com/VictoriaMetrics/VictoriaMetrics@/lib/logger/logger.go:124 +0x586 github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.logLevel(0xa71944, 0x5, 0xa82300, 0x20, 0xc0bf9b36e8, 0x2, 0x2) github.com/VictoriaMetrics/VictoriaMetrics@/lib/logger/logger.go:78 +0x112 github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.Panicf(...) github.com/VictoriaMetrics/VictoriaMetrics@/lib/logger/logger.go:62 github.com/VictoriaMetrics/VictoriaMetrics/lib/fs.MustWriteData(0x7f34dc3f4170, 0xc0c4d6c810, 0xc11af7a000, 0x21bb, 0x3000) github.com/VictoriaMetrics/VictoriaMetrics@/lib/fs/fs.go:326 +0x209 github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.(blockStreamWriter).WriteExternalBlock(0xc13cc6cd80, 0xc023076540, 0xc0bf9b3ae0, 0xc0000dc130) github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/block_stream_writer.go:171 +0x263 github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.mergeBlockStreamsInternal(0xc0bf9b3ae0, 0xc13cc6cd80, 0xc1f9199f80, 0xc00232cfc0, 0xc0000dc130, 0xc0095821e0, 0xc0000dc140, 0x0, 0x0) github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/merge.go:127 +0x10c2 github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.mergeBlockStreams(0xc0bf9b3ae0, 0xc13cc6cd80, 0xc02302f080, 0x3, 0x3, 0xc00232cfc0, 0xc0000dc130, 0xc0095821e0, 0xc0000dc140, 0x10, ...) github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/merge.go:22 +0x114 github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.(partition).mergeParts(0xc0000dc000, 0xc02302f060, 0x3, 0x4, 0xc00232cfc0, 0x0, 0x0) github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/partition.go:978 +0x75a github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.(partition).mergeBigParts(0xc0000dc000, 0xe3ea3bea01, 0x956bbe3b442, 0xc009568b48) github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/partition.go:874 +0x12f github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.(partition).partsMerger(0xc0000dc000, 0xc0bf9b3f78, 0x0, 0xc0001557a8) github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/partition.go:779 +0x8c github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.(partition).bigPartsMerger(0xc0000dc000) github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/partition.go:757 +0x55 github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.(partition).startMergeWorkers.func2(0xc0000dc000) github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/partition.go:750 +0x2b created by github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.(*partition).startMergeWorkers github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/partition.go:749 +0xc8

[valyala]

This looks like memory leak :(

Could you stop vmstorage pods, drop -storageDataPath directory on all of these pods and upgrade all the cluster components to Docker image tag v1.28.0-cluster-beta1?

[bhavith]

done...looks better than before. But, yeah it has only data from a shorter time now. will see how it is doing.

[valyala]

There was data corruption bug in v1.28.0-cluster-beta1 and beta2, which result in decoded data block contains unsorted items error. Could you drop all the data and upgrade to v1.28.0-cluster-beta3 with fixed bug?

[bhavith]

done...will monitor the performance.

[bhavith]

hi @valyala As the volume of data grows, the query is getting slower. i am using the latest beta version.

[valyala]

@bhavith , thanks for the update.

Query latency depends on time series churn rate and time range used in the query. Bigger churn rate and bigger time range result in slower queries, since they need to scan more time series.

A few questions:

1) Could you provide query latency numbers for both Prometheus and VictoriaMetrics for different time ranges you use the most? Please mention these time ranges.
2) How do query latency numbers compare for the latest beta (v1.28.0-beta5) and the latest stable release (v1.27.3)?
3) Could you provide memory usage numbers between v1.27.3 and v1.28.0-beta5? You can use process_resident_memory_bytes metric exported by VictoriaMetrics.

[valyala]

@bhavith , try upgrading to v1.28.0 and see how it is going.

[bhavith]

@valyala Deployed v1.28.0-cluster. We are running a few checks. Will let you know the details.

[bhavith]

hi @valyala i was just comparing the response time for a part of the query. it seems even kube_pod_container_resource_limits_cpu_cores is slower in victoriametrics compared to Prometheus. Prometheus takes less than a second to give the data, wherein victoriametrics is taking around 10 seconds. Similar results for container_cpu_usage_seconds_total.

[valyala]

Thanks for the update, @bhavith !

Could you provide details for the following questions:

1. Do you run VictoriaMetrics v1.28.0 ?
2. Could you provide hardware configuration (the number of CPUs, RAM size, storage type and size) for both Prometheus and VictoriaMetrics? Could you provide cluster topology (the number of vminsert, vmselect and vmstorage nodes) and network bandwidth between cluster components?
3. How many Prometheus instances write data to VictoriaMetrics?
4. Which time range is used for the query?
5. Could you provide a graph for vm_rows{type="indexdb"} metric during the last 2 days?
6. Which retention is configured in Prometheus and in VictoriaMetrics?

[bhavith]

1. Yes, we run v1.28.0
2. vmsinert - 4 pods (each pod has 4 cpu, 6 Gi)
   vmstorage - 2 pods (each pod has 3 cpu, 20Gi, 500 GB standard disk)
   vmselect - 2 pods (each pod has 1cpu, 10Gi)
   prometheus - 2 pods (each pod has 13cpu, 75 Gi, 1.5 TB disk ) (Usage per pod: 3 cpu, 30Gi, 500 GB )
   All pods are running in the same kubernetes cluster. The communication between the pods is between high bandwidth google network.
3. 2 prometheus instances write data to VM, with unique label
4. 15 minutes
5. 
   
6. Retention Period:
   Prometheus: 30 days
   VM: 6 months

[valyala]

Could you temporarily increase the number of CPU cores on vmselect pods from 1cpu to 4cpus and see whether the query times change?

[bhavith]

Increased the cpu for vmselect. I dont see any difference.

[valyala]

@bhavith , could you collect CPU profile from vmstorage pod according to these instructions and attach it here? The profile must be collected from port 8482 on vmstorage pod.

[valyala]

@bhavith , try v1.28.1 - it contains performance improvement according to the provided CPU profiles.

[bhavith]

@valyala its still taking time to return the data. I dont see much improvement. Do you want me to generate profile and share it once again?

[valyala]

Do you want me to generate profile and share it once again?

Yes, after upgrading to v1.28.2 and running it for a few hours, since v1.28.1 had a panic on select path.

[valyala]

@bhavith , could you upgrade to v1.29.0 and try running slow queries multiple times in a day after the upgrade? This release of VictoriaMetrics creates per-day inverted index for newly written data. This speeds up queries over time ranges with start times greater than the upgrade day.

[bhavith]

@valyala done!!! Will let you know the result.

[bhavith]

We have an issue with the new version. vmstorage failed to turn healthy and I had to revert to the previous version. I will try again later to move to 1.29.0

[valyala]

@bhavith , could you provide vmstorage error logs for v1.29.0?

[bhavith]

There are no errors logged in the container. Just that the readiness probe is failing. Has there been any changes in the parameters or environment variables as a part of the new release?

[valyala]

Has there been any changes in the parameters or environment variables as a part of the new release?

No. Probably there were issues with downloading Docker image for v1.29.0 during the upgrade?
BTW, if you store VictoriaMetrics data on NFS-based persistent disks, then try v1.29.1, since v1.29.0 had a bug, which prevented from deleting old directories from NFS.

[bhavith]

Upgraded to 1.29.1. Still the healtcheck is failing. I could see a few errors in the log.

severity: "ERROR"  
 textPayload: "2019-11-13T08:42:02.791+0000 error   net/http/server.go:3053 http: panic serving 10.24.4.6:60996: runtime error: invalid memory address or nil pointer dereference
severity: "ERROR"  
 textPayload: "goroutine 67 [running]:
severity: "ERROR"  
 textPayload: "net/http.(*conn).serve.func1(0xc026f18000)
severity: "ERROR"  
 textPayload: " net/http/server.go:1767 +0x139
severity: "ERROR"  
 textPayload: "panic(0x9f02e0, 0xe4bd30)
severity: "ERROR"  
textPayload: "  runtime/panic.go:679 +0x1b2
severity: "ERROR"  
textPayload: "github.com/VictoriaMetrics/VictoriaMetrics/lib/workingsetcache.(*Cache).UpdateStats(0x0, 0xc00027f720)
severity: "ERROR"  
 textPayload: " github.com/VictoriaMetrics/VictoriaMetrics@/lib/workingsetcache/cache.go:224 +0x37
severity: "ERROR"  
 textPayload: "github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.(*indexDB).UpdateMetrics(0xc00e362f70, 0xc0e8472ea0)
severity: "ERROR"  
textPayload: "  github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/index_db.go:216 +0x9c
severity: "ERROR"  
 textPayload: "github.com/VictoriaMetrics/VictoriaMetrics/lib/storage.(*Storage).UpdateMetrics(0xc0001b0000, 0xc0e8472dc0)
severity: "ERROR"  
 textPayload: " github.com/VictoriaMetrics/VictoriaMetrics@/lib/storage/storage.go:386 +0x3cd
severity: "ERROR"  
 textPayload: "main.registerStorageMetrics.func1(0x0)
severity: "ERROR"  
 textPayload: " github.com/VictoriaMetrics/VictoriaMetrics@/app/vmstorage/main.go:186 +0xfb
severity: "ERROR"  
 textPayload: "main.registerStorageMetrics.func3(0xc07ca15300)
severity: "ERROR"  
 textPayload: " github.com/VictoriaMetrics/VictoriaMetrics@/app/vmstorage/main.go:196 +0x26
severity: "ERROR"  
textPayload: "main.registerStorageMetrics.func6(0x18)
severity: "ERROR"  
 textPayload: " github.com/VictoriaMetrics/VictoriaMetrics@/app/vmstorage/main.go:207 +0x26
severity: "ERROR"  
textPayload: "github.com/VictoriaMetrics/metrics.(*Gauge).marshalTo(0xc0001b62a8, 0xa8a2d0, 0x20, 0x7efc282bfc38, 0xc07ca15380)
severity: "ERROR"  
textPayload: "  github.com/VictoriaMetrics/[email protected]/gauge.go:38 +0x3f
severity: "ERROR"  
textPayload: "github.com/VictoriaMetrics/metrics.(*Set).WritePrometheus(0xc0000e4340, 0x7efc282bfc38, 0xc07ca15380)
severity: "ERROR"  
textPayload: "  github.com/VictoriaMetrics/VictoriaMetrics@/lib/httpserver/metrics.go:16 +0x44
severity: "ERROR"  
textPayload: "github.com/VictoriaMetrics/VictoriaMetrics/lib/httpserver.handlerWrapper(0xb34c40, 0xc07ca15380, 0xc000322b00, 0xc00006d4c0)
severity: "ERROR"  
textPayload: "  github.com/VictoriaMetrics/VictoriaMetrics@/lib/httpserver/httpserver.go:140 +0x416
severity: "ERROR"  
textPayload: "github.com/VictoriaMetrics/VictoriaMetrics/lib/httpserver.gzipHandler.func1(0xb34c40, 0xc07ca15380, 0xc000322b00)
severity: "ERROR"  
textPayload: "  github.com/VictoriaMetrics/VictoriaMetrics@/lib/httpserver/httpserver.go:117 +0x88
severity: "ERROR"  
textPayload: "net/http.HandlerFunc.ServeHTTP(0xc000182f10, 0xb35140, 0xc0003602a0, 0xc000322b00)
severity: "ERROR"  
textPayload: "  net/http/server.go:2007 +0x44
severity: "ERROR"  
textPayload: "net/http.serverHandler.ServeHTTP(0xc01b044000, 0xb35140, 0xc0003602a0, 0xc000322b00)
severity: "ERROR"  
textPayload: "  net/http/server.go:2802 +0xa4
severity: "ERROR"  
textPayload: "net/http.(*conn).serve(0xc026f18000, 0xb36940, 0xc0000e4180)
severity: "ERROR"  
textPayload: "  net/http/server.go:1890 +0x875
severity: "ERROR"  
textPayload: "created by net/http.(*Server).Serve
severity: "ERROR"  
textPayload: "  net/http/server.go:2927 +0x38e
severity: "ERROR"  
textPayload: "2019-11-13T08:42:03.521+0000  info    VictoriaMetrics@/lib/storage/storage.go:640 saved MetricName->TSID cache to "/storage/cache/metricName_tsid" in 764.291067ms; entriesCount: 3189826; sizeBytes: 1780547584
severity: "ERROR" 
textPayload: "2019-11-13T08:42:03.521+0000  info    VictoriaMetrics@/lib/storage/storage.go:632 saving MetricID->TSID cache to "/storage/cache/metricID_tsid"...

[valyala]

We detected memory leak in v1.29.1 in the inverted index for recent hour. So new release has been published with the corresponding fix. Could you try v1.29.2?

[bhavith]

@valyala the performance for querying the data loaded after the upgrade is quite better now. (Still slower than prometheus though)

[valyala]

@bhavith , this is great news!

Could you post graphs and timings for the following query on Prometheus and VictoriaMetrics v1.29.4 - count(kube_pod_container_resource_limits_cpu_cores) - on the last 24 hours time range?

[bhavith]

Prometheus - 12 seconds

VictoriaMetrics - 1 min 27 seconds

[valyala]

Thanks!

Could you re-run this query multiple times with a few minutes interval between runs and measure the response times for both Prometheus and VictoriaMetrics? Also could you collect cpu and memory profiles from VictoriaMetrics when executing this query according to these docs and send them to [email protected] ?

Some observations:
1) According to graphs VictoriaMetrics contains 2x more time series than Prometheus - see numbers on the left side of graphs. Probably, multiple Prometheus instances push data into VictoriaMetrics?
2) The number of kube_pod_container_resource_limits_cpu_cores time series is very volatile. This suggests that k8s containers are very frequently re-created.This can lead to high churn rate for these series.

Could you attach graph for the following query for VictoriaMetrics in order to determine the total number of time series with kube_pod_container_resource_limits_cpu_cores name over the last 24h time range?

count(kube_pod_container_resource_limits_cpu_cores default 0)

This query won't work in Prometheus, since it uses default extension from extended PromQL. If this query won't complete for 24 hours time range, then try it for the last 3 hours time range.

[bhavith]

Hi @valyala

Thanks for sharing the analysis. I am on leave for a few days. I will share the info once I am back.

Yes, you are correct about two prometheus instances pushing data to Victoriametrics.

Regards
Bhavith

[bhavith]

hi @valyala
Please find below the graph for the query count(kube_pod_container_resource_limits_cpu_cores default 0)

I will get you the rest of the information soon.

[valyala]

@bhavith , could you upgrade to v1.30.4 and re-run slow queries? This release contains performance improvement according to the last CPU profiles obtained from you.

[bhavith]

@valyala The performance has considerably improved after deploying the new version. We are checking a few other details. Will let you know. Please let me know if you want profiles for further improvements.

[valyala]

Great news! I propose closing this issue, since it became too long, and re-opening new one if you'll encounter slow queries in VictoriaMetrics.