metric: periodic gaps in histogram metrics

[kvoli]

Describe the problem

When recording to a prometheus histogram every 10s, gaps in the dbconsole metric appear every HistogramOptions.Duration interval.

Screenshot taken with these histogram settings:

metric.HistogramOptions{
    Duration: 2 * histogramWindow, /* 120s */
    Buckets: metric.IOLatencyBuckets,
    Mode:    metric.HistogramModePrometheus,
}

To Reproduce

1. Build this commit 3515d1d
2. Run a workload e.g. ./cockroach workload run kv --read-percent=95 --drop --zipfian
3. Inspect output of rebalancing.replicas.cpunanospersecond

Jira issue: CRDB-25158

[aadityasondhi]

Ran some experiments. The problem seems to be that the replica stats are stored every 10s and we scrape for tsdb at a similar cadence (I think it is also every 10s). So when we scrape for the first time after every tick, we get an empty histogram that we are calculating percentiles out of. This was documented as a limitation of our current windowed design:

cockroach/pkg/util/metric/metric.go

Line 290 in f96b21f

// TODO(obs-inf): the way we implement windowed histograms is not great. If

.

Some solutions I can think of:

1. Store stats for twice the rotation duration so that we have a combined view of the cur + prev bucket. This way we avoid reporting 0 after a fresh tick (seems like a simple solution)
2. Synchronize ticks with tsdb scrapes so that we always scrape before a tick. (seems complex and could have side effects since our rotation duration is configurable).
3. Record windowed stats in tsdb of the previous bucket instead of the current. We trade off having the most recent data but will always have a complete view of the rotation duration.

I think 3 is a good option if we are willing to make the tradeoff, otherwise, 1 would be my preference if we need to report the most recent bucket. 2 seems like the most accurate way to do it but I am hesitant to do that considering we are so late into the release and wouldn't want to break histograms.

cc @dhartunian

Screenshot taken after adjusting the interval for replica stats to 500ms instead of 10s. (There are no gaps in timeseries)

[andreimatei]

2. Synchronize ticks with tsdb scrapes so that we always scrape before a tick. (seems complex and could have side effects since our rotation duration is configurable).

To me, this one seems the most appealing. Unless we tie the rotation frequency with the tsdb poll, the problem you quote is common with option 3, isn't it?

[aadityasondhi]

Yeah with 3 we will always report stats that are one rotation interval old. Which on second thought seems less than ideal. I can take a look into how we can implement 2.

What are your thoughts on 1? When we scrape/calculate quantiles, we can use a merged view of current and previous windows.

[andreimatei]

I don't understand 1 and 3 very well, truth is. Our problem is not simply that we want to avoid reporting zeroes; it's that we want to report data that makes sense (i.e. is calculated over the past 10s, not more than that).
For Option 1), let's consider this scenario:

|---------|---- ------|-----
a          b   c      d     e

Let's say that our windowed histograms ticks at time a, then b, then d. And let's say that out poller comes around at time c. If I understand correctly, you're proposing that we record the data for (a,c), right?
Then, let's say that the poller comes again at time e. Now we're recording (b, e), right? So we're double-counting the data for (b,c). And each point on the quantile graphs will represent not 10s, not 20s, but some duration in between.
In the case where the window ticking interval is smaller than the polling interval, we'll also be missing some data (like we also do today).
Similarly, if the two intervals are the same, and they actually align (i.e. we start the timers ~the same time), the ticking and the polling are racing and you'll sometimes look at two buckets out of which one is empty, other times you'll look at two full buckets.
I find it a bit hard to reason about this scheme (assuming I got it right), because it's complicated.

So, it seems to me that we should synchronize the polling and the ticking, one way or another. It can be done explicitly, like you propose in 2), or maybe I can suggest
4) Lift the windowing into the poller: Get rid of any notion of windows in the histogram implementation; maintain only the data for one cumulative histogram. And have the poller capture a snapshot of the histograms it polls and record the delta from the previous snapshot.
It contrast to 2), this would keep histograms able to be polled by different pollers.

---

The problem seems to be that the replica stats are stored every 10s and we scrape for tsdb at a similar cadence (I think it is also every 10s).

I'm confused, because the window size seems to be 60s (from here). Which, if true, would make no sense to me... Is it true?

[aadityasondhi]

I see your point of view. Thanks for the detailed explanation. I don't think it will be double counting since we use these to store averages and quantiles which are a factor of the number of samples and not time that has passed. But I do agree that having an ambiguous time window for what that data represents is not the best way to do it.

I like the idea of moving the window into the poller. Just want to clarify that this would mean that we remove the windowing config option entirely and always have a 10s windowing (or whatever we decide we want our polling interval to be).

I'm confused, because the window size seems to be 60s (from here). Which, if true, would make no sense to me... Is it true?

The window size is indeed 60s by default. The problem here is that when we poll for the first time after a tick, we are polling an empty histogram since the histogram in question only reports values every 10s.

[andreimatei]

I don't think it will be double counting since we use these to store averages and quantiles which are a factor of the number of samples and not time that has passed.

By "double counting", I mean some measurements will affect multiple tsdb records, and others will affect only one (e.g. (c,d) if we continue the above example).

I like the idea of moving the window into the poller. Just want to clarify that this would mean that we remove the windowing config option entirely and always have a 10s windowing (or whatever we decide we want our polling interval to be).

