Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1917009

Summary:

Prometheus reporting samples with timestamps arriving out of order

Product:

OpenShift Container Platform

Reporter:

Sam Yangsao <syangsao>

Component:

Monitoring

Assignee:

Damien Grisonnet <dgrisonn>

Status:

CLOSED DEFERRED

QA Contact:

Junqi Zhao <juzhao>

Severity:

medium

Docs Contact:

Priority:

medium

Version:

4.6.z

CC:

alegrand, anpicker, aos-bugs, erooth, kakkoyun, lcosic, pkrupa, surbania

Target Milestone:

---

Target Release:

---

Hardware:

x86_64

OS:

Linux

Whiteboard:

Fixed In Version:

Doc Type:

If docs needed, set a value

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2021-02-11 14:57:50 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
error of issue	none

Description Sam Yangsao 2021-01-16 14:09:15 UTC

Created attachment 1748094 [details]
error of issue

Description of problem:

Prometheus openshift-monitoring/prometheus-k8s-1 is dropping 207.2 samples/s with timestamps arriving out of order.

Version-Release number of selected component (if applicable):

OCP 4.6.9 fresh installation

How reproducible:

Unsure

Steps to Reproduce:
1.
2.
3.

Actual results:

Seeing this error from both prometheus-k8s pods and reported to the overview page - not clearing itself out.

Expected results:

Additional info:

screen shot attached

Comment 1 Sam Yangsao 2021-01-16 14:15:13 UTC

Seeing this on 2 builds of OCP 4.6.9

devocp4 - upgraded from OCP 4.5.z
ocp4 - new installation of OCP 4.6.9

must-gathers will be attached

Comment 3 Sam Yangsao 2021-01-16 14:46:05 UTC

Error from Prometheus logs:

[...]
2021-01-16T14:33:44.716861097Z level=warn ts=2021-01-16T14:33:44.716Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-monitoring/node-exporter/0 target=https://10.15.108.84:9100/metrics msg="Error on ingesting out-of-order samples" num_dropped=3008
2021-01-16T14:33:45.133554035Z level=warn ts=2021-01-16T14:33:45.133Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-multus/monitor-network/0 target=https://10.129.2.3:8443/metrics msg="Error on ingesting out-of-order samples" num_dropped=14
2021-01-16T14:33:49.595216421Z level=warn ts=2021-01-16T14:33:49.595Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-multus/monitor-network/0 target=https://10.131.0.2:8443/metrics msg="Error on ingesting out-of-order samples" num_dropped=15
2021-01-16T14:33:53.160282423Z level=warn ts=2021-01-16T14:33:53.154Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-monitoring/node-exporter/0 target=https://10.15.108.88:9100/metrics msg="Error on ingesting out-of-order samples" num_dropped=1703
2021-01-16T14:34:00.816969023Z level=warn ts=2021-01-16T14:34:00.816Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-monitoring/node-exporter/0 target=https://10.15.108.89:9100/metrics msg="Error on ingesting out-of-order samples" num_dropped=1121
2021-01-16T14:34:18.825051026Z level=warn ts=2021-01-16T14:34:18.824Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-multus/monitor-network/0 target=https://10.130.2.2:8443/metrics msg="Error on ingesting out-of-order samples" num_dropped=17
2021-01-16T14:34:19.581206480Z level=warn ts=2021-01-16T14:34:19.581Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-multus/monitor-network/0 target=https://10.131.0.2:8443/metrics msg="Error on ingesting out-of-order samples" num_dropped=15
2021-01-16T14:34:20.209902545Z level=warn ts=2021-01-16T14:34:20.209Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-multus/monitor-network/0 target=https://10.129.0.25:8443/metrics msg="Error on ingesting out-of-order samples" num_dropped=69
2021-01-16T14:34:28.824324382Z level=warn ts=2021-01-16T14:34:28.824Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-multus/monitor-network/0 target=https://10.130.2.2:8443/metrics msg="Error on ingesting out-of-order samples" num_dropped=17
2021-01-16T14:34:29.587323477Z level=warn ts=2021-01-16T14:34:29.587Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-multus/monitor-network/0 target=https://10.131.0.2:8443/metrics msg="Error on ingesting out-of-order samples" num_dropped=15
2021-01-16T14:34:30.217442475Z level=warn ts=2021-01-16T14:34:30.217Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-multus/monitor-network/0 target=https://10.129.0.25:8443/metrics msg="Error on ingesting out-of-order samples" num_dropped=69
2021-01-16T14:35:08.220980382Z level=warn ts=2021-01-16T14:35:08.220Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-monitoring/node-exporter/0 target=https://10.15.108.88:9100/metrics msg="Error on ingesting out-of-order samples" num_dropped=1703
2021-01-16T14:35:10.253734776Z level=warn ts=2021-01-16T14:35:10.251Z caller=scrape.go:1372 component="scrape manager" scrape_pool=openshift-multus/monitor-network/0 target=https://10.129.0.25:8443/metrics msg="Error on ingesting out-of-order samples" num_dropped=69

