rustfs/crates/io-metrics/src/list_objects_metrics.rs

// Copyright 2024 RustFS Team
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//     http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

use metrics::{counter, describe_counter, describe_histogram, histogram};
use std::sync::OnceLock;

use crate::get_stage_metrics_enabled;

pub const LIST_OBJECTS_SOURCE_WALKER: &str = "walker";
pub const LIST_OBJECTS_GATHER_OUTCOME_LIMIT_REACHED: &str = "limit_reached";
pub const LIST_OBJECTS_GATHER_OUTCOME_INPUT_CLOSED: &str = "input_closed";
pub const LIST_OBJECTS_MERGE_OUTCOME_STARTED: &str = "started";

const LIST_OBJECTS_GATHER_TOTAL: &str = "rustfs_s3_list_objects_gather_total";
const LIST_OBJECTS_GATHER_DURATION_MS: &str = "rustfs_s3_list_objects_gather_duration_ms";
const LIST_OBJECTS_GATHER_SCANNED_ENTRIES: &str = "rustfs_s3_list_objects_gather_scanned_entries";
const LIST_OBJECTS_GATHER_RETURNED_ENTRIES: &str = "rustfs_s3_list_objects_gather_returned_entries";
const LIST_OBJECTS_GATHER_FILTERED_ENTRIES: &str = "rustfs_s3_list_objects_gather_filtered_entries";
const LIST_OBJECTS_GATHER_SCAN_AMPLIFICATION: &str = "rustfs_s3_list_objects_gather_scan_amplification";
const LIST_OBJECTS_GATHER_LIMIT: &str = "rustfs_s3_list_objects_gather_limit";
const LIST_OBJECTS_MERGE_FAN_IN: &str = "rustfs_s3_list_objects_merge_fan_in";
const LIST_OBJECTS_MERGE_READ_QUORUM: &str = "rustfs_s3_list_objects_merge_read_quorum";
const LIST_OBJECTS_INDEX_ATTEMPT_TOTAL: &str = "rustfs_s3_list_objects_index_attempt_total";
const LIST_OBJECTS_INDEX_FALLBACK_TOTAL: &str = "rustfs_s3_list_objects_index_fallback_total";
const LIST_OBJECTS_INDEX_SERVED_TOTAL: &str = "rustfs_s3_list_objects_index_served_total";
const LIST_OBJECTS_INDEX_CANDIDATE_KEYS: &str = "rustfs_s3_list_objects_index_candidate_keys";
const LIST_OBJECTS_INDEX_LIVE_VERIFY_ATTEMPTS: &str = "rustfs_s3_list_objects_index_live_verify_attempts";
const LIST_OBJECTS_INDEX_LIVE_VERIFY_HITS: &str = "rustfs_s3_list_objects_index_live_verify_hits";
const LIST_OBJECTS_INDEX_LIVE_VERIFY_MISSES: &str = "rustfs_s3_list_objects_index_live_verify_misses";
const LIST_OBJECTS_INDEX_LIVE_VERIFY_FAILURE_TOTAL: &str = "rustfs_s3_list_objects_index_live_verify_failure_total";
const LIST_OBJECTS_INDEX_RETURNED_OBJECTS: &str = "rustfs_s3_list_objects_index_returned_objects";
const LIST_OBJECTS_INDEX_RETURNED_PREFIXES: &str = "rustfs_s3_list_objects_index_returned_prefixes";
const LIST_OBJECTS_INDEX_VERIFICATION_IO_AMPLIFICATION: &str = "rustfs_s3_list_objects_index_verification_io_amplification";
const LIST_OBJECTS_LOCAL_READ_DIR_TOTAL: &str = "rustfs_s3_list_objects_local_read_dir_total";
const LIST_OBJECTS_LOCAL_READ_DIR_DURATION_MS: &str = "rustfs_s3_list_objects_local_read_dir_duration_ms";
const LIST_OBJECTS_LOCAL_READ_DIR_ENTRIES: &str = "rustfs_s3_list_objects_local_read_dir_entries";
const LIST_OBJECTS_LOCAL_READ_DIR_LIMIT: &str = "rustfs_s3_list_objects_local_read_dir_limit";

