Gaps in recording rules series, but data is available when querying the rule expression

[dannyk81]

Bug Report

What did you do?

Defined a Recording Rule:

record: namespace_node_pod:container_cpu_usage_seconds_total:sum_rate2m
expr: sum
  by(job, namespace, kubernetes_io_hostname, pod_name) (rate(container_cpu_system_seconds_total{image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m])
  + rate(container_cpu_user_seconds_total{image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m]))

What did you expect to see?

Expected to see continuous graphs from the recording rule, in the same way as I see when querying the underlying expression directly.

What did you see instead? Under which circumstances?

Instead I see mostly gaps with no data on some series of the recording rule (I did find that all the gaps are for series of a specific kubernetes_io_hostname) but when querying the record expression above for the same data I get the results and there are no gaps.

1. Result from querying the recording rule
   Query:

namespace_node_pod:container_cpu_usage_seconds_total:sum_rate2m{pod_name="mcrouter-856429244-zkcl2"}

2. Result from querying the recording rule expression directly (using same pod_name label selection)
   Query:

sum
  by(job, namespace, kubernetes_io_hostname, pod_name) (rate(container_cpu_system_seconds_total{image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$",pod_name="mcrouter-856429244-zkcl2"}[2m])
  + rate(container_cpu_user_seconds_total{image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$",pod_name="mcrouter-856429244-zkcl2"}[2m]))

Environment

• System information:

  Linux 4.14.32-coreos x86_64

• Prometheus version:

	prometheus, version 2.2.1 (branch: HEAD, revision: 		bc6058c81272a8d938c05e75607371284236aadc)
  		build user:       root@149e5b3f0829
  		build date:       20180314-14:15:45
  		go version:       go1.10

• Alertmanager version:

  N/A

• Prometheus configuration file:

I pasted below the kubernetes-nodes job configuration (as seen in the Prometheus UI), as this is where these metrics are coming from.

- job_name: kubernetes-nodes
  scrape_interval: 1m
  scrape_timeout: 10s
  metrics_path: /metrics
  scheme: https
  kubernetes_sd_configs:
  - api_server: null
    role: node
    namespaces:
      names: []
  bearer_token_file: /var/run/secrets/kubernetes.io/serviceaccount/token
  tls_config:
    ca_file: /var/run/secrets/kubernetes.io/serviceaccount/ca.crt
    insecure_skip_verify: true
  relabel_configs:
  - separator: ;
    regex: __meta_kubernetes_node_label_(.+)
    replacement: $1
    action: labelmap
  - source_labels: [__meta_kubernetes_node_name]
    separator: ;
    regex: (.+)
    target_label: instance
    replacement: ${1}
    action: replace
  metric_relabel_configs:
  - source_labels: [__name__]
    separator: ;
    regex: container_tasks_state|container_memory_failures_total|container_last_seen|container_fs_.*|container_spec_.*
    replacement: $1
    action: drop

• Alertmanager configuration file:

N/A

• Logs:

I reviewed the logs we have from Prometheus over the last few days and there was nothing except the occasional WAL truncation completed, head GC completed and compact blocks msgs, like so:

June 6th 2018, 11:00:43.080 | level=info ts=2018-06-06T15:00:43.080034702Z caller=head.go:357 component=tsdb msg="WAL truncation completed" duration=4.93668698s

June 6th 2018, 11:00:38.143 | level=info ts=2018-06-06T15:00:38.143190144Z caller=head.go:348 component=tsdb msg="head GC completed" duration=1.796350616s

June 6th 2018, 11:00:00.127 | level=info ts=2018-06-06T15:00:00.127434106Z caller=compact.go:393 component=tsdb msg="compact blocks" count=1 mint=1528286400000 maxt=1528293600000

[dannyk81]

Just wanted to add few more details:

1. Prometheus runs in K8s cluster
2. It uses a temporal storage (emptyDir)
3. retention is set to 12 hours, as we federate the series generated by the recording rules to an external Prometheus where we keep the metrics longer

[brian-brazil]

Can you share the raw time series data backing this and the full Prometheus configuration and rule group please?
What happens when you run the actual query, rather than the modified version?

[brian-brazil]

Ah wait, I see what it is now. You're using a 2m rate on data with a 1m scrape interval. That's going to be flaky, you need at least a 4m rate in those circumstances.

[dannyk81]

Hi @brian-brazil! thanks for the quick response.

In the issue post, I'm showing the graph of the recording rule and the actual expression I use in that recording rule.

As you can see there, the recording rule is mostly gaps however the actual expression shows a nice and continuous graph with no gaps.

That's a good point about the [2m] rate interval, indeed we will increase it to get things more accurate (considering the 1m scrape interval), but this still doesn't explain why the underlying recording rule expression shows a nice graph but the recording rule doesn't.

Also, as I mentioned, this doesn't happen on all series generated by this recording rule.

Here's the extra details you requested.

Raw time series data: I'm not sure exactly what I should provide here and how, could you guide me please?

Rule group:

groups:
- name: k8s-cadvisor-cpu.rules
  rules:
  - record: namespace:container_cpu_usage_seconds_total:sum_rate2m
    expr: sum(rate(container_cpu_system_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m])
      + rate(container_cpu_user_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m]))
      BY (job, namespace)
  - record: namespace_node_pod:container_cpu_usage_seconds_total:sum_rate2m
    expr: sum(rate(container_cpu_system_seconds_total{image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m])
      + rate(container_cpu_user_seconds_total{image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m]))
      BY (job, namespace, kubernetes_io_hostname, pod_name)
  - record: namespace_node_role_pod:container_cpu_usage_seconds_total:sum_rate2m
    expr: sum(rate(container_cpu_system_seconds_total{image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m])
      + rate(container_cpu_user_seconds_total{image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m]))
      BY (job, namespace, kubernetes_io_hostname, role, pod_name)
  - record: namespace_node_container:container_cpu_usage_seconds_total:sum_rate2m
    expr: sum(rate(container_cpu_system_seconds_total{container_name!="POD",image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m])
      + rate(container_cpu_user_seconds_total{container_name!="POD",image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m]))
      BY (job, namespace, kubernetes_io_hostname, container_name)
  - record: namespace_node_role_container:container_cpu_usage_seconds_total:sum_rate2m
    expr: sum(rate(container_cpu_system_seconds_total{container_name!="POD",image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m])
      + rate(container_cpu_user_seconds_total{container_name!="POD",image!="",job="kubernetes-nodes",name=~"^(?:^k8s_.*)$"}[2m]))
      BY (job, namespace, kubernetes_io_hostname, role, container_name)
  - record: namespace_app:container_cpu_usage_seconds_total:sum_rate2m
    expr: sum(sum(rate(container_cpu_system_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m])
      + rate(container_cpu_user_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m]))
      BY (job, namespace, pod_name) * ON(pod_name) GROUP_LEFT(label_app) label_replace(kube_pod_labels{label_app!=""},
      "pod_name", "$1", "pod", "(.*)")) BY (job, namespace, label_app)
  - record: namespace_app_pod:container_cpu_usage_seconds_total:sum_rate2m
    expr: sum(sum(rate(container_cpu_system_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m])
      + rate(container_cpu_user_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m]))
      BY (job, namespace, pod_name) * ON(pod_name) GROUP_LEFT(label_app) label_replace(kube_pod_labels{label_app!=""},
      "pod_name", "$1", "pod", "(.*)")) BY (job, namespace, label_app, pod_name)
  - record: namespace_k8s_app:container_cpu_usage_seconds_total:sum_rate2m
    expr: sum(sum(rate(container_cpu_system_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m])
      + rate(container_cpu_user_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m]))
      BY (job, namespace, pod_name) * ON(pod_name) GROUP_LEFT(label_k8s_app) label_replace(kube_pod_labels{label_k8s_app!=""},
      "pod_name", "$1", "pod", "(.*)")) BY (job, namespace, label_k8s_app)
  - record: namespace_k8s_app_pod:container_cpu_usage_seconds_total:sum_rate2m
    expr: sum(sum(rate(container_cpu_system_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m])
      + rate(container_cpu_user_seconds_total{image!="",job="kubernetes-nodes",namespace!=""}[2m]))
      BY (job, namespace, pod_name) * ON(pod_name) GROUP_LEFT(label_k8s_app) label_replace(kube_pod_labels{label_k8s_app!=""},
      "pod_name", "$1", "pod", "(.*)")) BY (job, namespace, label_k8s_app, pod_name)