Comment 7 Damien Grisonnet 2021-02-11 14:46:40 UTC

After looking at the must-gather it might be caused by a time related issue with the machine running Prometheus. The network-metrics deamonsets scraped via the `openshift-multus/monitor-network` target aren't showing any logs that would induce such issue. On the other hand, node-exporter logs are showing an error that could result in samples being out-of-order but it's very rarely happening compared to how much we see it in Prometheus.

Errors from node-exporter-nr4tz:
```
2021-01-07T12:09:12.021371753Z level=warn ts=2021-01-07T12:09:12.020Z caller=cpu_linux.go:247 collector=cpu msg="CPU Idle counter jumped backwards, possible hotplug event, resetting CPU stats" cpu=0 old_value=885044.1 new_value=885044.09
2021-01-07T12:09:12.021564275Z level=warn ts=2021-01-07T12:09:12.021Z caller=cpu_linux.go:267 collector=cpu msg="CPU System counter jumped backwards" cpu=1 old_value=92946.49 new_value=92946.48
2021-01-07T12:09:12.021655307Z level=warn ts=2021-01-07T12:09:12.021Z caller=cpu_linux.go:267 collector=cpu msg="CPU System counter jumped backwards" cpu=2 old_value=92655.46 new_value=92655.45
2021-01-07T12:09:12.021718513Z level=warn ts=2021-01-07T12:09:12.021Z caller=cpu_linux.go:247 collector=cpu msg="CPU Idle counter jumped backwards, possible hotplug event, resetting CPU stats" cpu=3 old_value=874116.6 new_value=874116.59
2021-01-08T10:31:00.311591313Z level=warn ts=2021-01-08T10:31:00.293Z caller=cpu_linux.go:247 collector=cpu msg="CPU Idle counter jumped backwards, possible hotplug event, resetting CPU stats" cpu=0 old_value=944037.11 new_value=944037.1
2021-01-08T10:31:00.311591313Z level=warn ts=2021-01-08T10:31:00.293Z caller=cpu_linux.go:255 collector=cpu msg="CPU User counter jumped backwards" cpu=1 old_value=147959.87 new_value=147959.86
2021-01-08T10:31:00.311591313Z level=warn ts=2021-01-08T10:31:00.293Z caller=cpu_linux.go:267 collector=cpu msg="CPU System counter jumped backwards" cpu=1 old_value=99600.22 new_value=99600.21
2021-01-08T10:31:00.311591313Z level=warn ts=2021-01-08T10:31:00.293Z caller=cpu_linux.go:255 collector=cpu msg="CPU User counter jumped backwards" cpu=2 old_value=147504.75 new_value=147504.74
2021-01-08T10:31:00.311591313Z level=warn ts=2021-01-08T10:31:00.293Z caller=cpu_linux.go:267 collector=cpu msg="CPU System counter jumped backwards" cpu=2 old_value=99301.19 new_value=99301.18
2021-01-08T10:31:00.311591313Z level=warn ts=2021-01-08T10:31:00.293Z caller=cpu_linux.go:255 collector=cpu msg="CPU User counter jumped backwards" cpu=3 old_value=148326.25 new_value=148326.24
2021-01-08T10:31:00.311591313Z level=warn ts=2021-01-08T10:31:00.293Z caller=cpu_linux.go:285 collector=cpu msg="CPU SoftIRQ counter jumped backwards" cpu=3 old_value=15692.51 new_value=15692.5
```
Considering that the values are barely different, there might be a very little time drift causing these errors.

Also, it might be worth noting that these errors also appears in the dev cluster's node-exporter instances but we there aren't any ingestion errors for node-exporter in the Prometheus logs.

As a next step, could you perhaps follow this blogpost [1] that explains how to debug out-of-order samples errors and come back to me with the results? This would help in the investigation.

[1] https://www.robustperception.io/debugging-out-of-order-samples

Comment 8 Sam Yangsao 2021-02-11 14:57:50 UTC

The errors are now gone, not sure why or how.  I'll go ahead and reopen if these occur again and will try the suggestion from comment#7.  Thanks!