-
Notifications
You must be signed in to change notification settings - Fork 180
[df] Export more metrics from query engine #4983
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -11,9 +11,9 @@ | |
| use std::io::Write; | ||
| use std::pin::Pin; | ||
| use std::sync::Arc; | ||
| use std::task::{Context, Poll}; | ||
| use std::time::Instant; | ||
|
|
||
| use crate::query_utils::{RecordBatchWriter, WriteRecordBatchStream}; | ||
| use crate::state::AdminServiceState; | ||
| use axum::extract::State; | ||
| use axum::http::StatusCode; | ||
| use axum::response::{IntoResponse, Response}; | ||
|
|
@@ -24,16 +24,24 @@ use datafusion::arrow::datatypes::Schema; | |
| use datafusion::arrow::ipc::writer::StreamWriter; | ||
| use datafusion::arrow::json::writer::JsonArray; | ||
| use datafusion::common::DataFusionError; | ||
| use futures::{StreamExt, TryStreamExt}; | ||
| use futures::{Stream, StreamExt, TryStreamExt}; | ||
| use http::{HeaderMap, HeaderValue}; | ||
| use http_body::Frame; | ||
| use http_body_util::StreamBody; | ||
| use metrics::histogram; | ||
| use parking_lot::Mutex; | ||
| use serde::Serialize; | ||
|
|
||
| use restate_admin_rest_model::query::QueryRequest; | ||
| use restate_core::network::TransportConnect; | ||
| use restate_types::invocation::client::InvocationClient; | ||
| use restate_types::schema::registry::{DiscoveryClient, MetadataService, TelemetryClient}; | ||
| use serde::Serialize; | ||
|
|
||
| use crate::metric_definitions::QUERY_ENGINE_QUERY_DURATION_SECONDS; | ||
| use crate::query_utils::{RecordBatchWriter, WriteRecordBatchStream}; | ||
| use crate::state::AdminServiceState; | ||
|
|
||
| const RETRY_AFTER_HEADER: &str = "Retry-After"; | ||
|
|
||
| /// Error response for query endpoint. | ||
| #[derive(Debug, Serialize, utoipa::ToSchema)] | ||
|
|
@@ -48,16 +56,47 @@ pub(crate) enum QueryError { | |
| Datafusion(#[from] datafusion::error::DataFusionError), | ||
| #[error("Query service not available")] | ||
| Unavailable, | ||
| #[error("Rate limited")] | ||
| RateLimited(#[from] gardal::RateLimited), | ||
| } | ||
|
|
||
| impl From<restate_storage_query_datafusion::context::QueryError> for QueryError { | ||
| fn from(err: restate_storage_query_datafusion::context::QueryError) -> Self { | ||
| match err { | ||
| restate_storage_query_datafusion::context::QueryError::DataFusion(e) => { | ||
| Self::Datafusion(e) | ||
| } | ||
| restate_storage_query_datafusion::context::QueryError::RateLimited(e) => { | ||
| Self::RateLimited(e) | ||
| } | ||
| } | ||
| } | ||
| } | ||
|
|
||
| impl IntoResponse for QueryError { | ||
| fn into_response(self) -> Response { | ||
| let status_code = match &self { | ||
| QueryError::Datafusion(datafusion::error::DataFusionError::Plan(_)) | ||
| | QueryError::Datafusion(datafusion::error::DataFusionError::SchemaError(_, _)) | ||
| | QueryError::Datafusion(datafusion::error::DataFusionError::SQL(_, _)) => { | ||
| StatusCode::BAD_REQUEST | ||
| } | ||
| QueryError::Datafusion(_) => StatusCode::INTERNAL_SERVER_ERROR, | ||
| QueryError::Unavailable => StatusCode::SERVICE_UNAVAILABLE, | ||
| QueryError::RateLimited(_) => StatusCode::TOO_MANY_REQUESTS, | ||
| }; | ||
|
|
||
| let mut headers = http::HeaderMap::new(); | ||
| if let QueryError::RateLimited(e) = &self { | ||
| headers.insert( | ||
| RETRY_AFTER_HEADER, | ||
| HeaderValue::from(e.earliest_retry_after().as_secs()), | ||
| ); | ||
| } | ||
|
|
||
| ( | ||
| status_code, | ||
| headers, | ||
| Json(QueryErrorBody { | ||
| message: self.to_string(), | ||
| }), | ||
|
|
@@ -94,6 +133,10 @@ where | |
| Invocations: InvocationClient + Send + Sync + Clone + 'static, | ||
| Transport: TransportConnect, | ||
| { | ||
| let duration_guard = QueryDurationGuard { | ||
| start: Instant::now(), | ||
| }; | ||
|
|
||
| let Some(query_context) = state.query_context.as_ref() else { | ||
| return Err(QueryError::Unavailable); | ||
| }; | ||
|
|
@@ -126,13 +169,46 @@ where | |
| return Err(err.into()); | ||
| } | ||
|
|
||
| // Move the guard into the body so the duration is recorded once the stream is fully | ||
| // consumed or dropped (e.g. on client disconnect). | ||
| let result_stream = Timed { | ||
| inner: result_stream, | ||
| _guard: duration_guard, | ||
| }; | ||
|
|
||
| Ok(Response::builder() | ||
| .header(http::header::CONTENT_TYPE, content_type) | ||
| .body(StreamBody::new(result_stream)) | ||
| .expect("content-type header is correct") | ||
| .into_response()) | ||
| } | ||
|
|
||
| /// Records the elapsed time since `start` into the query-duration histogram when dropped. | ||
| struct QueryDurationGuard { | ||
| start: Instant, | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Use our |
||
| } | ||
|
|
||
| impl Drop for QueryDurationGuard { | ||
| fn drop(&mut self) { | ||
| histogram!(QUERY_ENGINE_QUERY_DURATION_SECONDS).record(self.start.elapsed().as_secs_f64()); | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I am still not entirely sure about this metric. You already mentioned in the commit message that this can/will be skewed by the complexity of the query. But will also be skewed by slow clients, network speed, or cancelled queries (users dropping the stream before draining it completely). What I am trying to say it's heavily affected by user behaviour, and worried it can be misleading in some situations. What might be useful imho is a metric that measure latency of @AhmedSoliman what do you hink?
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Ah, I only considered the complexity of the query, but didn't consider the client's speed in draining the stream. That's a good point. We can definitely do TTFB, but then it wouldn't say much about how expensive the query is. I assume that maybe I can try to track the time we spent blocked on the record batch stream, but I don't know if this is going to be worth the complexity. |
||
| } | ||
| } | ||
|
|
||
| /// Wraps a stream, keeping a [`QueryDurationGuard`] alive for as long as the stream is held. | ||
| /// The guard records the query duration when this wrapper (the response body) is dropped. | ||
| struct Timed<S> { | ||
| inner: S, | ||
| _guard: QueryDurationGuard, | ||
| } | ||
|
|
||
| impl<S: Stream + Unpin> Stream for Timed<S> { | ||
| type Item = S::Item; | ||
|
|
||
| fn poll_next(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Option<Self::Item>> { | ||
| self.inner.poll_next_unpin(cx) | ||
| } | ||
| } | ||
|
|
||
| #[derive(Clone)] | ||
| // unfortunately the json writer doesnt give a way to get a mutable reference to the underlying writer, so we need another pointer in to its buffer | ||
| // we use a lock here to help make the writer send/sync, despite it being totally uncontended :( | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -163,6 +163,8 @@ impl Node { | |
| mut address_book: AddressBook, | ||
| ) -> Result<Self, BuildError> { | ||
| metric_definitions::describe_metrics(); | ||
| restate_storage_query_datafusion::describe_metrics(); | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I would avoid calling this from node crate tbh. I understand that datafusion has no |
||
|
|
||
| let mut server_builder = NetworkServerBuilder::new(&mut address_book); | ||
| let config = updateable_config.pinned(); | ||
|
|
||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -48,6 +48,16 @@ use crate::empty_invoker_status_handle::EmptyInvokerStatusHandle; | |
| use crate::node_fan_out::NodeWarnings; | ||
| use crate::remote_query_scanner_manager::RemoteScannerManager; | ||
|
|
||
| type RateLimiter = gardal::SharedTokenBucket<gardal::TokioClock>; | ||
|
|
||
| #[derive(thiserror::Error, Debug)] | ||
| pub enum QueryError { | ||
| #[error("Datafusion error: {0}")] | ||
| DataFusion(#[from] datafusion::common::DataFusionError), | ||
| #[error("Rate limited")] | ||
| RateLimited(#[from] gardal::RateLimited), | ||
| } | ||
|
|
||
| const SYS_INVOCATION_VIEW: &str = "CREATE VIEW sys_invocation as SELECT | ||
| ss.id, | ||
| ss.vqueue_id, | ||
|
|
@@ -496,6 +506,7 @@ where | |
| pub struct QueryContext { | ||
| sql_options: SQLOptions, | ||
| datafusion_context: SessionContext, | ||
| rate_limiter: Option<RateLimiter>, | ||
| } | ||
|
|
||
| impl QueryContext { | ||
|
|
@@ -508,6 +519,9 @@ impl QueryContext { | |
| options.tmp_dir.clone(), | ||
| options.query_parallelism(), | ||
| &options.datafusion_options, | ||
| options.rate_limiting.as_ref().map(|limit| { | ||
| RateLimiter::new(gardal::Limit::from(limit.clone()), gardal::TokioClock) | ||
| }), | ||
|
Comment on lines
+522
to
+524
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
When rate limiting is configured, this allocates a fresh bucket for every Useful? React with 👍 / 👎. |
||
| )?; | ||
|
|
||
| registerer.register(&ctx).await?; | ||
|
|
@@ -572,6 +586,7 @@ impl QueryContext { | |
| temp_folder: Option<String>, | ||
| default_parallelism: Option<usize>, | ||
| datafusion_options: &HashMap<String, String>, | ||
| rate_limiter: Option<RateLimiter>, | ||
| ) -> Result<Self, DataFusionError> { | ||
| // | ||
| // build the runtime | ||
|
|
@@ -625,10 +640,15 @@ impl QueryContext { | |
| Ok(Self { | ||
| sql_options, | ||
| datafusion_context: ctx, | ||
| rate_limiter, | ||
| }) | ||
| } | ||
|
|
||
| pub async fn execute(&self, sql: &str) -> datafusion::common::Result<QueryResult> { | ||
| pub async fn execute(&self, sql: &str) -> Result<QueryResult, QueryError> { | ||
| if let Some(limiter) = self.rate_limiter.as_ref() { | ||
| limiter.try_consume_one()?; | ||
| } | ||
|
Comment on lines
+648
to
+650
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
Because the token is consumed inside Useful? React with 👍 / 👎. |
||
|
|
||
| let state = self.datafusion_context.state(); | ||
| let statement = state.sql_to_statement(sql, &datafusion::config::Dialect::PostgreSQL)?; | ||
| let plan = state.statement_to_plan(statement).await?; | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
nit: Maybe a
QueryDurationGuard::new()is nicer ?