pub const LIST_OBJECTS_LOCAL_READ_DIR_OUTCOME_OK: &str = "ok";
pub const LIST_OBJECTS_LOCAL_READ_DIR_OUTCOME_ERROR: &str = "error";

#[derive(Clone, Copy, Debug, PartialEq)]
pub struct ListObjectsGatherObservation {
    pub source: &'static str,
    pub outcome: &'static str,
    pub limit: i32,
    pub scanned_entries: usize,
    pub returned_entries: usize,
    pub duration_ms: f64,
    pub has_prefix: bool,
    pub has_delimiter: bool,
    pub has_marker: bool,
}

#[derive(Clone, Copy, Debug, PartialEq)]
pub struct ListObjectsIndexPageObservation {
    pub source: &'static str,
    pub provider: &'static str,
    pub candidate_keys: usize,
    pub live_verify_attempts: usize,
    pub live_verify_hits: usize,
    pub live_verify_misses: usize,
    pub returned_objects: usize,
    pub returned_prefixes: usize,
    pub is_truncated: bool,
}

#[derive(Clone, Copy, Debug, PartialEq)]
pub struct ListObjectsLocalReadDirObservation {
    pub outcome: &'static str,
    pub requested_count: i32,
    pub returned_entries: usize,
    pub duration_ms: f64,
    pub is_root: bool,
    pub has_filter_prefix: bool,
    pub has_forward: bool,
}

#[inline(always)]
fn bool_label(value: bool) -> &'static str {
    if value { "true" } else { "false" }
}

#[inline(always)]
fn count_as_f64(value: usize) -> f64 {
    value as f64
}

#[inline(always)]
fn limit_as_f64(value: i32) -> f64 {
    value.max(0) as f64
}

#[inline(always)]
fn count_mode_label(count: i32) -> &'static str {
    if count < 0 { "whole" } else { "bounded" }
}

#[inline(always)]
fn read_dir_count_as_f64(value: i32) -> f64 {
    f64::from(value)
}

