From d7fa2dba2d3eaad9f7693f25ae07ed77f5ba9bf8 Mon Sep 17 00:00:00 2001 From: duguorong009 <80258679+duguorong009@users.noreply.github.com> Date: Mon, 11 Sep 2023 19:58:15 +0800 Subject: [PATCH] fix(pageserver): update the `STORAGE_IO_TIME` metrics to avoid expensive operations (#5273) Introduce the `StorageIoOperation` enum, `StorageIoTime` struct, and `STORAGE_IO_TIME_METRIC` static which provides lockless access to histograms consumed by `VirtualFile`. Closes #5131 Co-authored-by: Joonas Koivunen --- pageserver/src/metrics.rs | 71 +++++++++++++++++++++++++++++----- pageserver/src/virtual_file.rs | 43 +++++++++++--------- 2 files changed, 85 insertions(+), 29 deletions(-) diff --git a/pageserver/src/metrics.rs b/pageserver/src/metrics.rs index e024a9d77a..691ccafae1 100644 --- a/pageserver/src/metrics.rs +++ b/pageserver/src/metrics.rs @@ -537,7 +537,7 @@ const STORAGE_IO_TIME_BUCKETS: &[f64] = &[ 30.000, // 30000 ms ]; -/// Tracks time taken by fs operations near VirtualFile. +/// VirtualFile fs operation variants. /// /// Operations: /// - open ([`std::fs::OpenOptions::open`]) @@ -548,15 +548,66 @@ const STORAGE_IO_TIME_BUCKETS: &[f64] = &[ /// - seek (modify internal position or file length query) /// - fsync ([`std::fs::File::sync_all`]) /// - metadata ([`std::fs::File::metadata`]) -pub(crate) static STORAGE_IO_TIME: Lazy = Lazy::new(|| { - register_histogram_vec!( - "pageserver_io_operations_seconds", - "Time spent in IO operations", - &["operation"], - STORAGE_IO_TIME_BUCKETS.into() - ) - .expect("failed to define a metric") -}); +#[derive( + Debug, Clone, Copy, strum_macros::EnumCount, strum_macros::EnumIter, strum_macros::FromRepr, +)] +pub(crate) enum StorageIoOperation { + Open, + Close, + CloseByReplace, + Read, + Write, + Seek, + Fsync, + Metadata, +} + +impl StorageIoOperation { + pub fn as_str(&self) -> &'static str { + match self { + StorageIoOperation::Open => "open", + StorageIoOperation::Close => "close", + StorageIoOperation::CloseByReplace => "close-by-replace", + StorageIoOperation::Read => "read", + StorageIoOperation::Write => "write", + StorageIoOperation::Seek => "seek", + StorageIoOperation::Fsync => "fsync", + StorageIoOperation::Metadata => "metadata", + } + } +} + +/// Tracks time taken by fs operations near VirtualFile. +#[derive(Debug)] +pub(crate) struct StorageIoTime { + metrics: [Histogram; StorageIoOperation::COUNT], +} + +impl StorageIoTime { + fn new() -> Self { + let storage_io_histogram_vec = register_histogram_vec!( + "pageserver_io_operations_seconds", + "Time spent in IO operations", + &["operation"], + STORAGE_IO_TIME_BUCKETS.into() + ) + .expect("failed to define a metric"); + let metrics = std::array::from_fn(|i| { + let op = StorageIoOperation::from_repr(i).unwrap(); + let metric = storage_io_histogram_vec + .get_metric_with_label_values(&[op.as_str()]) + .unwrap(); + metric + }); + Self { metrics } + } + + pub(crate) fn get(&self, op: StorageIoOperation) -> &Histogram { + &self.metrics[op as usize] + } +} + +pub(crate) static STORAGE_IO_TIME_METRIC: Lazy = Lazy::new(StorageIoTime::new); const STORAGE_IO_SIZE_OPERATIONS: &[&str] = &["read", "write"]; diff --git a/pageserver/src/virtual_file.rs b/pageserver/src/virtual_file.rs index 1fa5fcc297..9612b8ec6d 100644 --- a/pageserver/src/virtual_file.rs +++ b/pageserver/src/virtual_file.rs @@ -10,7 +10,7 @@ //! This is similar to PostgreSQL's virtual file descriptor facility in //! src/backend/storage/file/fd.c //! -use crate::metrics::{STORAGE_IO_SIZE, STORAGE_IO_TIME}; +use crate::metrics::{StorageIoOperation, STORAGE_IO_SIZE, STORAGE_IO_TIME_METRIC}; use crate::tenant::TENANTS_SEGMENT_NAME; use once_cell::sync::OnceCell; use std::fs::{self, File, OpenOptions}; @@ -155,8 +155,8 @@ impl OpenFiles { if let Some(old_file) = slot_guard.file.take() { // the normal path of dropping VirtualFile uses "close", use "close-by-replace" here to // distinguish the two. - STORAGE_IO_TIME - .with_label_values(&["close-by-replace"]) + STORAGE_IO_TIME_METRIC + .get(StorageIoOperation::CloseByReplace) .observe_closure_duration(|| drop(old_file)); } @@ -245,8 +245,9 @@ impl VirtualFile { timeline_id = "*".to_string(); } let (handle, mut slot_guard) = get_open_files().find_victim_slot(); - let file = STORAGE_IO_TIME - .with_label_values(&["open"]) + + let file = STORAGE_IO_TIME_METRIC + .get(StorageIoOperation::Open) .observe_closure_duration(|| open_options.open(path))?; // Strip all options other than read and write. @@ -330,17 +331,19 @@ impl VirtualFile { /// Call File::sync_all() on the underlying File. pub async fn sync_all(&self) -> Result<(), Error> { - self.with_file("fsync", |file| file.sync_all()).await? + self.with_file(StorageIoOperation::Fsync, |file| file.sync_all()) + .await? } pub async fn metadata(&self) -> Result { - self.with_file("metadata", |file| file.metadata()).await? + self.with_file(StorageIoOperation::Metadata, |file| file.metadata()) + .await? } /// Helper function that looks up the underlying File for this VirtualFile, /// opening it and evicting some other File if necessary. It calls 'func' /// with the physical File. - async fn with_file(&self, op: &str, mut func: F) -> Result + async fn with_file(&self, op: StorageIoOperation, mut func: F) -> Result where F: FnMut(&File) -> R, { @@ -363,8 +366,8 @@ impl VirtualFile { if let Some(file) = &slot_guard.file { // Found a cached file descriptor. slot.recently_used.store(true, Ordering::Relaxed); - return Ok(STORAGE_IO_TIME - .with_label_values(&[op]) + return Ok(STORAGE_IO_TIME_METRIC + .get(op) .observe_closure_duration(|| func(file))); } } @@ -390,13 +393,13 @@ impl VirtualFile { let (handle, mut slot_guard) = open_files.find_victim_slot(); // Open the physical file - let file = STORAGE_IO_TIME - .with_label_values(&["open"]) + let file = STORAGE_IO_TIME_METRIC + .get(StorageIoOperation::Open) .observe_closure_duration(|| self.open_options.open(&self.path))?; // Perform the requested operation on it - let result = STORAGE_IO_TIME - .with_label_values(&[op]) + let result = STORAGE_IO_TIME_METRIC + .get(op) .observe_closure_duration(|| func(&file)); // Store the File in the slot and update the handle in the VirtualFile @@ -421,7 +424,9 @@ impl VirtualFile { } SeekFrom::End(offset) => { self.pos = self - .with_file("seek", |mut file| file.seek(SeekFrom::End(offset))) + .with_file(StorageIoOperation::Seek, |mut file| { + file.seek(SeekFrom::End(offset)) + }) .await?? } SeekFrom::Current(offset) => { @@ -511,7 +516,7 @@ impl VirtualFile { pub async fn read_at(&self, buf: &mut [u8], offset: u64) -> Result { let result = self - .with_file("read", |file| file.read_at(buf, offset)) + .with_file(StorageIoOperation::Read, |file| file.read_at(buf, offset)) .await?; if let Ok(size) = result { STORAGE_IO_SIZE @@ -523,7 +528,7 @@ impl VirtualFile { async fn write_at(&self, buf: &[u8], offset: u64) -> Result { let result = self - .with_file("write", |file| file.write_at(buf, offset)) + .with_file(StorageIoOperation::Write, |file| file.write_at(buf, offset)) .await?; if let Ok(size) = result { STORAGE_IO_SIZE @@ -576,8 +581,8 @@ impl Drop for VirtualFile { slot.recently_used.store(false, Ordering::Relaxed); // there is also operation "close-by-replace" for closes done on eviction for // comparison. - STORAGE_IO_TIME - .with_label_values(&["close"]) + STORAGE_IO_TIME_METRIC + .get(StorageIoOperation::Close) .observe_closure_duration(|| drop(slot_guard.file.take())); } }