try: log cancelations within timeline_detail_handler

this in effort to hunt down https://github.com/neondatabase/cloud/issues/4998
This commit is contained in:
Joonas Koivunen
2023-05-16 14:29:29 +03:00
parent 4f64be4a98
commit 43fcf51133
4 changed files with 69 additions and 6 deletions

11
Cargo.lock generated
View File

@@ -2859,22 +2859,22 @@ dependencies = [
[[package]]
name = "pin-project"
version = "1.0.12"
version = "1.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ad29a609b6bcd67fee905812e544992d216af9d755757c05ed2d0e15a74c6ecc"
checksum = "c95a7476719eab1e366eaf73d0260af3021184f18177925b07f54b30089ceead"
dependencies = [
"pin-project-internal",
]
[[package]]
name = "pin-project-internal"
version = "1.0.12"
version = "1.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "069bdb1e05adc7a8990dce9cc75370895fbe4e3d58b9b73bf1aee56359344a55"
checksum = "39407670928234ebc5e6e580247dd567ad73a3578460c5990f9503df207e8f07"
dependencies = [
"proc-macro2",
"quote",
"syn 1.0.109",
"syn 2.0.15",
]
[[package]]
@@ -4979,6 +4979,7 @@ dependencies = [
"metrics",
"nix",
"once_cell",
"pin-project",
"pin-project-lite",
"pq_proto",
"rand",

View File

@@ -41,6 +41,9 @@ pq_proto.workspace = true
metrics.workspace = true
workspace_hack.workspace = true
# needed to have pin-projected with PinnedDrop
pin-project = "1.1"
[dev-dependencies]
byteorder.workspace = true
bytes.workspace = true

View File

@@ -147,3 +147,56 @@ macro_rules! const_assert {
const _: () = assert!($($args)*);
};
}
pub mod cancel_log {
pub trait CancelationLoggingExt {
fn log_being_canceled(self, step: &'static str) -> LogCancelation<Self>
where
Self: Sized;
}
impl<Fut: std::future::Future> CancelationLoggingExt for Fut {
fn log_being_canceled(self, step: &'static str) -> LogCancelation<Self>
where
Self: Sized,
{
LogCancelation {
inner: self,
name: Some(step),
span: tracing::Span::current(),
}
}
}
#[pin_project::pin_project(PinnedDrop)]
pub struct LogCancelation<Fut> {
#[pin]
inner: Fut,
name: Option<&'static str>,
span: tracing::Span,
}
impl<Fut: std::future::Future> std::future::Future for LogCancelation<Fut> {
type Output = Fut::Output;
fn poll(
self: std::pin::Pin<&mut Self>,
cx: &mut std::task::Context<'_>,
) -> std::task::Poll<Self::Output> {
let this = self.project();
let ready = std::task::ready!(this.inner.poll(cx));
this.name.take();
std::task::Poll::Ready(ready)
}
}
#[pin_project::pinned_drop]
impl<Fut> PinnedDrop for LogCancelation<Fut> {
fn drop(self: std::pin::Pin<&mut Self>) {
if let Some(name) = self.name {
let _g = self.span.enter();
tracing::info!("canceled while waiting for {name}");
}
}
}
}

View File

@@ -29,6 +29,7 @@ use crate::tenant::{LogicalSizeCalculationCause, PageReconstructError, Timeline}
use crate::{config::PageServerConf, tenant::mgr};
use utils::{
auth::JwtAuth,
cancel_log::CancelationLoggingExt,
http::{
endpoint::{self, attach_openapi_ui, auth_middleware, check_permission_with},
error::{ApiError, HttpErrorBody},
@@ -186,6 +187,7 @@ async fn build_timeline_info(
CancellationToken::new(),
ctx,
)
.log_being_canceled("get_current_logical_size_non_incremental")
.await?,
);
}
@@ -338,7 +340,9 @@ async fn timeline_detail_handler(request: Request<Body>) -> Result<Response<Body
let ctx = RequestContext::new(TaskKind::MgmtRequest, DownloadBehavior::Download);
let timeline_info = async {
let tenant = mgr::get_tenant(tenant_id, true).await?;
let tenant = mgr::get_tenant(tenant_id, true)
.log_being_canceled("get_tenant")
.await?;
let timeline = tenant
.get_timeline(timeline_id, false)
@@ -349,6 +353,7 @@ async fn timeline_detail_handler(request: Request<Body>) -> Result<Response<Body
include_non_incremental_logical_size.unwrap_or(false),
&ctx,
)
.log_being_canceled("build_timeline_info")
.await
.context("get local timeline info")
.map_err(ApiError::InternalServerError)?;
@@ -356,6 +361,7 @@ async fn timeline_detail_handler(request: Request<Body>) -> Result<Response<Body
Ok::<_, ApiError>(timeline_info)
}
.instrument(info_span!("timeline_detail", tenant = %tenant_id, timeline = %timeline_id))
.log_being_canceled("whole response")
.await?;
json_response(StatusCode::OK, timeline_info)