pub fn init_list_objects_metrics() {
    static METRICS_DESC_INIT: OnceLock<()> = OnceLock::new();
    METRICS_DESC_INIT.get_or_init(|| {
        describe_counter!(
            LIST_OBJECTS_GATHER_TOTAL,
            "Total number of ListObjects gather phases by source, outcome, and request shape."
        );
        describe_histogram!(LIST_OBJECTS_GATHER_DURATION_MS, "ListObjects gather phase duration in milliseconds.");
        describe_histogram!(
            LIST_OBJECTS_GATHER_SCANNED_ENTRIES,
            "Number of entries consumed by ListObjects gather before producing a page."
        );
        describe_histogram!(
            LIST_OBJECTS_GATHER_RETURNED_ENTRIES,
            "Number of entries returned by ListObjects gather before pagination trimming."
        );
        describe_histogram!(
            LIST_OBJECTS_GATHER_FILTERED_ENTRIES,
            "Number of entries filtered by ListObjects gather before producing a page."
        );
        describe_histogram!(
            LIST_OBJECTS_GATHER_SCAN_AMPLIFICATION,
            "Ratio of scanned entries to returned entries in ListObjects gather."
        );
        describe_histogram!(LIST_OBJECTS_GATHER_LIMIT, "Requested internal ListObjects gather page limit.");
        describe_histogram!(LIST_OBJECTS_MERGE_FAN_IN, "Number of input streams merged for ListObjects pages.");
        describe_histogram!(LIST_OBJECTS_MERGE_READ_QUORUM, "Read quorum used while merging ListObjects entries.");
        describe_counter!(
            LIST_OBJECTS_INDEX_ATTEMPT_TOTAL,
            "Total number of opt-in ListObjects index serving attempts by source, provider, and request shape."
        );
        describe_counter!(
            LIST_OBJECTS_INDEX_FALLBACK_TOTAL,
            "Total number of opt-in ListObjects index attempts that fell back to the live walker."
        );
        describe_counter!(
            LIST_OBJECTS_INDEX_SERVED_TOTAL,
            "Total number of ListObjects pages served by an opt-in index provider."
        );
        describe_histogram!(
            LIST_OBJECTS_INDEX_CANDIDATE_KEYS,
            "Number of candidate keys proposed by the opt-in ListObjects index provider per page."
        );
        describe_histogram!(
            LIST_OBJECTS_INDEX_LIVE_VERIFY_ATTEMPTS,
            "Number of live xl.meta verification attempts made by opt-in ListObjects index serving per page."
        );
        describe_histogram!(
            LIST_OBJECTS_INDEX_LIVE_VERIFY_HITS,
            "Number of opt-in ListObjects index candidates accepted by live xl.meta verification per page."
        );
        describe_histogram!(
            LIST_OBJECTS_INDEX_LIVE_VERIFY_MISSES,
            "Number of opt-in ListObjects index candidates rejected as stale or missing by live xl.meta verification per page."
        );
        describe_counter!(
            LIST_OBJECTS_INDEX_LIVE_VERIFY_FAILURE_TOTAL,
            "Total number of opt-in ListObjects index live xl.meta verification failures."
        );
        describe_histogram!(
            LIST_OBJECTS_INDEX_RETURNED_OBJECTS,
            "Number of objects returned by opt-in ListObjects index serving per page."
        );
        describe_histogram!(
            LIST_OBJECTS_INDEX_RETURNED_PREFIXES,
            "Number of common prefixes returned by opt-in ListObjects index serving per page."
        );
        describe_histogram!(
            LIST_OBJECTS_INDEX_VERIFICATION_IO_AMPLIFICATION,
            "Ratio of live verification attempts to returned objects for opt-in ListObjects index serving."
        );
        describe_counter!(
            LIST_OBJECTS_LOCAL_READ_DIR_TOTAL,
            "Total number of local read_dir calls made while serving live-walker ListObjects pages."
        );
        describe_histogram!(
            LIST_OBJECTS_LOCAL_READ_DIR_DURATION_MS,
            "Duration in milliseconds of local read_dir calls made while serving live-walker ListObjects pages."
        );
        describe_histogram!(
            LIST_OBJECTS_LOCAL_READ_DIR_ENTRIES,
            "Number of immediate directory entries returned by local read_dir while serving live-walker ListObjects pages."
        );
        describe_histogram!(
            LIST_OBJECTS_LOCAL_READ_DIR_LIMIT,
            "Requested local read_dir count used while serving live-walker ListObjects pages; negative counts mean whole-directory enumeration."
        );
    });
}

pub fn record_list_objects_gather(observation: ListObjectsGatherObservation) {
    if !get_stage_metrics_enabled() {
        return;
    }

    let filtered_entries = observation.scanned_entries.saturating_sub(observation.returned_entries);
    let scan_amplification = if observation.returned_entries == 0 {
        count_as_f64(observation.scanned_entries)
    } else {
        count_as_f64(observation.scanned_entries) / count_as_f64(observation.returned_entries)
    };

    counter!(
        LIST_OBJECTS_GATHER_TOTAL,
        "source" => observation.source,
        "outcome" => observation.outcome,
        "has_prefix" => bool_label(observation.has_prefix),
        "has_delimiter" => bool_label(observation.has_delimiter),
        "has_marker" => bool_label(observation.has_marker),
    )
    .increment(1);
    histogram!(
        LIST_OBJECTS_GATHER_DURATION_MS,
        "source" => observation.source,
        "outcome" => observation.outcome
    )
    .record(observation.duration_ms);
    histogram!(LIST_OBJECTS_GATHER_SCANNED_ENTRIES, "source" => observation.source)
        .record(count_as_f64(observation.scanned_entries));
    histogram!(LIST_OBJECTS_GATHER_RETURNED_ENTRIES, "source" => observation.source)
        .record(count_as_f64(observation.returned_entries));
    histogram!(LIST_OBJECTS_GATHER_FILTERED_ENTRIES, "source" => observation.source).record(count_as_f64(filtered_entries));
    histogram!(LIST_OBJECTS_GATHER_SCAN_AMPLIFICATION, "source" => observation.source).record(scan_amplification);
    histogram!(LIST_OBJECTS_GATHER_LIMIT, "source" => observation.source).record(limit_as_f64(observation.limit));
}

