PrometheusLayer: Add a new metrics called bytes_duration_seconds

[Xuanwo]

          > Another blocker is that the layer observes the timer before returning `Writer`/`Reader`. So it doesn't record the time spent by the `Writer`/`Reader`.

The idea of tracking the duration for a reader and writer seems illogical to me because it might include irrelevant time periods. For instance, if you create a new writer and have them write every 10 seconds, measuring their duration doesn't make sense.

The current time only measures the cost of read/write, users can use this to know if they spent too much time on opening a reader/writer.

I think we can add a new metrics called bytes_duration_seconds, so we can observe the time we spent on reading/writing bytes.

Originally posted by @Xuanwo in GreptimeTeam/greptimedb#4041 (comment)

[evenyag]

The idea of tracking the duration for a reader and writer seems illogical to me because it might include irrelevant time periods. For instance, if you create a new writer and have them write every 10 seconds, measuring their duration doesn't make sense.

Understood. I also have the same concerns.

The current time only measures the cost of read/write, users can use this to know if they spent too much time on opening a reader/writer.

I think we can add a new metrics called bytes_duration_seconds, so we can observe the time we spent on reading/writing bytes.

I found that the three different metrics layer in OpenDAL observes the request duration in different ways.

MetricsLayer

The MetricsLayer observes the time spent on reading/writing bytes to opendal_requests_duration_seconds. It doesn't observe the time creating the reader/writer.

opendal/core/src/layers/metrics.rs

Lines 787 to 804 in bfe9e44

	impl<R: oio::Write> oio::Write for MetricWrapper<R> {
	async fn write(&mut self, bs: Buffer) -> Result<usize> {
	let start = Instant::now();
	self.inner
	.write(bs)
	.await
	.map(|n| {
	self.bytes_counter.increment(n as u64);
	self.requests_duration_seconds
	.record(start.elapsed().as_secs_f64());
	n
	})
	.map_err(|err| {
	self.handle.increment_errors_total(self.op, err.kind());
	err
	})
	}

There is one exception: The block_write

opendal/core/src/layers/metrics.rs

Lines 636 to 645 in bfe9e44

	fn blocking_write(&self, path: &str, args: OpWrite) -> Result<(RpWrite, Self::BlockingWriter)> {
	self.handle.requests_total_blocking_write.increment(1);
	let start = Instant::now();
	let result = self.inner.blocking_write(path, args);
	let dur = start.elapsed().as_secs_f64();
	self.handle
	.requests_duration_seconds_blocking_write
	.record(dur);

PrometheusLayer

The PrometheusLayer only records the time creating the reader/writer to requests_duration_seconds

opendal/core/src/layers/prometheus.rs

Lines 345 to 369 in bfe9e44

	let timer = self
	.stats
	.requests_duration_seconds
	.with_label_values(&labels)
	.start_timer();
	let write_res = self
	.inner
	.write(path, args)
	.map(|v| {
	v.map(|(rp, r)| {
	(
	rp,
	PrometheusMetricWrapper::new(
	r,
	Operation::Write,
	self.stats.clone(),
	self.scheme,
	&path.to_string(),
	),
	)
	})
	})
	.await;
	timer.observe_duration();

PrometheusClientLayer

The PrometheusClientLayer records both the writer/reader creation time and bytes reading/writing time to opendal_request_duration_seconds

opendal/core/src/layers/prometheus_client.rs

Lines 577 to 588 in bfe9e44

	async fn write(&mut self, bs: Buffer) -> Result<usize> {
	let start = Instant::now();
	self.inner
	.write(bs)
	.await
	.map(|n| {
	self.metrics.observe_bytes_total(self.scheme, self.op, n);
	self.metrics
	.observe_request_duration(self.scheme, self.op, start.elapsed());
	n
	})

opendal/core/src/layers/prometheus_client.rs

Lines 637 to 643 in bfe9e44

	impl<R> Drop for PrometheusMetricWrapper<R> {
	fn drop(&mut self) {
	self.metrics
	.observe_bytes_total(self.scheme, self.op, self.bytes_total);
	self.metrics
	.observe_request_duration(self.scheme, self.op, self.start_time.elapsed());
	}

Document

According to the document, users might expect to observe the time spent on reading/writing bytes from requests_duration_seconds.

opendal/core/src/layers/metrics.rs

Lines 37 to 48 in bfe9e44

	/// requests_duration_seconds records the duration seconds of successful
	/// requests.
	///
	/// # NOTE
	///
	/// this metric will track the whole lifetime of this request:
	///
	/// - Building request
	/// - Sending request
	/// - Receiving response
	/// - Consuming response
	static METRIC_REQUESTS_DURATION_SECONDS: &str = "opendal_requests_duration_seconds";

opendal/core/src/layers/prometheus.rs

Line 49 in bfe9e44

/// | requests_duration_seconds | Histogram | Histogram of the time spent on specific operation | scheme, operation |

Questions

• Maybe we should add a new metric or label to record the cost of opening a reader/writer? e.g. label value open_writer/open_blocking_writer
• Should we use a consistent way to record the request duration?

[Xuanwo]

Yes, there are historical reasons why the two layers did not evolve simultaneously. And we do need to use a consistent way to record the request duration.

Our pattern will be:

• opendal_requests_duration_seconds{operation}: operation could be Operation or ReadOperation, like read and Read::read.

We don't need seperate metric for open_writer or open_blocking_writer, they should be covered by opendal_requests_duration_seconds{operation="write"} and opendal_requests_duration_seconds{operation="blocking_write"}.

[evenyag]

Do we still need bytes_duration_seconds?

opendal_requests_duration_seconds{operation}: operation could be Operation or ReadOperation, like read and Read::read.

Do you mean that opendal_requests_duration_seconds{operation="read"} measures the cost of opening a reader, and opendal_requests_duration_seconds{operation="Read::read"} measures the time of reading bytes?

Will we have a metric opendal_requests_duration_seconds{operation="Write::write"} to record the time of writing bytes?

[Xuanwo]

Hi, @evenyag, your comment is correct. I have fixed in PR #4691, welcome to check it out.