I had no idea about the 60s window until today. So every 10s we have a point that represents the p99 over the past 60s? Or actually, even worse - the first point is p99[10s], the next is p99[20s],...p99[60s], p99[10s],...
It strikes me as bizarre; I think people expect every point to be the p99 over the past 10s. Otherwise, it gets really confusing when aggregating these percentiles over longer durations.
So, yeah, I'd get rid of it. Perhaps you could dig into the history a little bit and see if there was some reason for doing it this way.
If we really want the quantiles to be computed over a different duration, the poller can maintain multiple snapshots per histogram.

The window size is indeed 60s by default. The problem here is that when we poll for the first time after a tick, we are polling an empty histogram since the histogram in question only reports values every 10s.

Ack. I had misread the issue as complaining about gaps every 10s.

[aadityasondhi]

I had no idea about the 60s window until today. So every 10s we have a point that represents the p99 over the past 60s? Or actually, even worse - the first point is p99[10s], the next is p99[20s],...p99[60s], p99[10s],...

Yeah, I think we are on the same page now.

Perhaps you could dig into the history a little bit and see if there was some reason for doing it this way.

@tbg might have a better idea why this is the case. I believe the reasoning behind this is the same as the reason why we have issues with this histogram. By having window sizes configurable (and separate from polling) we let the users (for example, KV team) decide what they want their histogram to represent. p99 over a 10s window might be weird for histograms such as the one in question where we take a measurement every 10s. It will on average have 1 sample per tsdb record. And based on the timing of the sample being read, it might even have 0. Which can provide the wrong picture to the reader of the metric. The windows give us the ability to provide moving averages/percentiles over a larger window so that we don't have sudden drops as we see here.

I think the implementation had limitations (as were noted in the comments) but the underlying idea seems reasonable. The user can define the window they want their histogram to have moving averages/percentiles for. Maybe we should maintain a queue of 10s chunks and always provide the user with the last window size data (i.e. last 60s). This would keep the ability to configure windows while also making sure that we have consistent windowing behavior.

[tbg]

I don't think there was ever a desire to vary the window size by histogram. Rather, it's all a pile-up of unhappy historical accidents. I agree with Andrei's suggestion to more tightly couple the TSDB loop with the windowed histogram. I think so far we have tried to avoid this, but it's leading to the windowed histograms representing fairly unclear actual time windows. The only thing that really makes sense is that the datapoint at time T uses a windowed histogram that contains measurements that happened in the interval between the last scrape (so ~T-10s) and T. We were likely worried that there would be multiple scrapers sometimes (which, I think, can happen if you also scrape prometheus) so we should "simply" make sure that there is only one kind of scrape that actually affects the windowed histogram, and that this one scrape really only happens every 10s.

[aadityasondhi]

That makes sense. Thanks for the clarification.

If we make this change, what happens to the histogram mentioned in this issue? Should we discourage people from using histograms in cases where they only record data every 10s or higher? Using your example, a histogram with a low cadence of samples might have 0 data points within the [T-10, T] window. This will show up as 0 on the graphs and will paint the wrong picture about the underlying metric.

[kvoli]

From reading the thread, I'm thinking it would be easiest (for the use case at the top) to implement some histogram helpers for periodic recording, where all values we wish to record for a time window are known upfront. An example I found is in the client_go pkg.

To shed some more light on the use case:

I want to view, for that 10s what the 99th, 95th 50th etc percentile of replica load is in order to determine outliers and compare against other intervals and stores.

To implement this, I piggybacked existing logic where every 10s the store iterates over all its replica and grabs the replica's load stats. With the load stats, I record the replica's value to the histogram.

[aadityasondhi]

Based on an in-person discussion with Andrei, I propose the following:

1. Lift the windowing logic into the poller. This makes sure that each value that we store into tsdb is of the window [T-t, T], where t is the last poll time and T is the current time. This will work for histograms that are of cumulative nature.
2. For histograms such as the one above, I would suggest using ManualWindowHistogram. I do recognize that the current interface is cumbersome and I will rework it to make it more easily usable. When you create this histogram, you will be required to provide the promised update interval. The poller will report the last known value of these histograms as long as T-t < update interval. To avoid race conditions such as the one in this issue, we will allow for 1 missed update but start reporting 0 if the poller misses twice in a row.

I will prioritize 2 over 1 to unblock the PR. Let me know if this sounds good as a resolution.

cc @andreimatei @kvoli

[kvoli]

For histograms such as the one above, I would suggest using ManualWindowHistogram. I do recognize that the current interface is cumbersome and I will rework it to make it more easily usable. When you create this histogram, you will be required to provide the promised update interval. The poller will report the last known value of these histograms as long as T-t < update interval. To avoid race conditions such as the one in this issue, we will allow for 1 missed update but start reporting 0 if the poller misses twice in a row.

That seems perfect for my use case. Would the interface for recording be Observe(float64), called for every value?

[aadityasondhi]

Would the interface for recording be Observe(float64), called for every value?

I think the interface will require you to maintain a local histogram and call Update(Histogram) whenever you want to insert the new values and overwrite the previous histogram. This will mostly mimic what the batch histogram in Prometheus does https://github.com/prometheus/client_golang/blob/3d2cf0b338e19b0eaf277496058fc77bd3add440/prometheus/go_collector_latest.go#L454-L456.