pub fn record_list_objects_merge(source: &'static str, input_channels: usize, read_quorum: usize) {
    if !get_stage_metrics_enabled() {
        return;
    }

    histogram!(
        LIST_OBJECTS_MERGE_FAN_IN,
        "source" => source,
        "outcome" => LIST_OBJECTS_MERGE_OUTCOME_STARTED
    )
    .record(count_as_f64(input_channels));
    histogram!(
        LIST_OBJECTS_MERGE_READ_QUORUM,
        "source" => source,
        "outcome" => LIST_OBJECTS_MERGE_OUTCOME_STARTED
    )
    .record(count_as_f64(read_quorum));
}

pub fn record_list_objects_index_fallback(source: &'static str, reason: &'static str) {
    if !get_stage_metrics_enabled() {
        return;
    }

    counter!(
        LIST_OBJECTS_INDEX_FALLBACK_TOTAL,
        "source" => source,
        "reason" => reason
    )
    .increment(1);
}

pub fn record_list_objects_index_attempt(
    source: &'static str,
    provider: &'static str,
    has_prefix: bool,
    has_delimiter: bool,
    has_marker: bool,
) {
    if !get_stage_metrics_enabled() {
        return;
    }

    counter!(
        LIST_OBJECTS_INDEX_ATTEMPT_TOTAL,
        "source" => source,
        "provider" => provider,
        "has_prefix" => bool_label(has_prefix),
        "has_delimiter" => bool_label(has_delimiter),
        "has_marker" => bool_label(has_marker),
    )
    .increment(1);
}

pub fn record_list_objects_index_live_verify_failure(source: &'static str, reason: &'static str) {
    if !get_stage_metrics_enabled() {
        return;
    }

    counter!(
        LIST_OBJECTS_INDEX_LIVE_VERIFY_FAILURE_TOTAL,
        "source" => source,
        "reason" => reason,
    )
    .increment(1);
}

pub fn record_list_objects_index_served(observation: ListObjectsIndexPageObservation) {
    if !get_stage_metrics_enabled() {
        return;
    }

    let returned_objects = count_as_f64(observation.returned_objects);
    let verification_io_amplification = if observation.returned_objects == 0 {
        count_as_f64(observation.live_verify_attempts)
    } else {
        count_as_f64(observation.live_verify_attempts) / returned_objects
    };

    counter!(
        LIST_OBJECTS_INDEX_SERVED_TOTAL,
        "source" => observation.source,
        "provider" => observation.provider,
        "is_truncated" => bool_label(observation.is_truncated),
    )
    .increment(1);
    histogram!(
        LIST_OBJECTS_INDEX_CANDIDATE_KEYS,
        "source" => observation.source,
        "provider" => observation.provider,
    )
    .record(count_as_f64(observation.candidate_keys));
    histogram!(
        LIST_OBJECTS_INDEX_LIVE_VERIFY_ATTEMPTS,
        "source" => observation.source,
        "provider" => observation.provider,
    )
    .record(count_as_f64(observation.live_verify_attempts));
    histogram!(
        LIST_OBJECTS_INDEX_LIVE_VERIFY_HITS,
        "source" => observation.source,
        "provider" => observation.provider,
    )
    .record(count_as_f64(observation.live_verify_hits));
    histogram!(
        LIST_OBJECTS_INDEX_LIVE_VERIFY_MISSES,
        "source" => observation.source,
        "provider" => observation.provider,
    )
    .record(count_as_f64(observation.live_verify_misses));
    histogram!(
        LIST_OBJECTS_INDEX_RETURNED_OBJECTS,
        "source" => observation.source,
        "provider" => observation.provider,
    )
    .record(returned_objects);
    histogram!(
        LIST_OBJECTS_INDEX_RETURNED_PREFIXES,
        "source" => observation.source,
        "provider" => observation.provider,
    )
    .record(count_as_f64(observation.returned_prefixes));
    histogram!(
        LIST_OBJECTS_INDEX_VERIFICATION_IO_AMPLIFICATION,
        "source" => observation.source,
        "provider" => observation.provider,
    )
    .record(verification_io_amplification);
}