Full configuration:

global:
  scrape_interval: 1m
  scrape_timeout: 10s
  evaluation_interval: 1m
  external_labels:
    cluster: <cluster-foo>
    datacenter: <datacenter-bar>
    env: prd
rule_files:
- /etc/prometheus/rules/*.rules.yml
scrape_configs:
- job_name: kubernetes-apiservers
  scrape_interval: 1m
  scrape_timeout: 10s
  metrics_path: /metrics
  scheme: https
  kubernetes_sd_configs:
  - api_server: null
    role: endpoints
    namespaces:
      names: []
  bearer_token_file: /var/run/secrets/kubernetes.io/serviceaccount/token
  tls_config:
    ca_file: /var/run/secrets/kubernetes.io/serviceaccount/ca.crt
    insecure_skip_verify: true
  relabel_configs:
  - source_labels: [__meta_kubernetes_namespace, __meta_kubernetes_service_name, __meta_kubernetes_endpoint_port_name]
    separator: ;
    regex: default;kubernetes;https
    replacement: $1
    action: keep
- job_name: kubernetes-etcd
  scrape_interval: 1m
  scrape_timeout: 10s
  metrics_path: /metrics
  scheme: https
  kubernetes_sd_configs:
  - api_server: null
    role: node
    namespaces:
      names: []
  bearer_token_file: /var/run/secrets/kubernetes.io/serviceaccount/token
  tls_config:
    ca_file: /var/run/secrets/kubernetes.io/serviceaccount/ca.crt
    insecure_skip_verify: true
  relabel_configs:
  - source_labels: [__meta_kubernetes_node_label_role]
    separator: ;
    regex: master
    replacement: $1
    action: keep
  - source_labels: [__scheme__]
    separator: ;
    regex: (.*)
    target_label: __scheme__
    replacement: http
    action: replace
  - source_labels: [__address__]
    separator: ;
    regex: (.+):10250
    target_label: __address__
    replacement: ${1}:2379
    action: replace
  - source_labels: [__meta_kubernetes_node_name]
    separator: ;
    regex: (.+)
    target_label: instance
    replacement: ${1}
    action: replace
- job_name: kubernetes-controller-manager
  scrape_interval: 1m
  scrape_timeout: 10s
  metrics_path: /metrics
  scheme: https
  kubernetes_sd_configs:
  - api_server: null
    role: node
    namespaces:
      names: []
  bearer_token_file: /var/run/secrets/kubernetes.io/serviceaccount/token
  tls_config:
    ca_file: /var/run/secrets/kubernetes.io/serviceaccount/ca.crt
    insecure_skip_verify: true
  relabel_configs:
  - source_labels: [__meta_kubernetes_node_label_role]
    separator: ;
    regex: master
    replacement: $1
    action: keep
  - source_labels: [__scheme__]
    separator: ;
    regex: (.*)
    target_label: __scheme__
    replacement: http
    action: replace
  - source_labels: [__address__]
    separator: ;
    regex: (.+):10250
    target_label: __address__
    replacement: ${1}:10252
    action: replace
  - source_labels: [__meta_kubernetes_node_name]
    separator: ;
    regex: (.+)
    target_label: instance
    replacement: ${1}
    action: replace
- job_name: kubernetes-scheduler
  scrape_interval: 1m
  scrape_timeout: 10s
  metrics_path: /metrics
  scheme: https
  kubernetes_sd_configs:
  - api_server: null
    role: node
    namespaces:
      names: []
  bearer_token_file: /var/run/secrets/kubernetes.io/serviceaccount/token
  tls_config:
    ca_file: /var/run/secrets/kubernetes.io/serviceaccount/ca.crt
    insecure_skip_verify: true
  relabel_configs:
  - source_labels: [__meta_kubernetes_node_label_role]
    separator: ;
    regex: master
    replacement: $1
    action: keep
  - source_labels: [__scheme__]
    separator: ;
    regex: (.*)
    target_label: __scheme__
    replacement: http
    action: replace
  - source_labels: [__address__]
    separator: ;
    regex: (.+):10250
    target_label: __address__
    replacement: ${1}:10251
    action: replace
  - source_labels: [__meta_kubernetes_node_name]
    separator: ;
    regex: (.+)
    target_label: instance
    replacement: ${1}
    action: replace
- job_name: kubernetes-nodes
  scrape_interval: 1m
  scrape_timeout: 10s
  metrics_path: /metrics
  scheme: https
  kubernetes_sd_configs:
  - api_server: null
    role: node
    namespaces:
      names: []
  bearer_token_file: /var/run/secrets/kubernetes.io/serviceaccount/token
  tls_config:
    ca_file: /var/run/secrets/kubernetes.io/serviceaccount/ca.crt
    insecure_skip_verify: true
  relabel_configs:
  - separator: ;
    regex: __meta_kubernetes_node_label_(.+)
    replacement: $1
    action: labelmap
  - source_labels: [__meta_kubernetes_node_name]
    separator: ;
    regex: (.+)
    target_label: instance
    replacement: ${1}
    action: replace
  metric_relabel_configs:
  - source_labels: [__name__]
    separator: ;
    regex: container_tasks_state|container_memory_failures_total|container_last_seen|container_fs_.*|container_spec_.*
    replacement: $1
    action: drop
- job_name: kubernetes-service-endpoints
  scrape_interval: 1m
  scrape_timeout: 10s
  metrics_path: /metrics
  scheme: http
  kubernetes_sd_configs:
  - api_server: null
    role: endpoints
    namespaces:
      names: []
  relabel_configs:
  - source_labels: [__meta_kubernetes_service_annotation_prometheus_io_scrape]
    separator: ;
    regex: "true"
    replacement: $1
    action: keep
  - source_labels: [__meta_kubernetes_service_annotation_prometheus_io_scheme]
    separator: ;
    regex: (https?)
    target_label: __scheme__
    replacement: $1
    action: replace
  - source_labels: [__meta_kubernetes_service_annotation_prometheus_io_path]
    separator: ;
    regex: (.+)
    target_label: __metrics_path__
    replacement: $1
    action: replace
  - source_labels: [__address__, __meta_kubernetes_service_annotation_prometheus_io_port]
    separator: ;
    regex: (.+)(?::\d+);(\d+)
    target_label: __address__
    replacement: $1:$2
    action: replace
  - separator: ;
    regex: __meta_kubernetes_service_label_(.+)
    replacement: $1
    action: labelmap
  - source_labels: [__meta_kubernetes_namespace]
    separator: ;
    regex: (.*)
    target_label: kubernetes_namespace
    replacement: $1
    action: replace
  - source_labels: [__meta_kubernetes_service_name]
    separator: ;
    regex: (.*)
    target_label: kubernetes_name
    replacement: $1
    action: replace
- job_name: kubernetes-services
  params:
    module:
    - http_2xx
  scrape_interval: 1m
  scrape_timeout: 10s
  metrics_path: /probe
  scheme: http
  kubernetes_sd_configs:
  - api_server: null
    role: service
    namespaces:
      names: []
  relabel_configs:
  - source_labels: [__meta_kubernetes_service_annotation_prometheus_io_probe]
    separator: ;
    regex: "true"
    replacement: $1
    action: keep
  - source_labels: [__address__]
    separator: ;
    regex: (.*)
    target_label: __param_target
    replacement: $1
    action: replace
  - separator: ;
    regex: (.*)
    target_label: __address__
    replacement: blackbox
    action: replace
  - source_labels: [__param_target]
    separator: ;
    regex: (.*)
    target_label: instance
    replacement: $1
    action: replace
  - separator: ;
    regex: __meta_kubernetes_service_label_(.+)
    replacement: $1
    action: labelmap
  - source_labels: [__meta_kubernetes_namespace]
    separator: ;
    regex: (.*)
    target_label: kubernetes_namespace
    replacement: $1
    action: replace
  - source_labels: [__meta_kubernetes_service_name]
    separator: ;
    regex: (.*)
    target_label: kubernetes_name
    replacement: $1
    action: replace
- job_name: kubernetes-pods
  scrape_interval: 1m
  scrape_timeout: 10s
  metrics_path: /metrics
  scheme: http
  kubernetes_sd_configs:
  - api_server: null
    role: pod
    namespaces:
      names: []
  relabel_configs:
  - source_labels: [__meta_kubernetes_pod_annotation_prometheus_io_scrape]
    separator: ;
    regex: "true"
    replacement: $1
    action: keep
  - source_labels: [__meta_kubernetes_pod_annotation_prometheus_io_path]
    separator: ;
    regex: (.+)
    target_label: __metrics_path__
    replacement: $1
    action: replace
  - source_labels: [__address__, __meta_kubernetes_pod_annotation_prometheus_io_port]
    separator: ;
    regex: (.+):(?:\d+);(\d+)
    target_label: __address__
    replacement: ${1}:${2}
    action: replace
  - separator: ;
    regex: __meta_kubernetes_pod_label_(.+)
    replacement: $1
    action: labelmap
  - source_labels: [__meta_kubernetes_namespace]
    separator: ;
    regex: (.*)
    target_label: kubernetes_namespace
    replacement: $1
    action: replace
  - source_labels: [__meta_kubernetes_pod_name]
    separator: ;
    regex: (.*)
    target_label: kubernetes_pod_name
    replacement: $1
    action: replace
  - source_labels: [__meta_kubernetes_pod_node_name]
    separator: ;
    regex: (.*)
    target_label: kubernetes_pod_node_name
    replacement: $1
    action: replace
  - source_labels: [kubernetes_pod_node_name]
    separator: ;
    regex: (.+)
    target_label: node
    replacement: ${1}
    action: replace

[brian-brazil]

As you can see there, the recording rule is mostly gaps however the actual expression shows a nice and continuous graph with no gaps.

They're being run at different times, so that's sufficient to explain the issue. If you refresh a few times you should see the issue.

[dannyk81]

I've been hitting the Execute in the Graph UI for a few hours now (using the record expression as the query) and I always see a nice graph with no gaps, while the recording rule is mostly gaps.

And this issue is limited to a specific set of labels in the record generated time-series, specifically on series with this label kubernetes_io_hostname="kubw-44", all the rest look perfect and are identical to the graph result when I run the record expression.

[brian-brazil]

It might be a slow host, but a 2m rate on 1m interval is going to have issues like this.

[dannyk81]

The rule seem to evaluate quite quickly, I see 127.8ms in the Rules UI, and we don't seem to have any issues with any other rule (cpu usage is fairly low, no memory pressure, queries execute quite fast, etc..)

Anyway, I'm going to modify the recording rules and set the interval to [4m]

Will update with the results.

[dannyk81]

After modifying the rate interval to [4m], the recording rule graph is correct.

Thanks for the analysis and support!

What struck me as strange is that I got consistent results from the record expression, but not from the record itself, but I guess we were hitting some corner case due to rate interval being too short.

Thanks again and cheers! 🍻

[alexf101]

I was having a similar issue and thought it must be a bug, but this makes sense to me now, thanks for the analysis.

What struck me as strange is that I got consistent results from the record expression, but not from the record itself, but I guess we were hitting some corner case due to rate interval being too short.

@dannyk81 My understanding is that the recording rule data will have been generated once shortly after the scrape and then cached forever, whereas the other query will be looking back over a history that has since become complete, which would explain this behaviour.