pub fn record_list_objects_local_read_dir(observation: ListObjectsLocalReadDirObservation) {
    if !get_stage_metrics_enabled() {
        return;
    }

    let count_mode = count_mode_label(observation.requested_count);

    counter!(
        LIST_OBJECTS_LOCAL_READ_DIR_TOTAL,
        "outcome" => observation.outcome,
        "count_mode" => count_mode,
        "is_root" => bool_label(observation.is_root),
        "has_filter_prefix" => bool_label(observation.has_filter_prefix),
        "has_forward" => bool_label(observation.has_forward),
    )
    .increment(1);
    histogram!(
        LIST_OBJECTS_LOCAL_READ_DIR_DURATION_MS,
        "outcome" => observation.outcome,
        "count_mode" => count_mode,
    )
    .record(observation.duration_ms);
    histogram!(
        LIST_OBJECTS_LOCAL_READ_DIR_ENTRIES,
        "outcome" => observation.outcome,
        "count_mode" => count_mode,
    )
    .record(count_as_f64(observation.returned_entries));
    histogram!(LIST_OBJECTS_LOCAL_READ_DIR_LIMIT, "count_mode" => count_mode)
        .record(read_dir_count_as_f64(observation.requested_count));
}

#[cfg(test)]
mod tests {
    use super::*;
    use crate::set_get_stage_metrics_enabled;
    use crate::tests::{METRICS_FLAG_LOCK, counter_total, emitted_names, histogram_samples};
    use metrics_util::debugging::DebuggingRecorder;

    /// Run `body` against a local recorder with stage metrics on, and return the
    /// snapshot rows.
    ///
    /// Enabling the flag is the point: every `record_*` here returns early when
    /// `get_stage_metrics_enabled()` is false, which defaults to false. The
    /// previous versions of these tests never set it, so they exercised nothing
    /// but the early return (rustfs/backlog#1836).
    fn recorded(body: impl FnOnce()) -> Vec<crate::tests::MetricRow> {
        let _guard = METRICS_FLAG_LOCK.lock().unwrap_or_else(|e| e.into_inner());
        let recorder = DebuggingRecorder::new();
        let snapshotter = recorder.snapshotter();
        metrics::with_local_recorder(&recorder, || {
            init_list_objects_metrics();
            set_get_stage_metrics_enabled(true);
            body();
            set_get_stage_metrics_enabled(false);
        });
        snapshotter.snapshot().into_vec()
    }

    #[test]
    fn gather_scan_amplification_falls_back_to_the_scan_count_on_an_empty_page() {
        let rows = recorded(|| {
            record_list_objects_gather(ListObjectsGatherObservation {
                source: LIST_OBJECTS_SOURCE_WALKER,
                outcome: LIST_OBJECTS_GATHER_OUTCOME_INPUT_CLOSED,
                limit: 1001,
                scanned_entries: 42,
                returned_entries: 0,
                duration_ms: 3.5,
                has_prefix: true,
                has_delimiter: false,
                has_marker: true,
            })
        });

        assert_eq!(counter_total(&rows, LIST_OBJECTS_GATHER_TOTAL), Some(1));
        // Zero returned entries must not divide: the amplification reports the
        // scan count itself rather than an infinity or a NaN.
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_GATHER_SCAN_AMPLIFICATION), vec![42.0]);
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_GATHER_FILTERED_ENTRIES), vec![42.0]);
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_GATHER_RETURNED_ENTRIES), vec![0.0]);
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_GATHER_DURATION_MS), vec![3.5]);
    }

    #[test]
    fn merge_records_a_zero_read_quorum_rather_than_skipping_it() {
        let rows = recorded(|| record_list_objects_merge(LIST_OBJECTS_SOURCE_WALKER, 4, 0));

        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_MERGE_FAN_IN), vec![4.0]);
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_MERGE_READ_QUORUM), vec![0.0]);
    }

    #[test]
    fn index_fallback_counts_once_per_reason() {
        let rows = recorded(|| {
            record_list_objects_index_fallback("index_key_only", "unsupported_request");
            record_list_objects_index_fallback("index_key_only", "unsupported_request");
        });

        assert_eq!(counter_total(&rows, LIST_OBJECTS_INDEX_FALLBACK_TOTAL), Some(2));
    }

    #[test]
    fn index_serving_reports_verification_amplification_against_returned_objects() {
        let rows = recorded(|| {
            record_list_objects_index_attempt("index_key_only", "walker_key_only", true, true, false);
            record_list_objects_index_served(ListObjectsIndexPageObservation {
                source: "index_key_only",
                provider: "walker_key_only",
                candidate_keys: 1000,
                live_verify_attempts: 700,
                live_verify_hits: 650,
                live_verify_misses: 50,
                returned_objects: 600,
                returned_prefixes: 10,
                is_truncated: true,
            });
            record_list_objects_index_live_verify_failure("index_key_only", "read_error");
        });

        assert_eq!(counter_total(&rows, LIST_OBJECTS_INDEX_ATTEMPT_TOTAL), Some(1));
        assert_eq!(counter_total(&rows, LIST_OBJECTS_INDEX_SERVED_TOTAL), Some(1));
        assert_eq!(counter_total(&rows, LIST_OBJECTS_INDEX_LIVE_VERIFY_FAILURE_TOTAL), Some(1));
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_INDEX_CANDIDATE_KEYS), vec![1000.0]);
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_INDEX_LIVE_VERIFY_HITS), vec![650.0]);
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_INDEX_LIVE_VERIFY_MISSES), vec![50.0]);
        assert_eq!(
            histogram_samples(&rows, LIST_OBJECTS_INDEX_VERIFICATION_IO_AMPLIFICATION),
            vec![700.0 / 600.0]
        );
    }

    #[test]
    fn local_read_dir_passes_the_whole_directory_sentinel_through_as_the_limit() {
        let rows = recorded(|| {
            record_list_objects_local_read_dir(ListObjectsLocalReadDirObservation {
                outcome: LIST_OBJECTS_LOCAL_READ_DIR_OUTCOME_OK,
                requested_count: -1,
                returned_entries: 4096,
                duration_ms: 12.5,
                is_root: true,
                has_filter_prefix: false,
                has_forward: false,
            });
            record_list_objects_local_read_dir(ListObjectsLocalReadDirObservation {
                outcome: LIST_OBJECTS_LOCAL_READ_DIR_OUTCOME_ERROR,
                requested_count: -1,
                returned_entries: 0,
                duration_ms: 5000.0,
                is_root: true,
                has_filter_prefix: false,
                has_forward: true,
            });
        });

        assert_eq!(counter_total(&rows, LIST_OBJECTS_LOCAL_READ_DIR_TOTAL), Some(2));
        // `-1` is the "read the whole directory" sentinel and must reach the
        // limit histogram unchanged rather than being clamped to zero.
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_LOCAL_READ_DIR_LIMIT), vec![-1.0, -1.0]);
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_LOCAL_READ_DIR_ENTRIES), vec![0.0, 4096.0]);
        assert_eq!(histogram_samples(&rows, LIST_OBJECTS_LOCAL_READ_DIR_DURATION_MS), vec![12.5, 5000.0]);
        assert!(emitted_names(&rows).contains(LIST_OBJECTS_LOCAL_READ_DIR_TOTAL));
    }
}