From 7bc9b5b34c815c711dcdb058489ae0006d339bec Mon Sep 17 00:00:00 2001 From: Ethan Donowitz Date: Mon, 5 Feb 2024 15:08:42 -0500 Subject: [PATCH] adapter: Refactor query log metrics This commit makes a few changes related to the query logger used in the adapter. It: 1. Adds query logging for parsed select statements that require fallback (this was missing previously) 2. Adds query logging for parsed select statements that don't *require* fallback but should not be executed against Readyset (this was missing previously) 3. Removes checks in readyset_adapter::backend as to whether log information should be added to the query execution event, deferring deferring to the query logger to determine what information should be logged based on the query logging mode 4. Changes the possible query logging modes to be "disabled", "enabled", and "verbose," where "enabled" logs metrics about both proxied and cached queries but "verbose" includes the query string and query ID as metric labels In addition, this commit updates the query logging mode to "verbose" in the quickstart Docker compose files to ensure that the Grafana dashboards don't break. Release-Note-Core: Fixed an issue where query log metrics were not being emitted for certain proxied queries Change-Id: Iba0f6ab295cb01758e1e26176acf6ecaf3523a7e Reviewed-on: https://gerrit.readyset.name/c/readyset/+/6858 Tested-by: Buildkite CI Reviewed-by: Jason Brown --- .buildkite/test-demo.sh | 1 + community-development.md | 4 +- development.md | 4 +- quickstart/compose.mysql.yml | 2 +- quickstart/compose.postgres.yml | 2 +- quickstart/compose.yml | 2 +- readyset-adapter/src/backend.rs | 30 ++++---- readyset-client-metrics/src/lib.rs | 22 ++---- readyset/src/lib.rs | 6 +- readyset/src/query_logger.rs | 111 +++++++++++++++++------------ 10 files changed, 95 insertions(+), 89 deletions(-) diff --git a/.buildkite/test-demo.sh b/.buildkite/test-demo.sh index d9e536db99..ce7a5003df 100755 --- a/.buildkite/test-demo.sh +++ b/.buildkite/test-demo.sh @@ -166,6 +166,7 @@ run_script() { # If we are going to fail, dump some debug information that may be useful to look at show_docker_info docker logs readyset-cache-1 + docker-compose -f readyset.compose.yml down -v > /dev/null 2>&1 # The return code could have been 0, so exit with 1 explicitly exit 1 fi diff --git a/community-development.md b/community-development.md index 8327efa14f..1ccb5ebf24 100644 --- a/community-development.md +++ b/community-development.md @@ -77,13 +77,13 @@ This section is for developers who want to build ReadySet from source as they wo **Run against Postgres:** ```bash - cargo run --bin readyset --release -- --database-type=postgresql --upstream-db-url=postgresql://postgres:readyset@127.0.0.1:5432/testdb --username=postgres --password=readyset --address=0.0.0.0:5433 --deployment= --prometheus-metrics --query-log-mode all-queries + cargo run --bin readyset --release -- --database-type=postgresql --upstream-db-url=postgresql://postgres:readyset@127.0.0.1:5432/testdb --username=postgres --password=readyset --address=0.0.0.0:5433 --deployment= --prometheus-metrics ``` **Run against MySQL:** ```bash - cargo run --bin readyset --release -- --database-type=mysql --upstream-db-url=mysql://root:readyset@127.0.0.1:3306/testdb --username=root --password=readyset --address=0.0.0.0:3307 --deployment= --prometheus-metrics --query-log-mode all-queries + cargo run --bin readyset --release -- --database-type=mysql --upstream-db-url=mysql://root:readyset@127.0.0.1:3306/testdb --username=root --password=readyset --address=0.0.0.0:3307 --deployment= --prometheus-metrics ``` This runs the ReadySet Server and Adapter as a single process, a simple, standard way to run ReadySet that is also the easiest approach when developing. For production deployments, however, it is possible to run the Server and Adapter as separate processes. See the [scale out deployment pattern](https://docs.readyset.io/guides/deploy/production-notes/#scale-out) in the docs. diff --git a/development.md b/development.md index 482343dd3c..f68392d58d 100644 --- a/development.md +++ b/development.md @@ -65,13 +65,13 @@ Then, run the adapter binary. The adapter will communicate with servers that hav **MySQL** ``` cargo run --bin readyset --release -- --database-type mysql --upstream-db-url mysql://root:readyset@127.1/readyset --allow-unauthenticated-connections - --address 0.0.0.0:3307 --deployment --prometheus-metrics --query-log-mode all-queries + --address 0.0.0.0:3307 --deployment --prometheus-metrics ``` **Postgres** ``` cargo run --bin readyset --release -- --database-type postgresql --upstream-db-url postgresql://postgres:readyset@127.1/readyset --allow-unauthenticated-connections - --address 0.0.0.0:5433 --deployment --prometheus-metrics --query-log-mode all-queries + --address 0.0.0.0:5433 --deployment --prometheus-metrics ``` The adapter listens for connections at the address specified in the `address` flag. diff --git a/quickstart/compose.mysql.yml b/quickstart/compose.mysql.yml index 6cc3c5b19e..491eea9881 100644 --- a/quickstart/compose.mysql.yml +++ b/quickstart/compose.mysql.yml @@ -13,7 +13,7 @@ services: DEPLOYMENT_ENV: quickstart_docker DB_DIR: /state PROMETHEUS_METRICS: true - QUERY_LOG_MODE: all-queries + QUERY_LOG_MODE: verbose QUERY_CACHING: explicit STANDALONE: true DEPLOYMENT: docker_compose_deployment diff --git a/quickstart/compose.postgres.yml b/quickstart/compose.postgres.yml index 2e0fe0346c..5176a63429 100644 --- a/quickstart/compose.postgres.yml +++ b/quickstart/compose.postgres.yml @@ -14,7 +14,7 @@ services: DB_DIR: /state PROMETHEUS_METRICS: true QUERY_CACHING: explicit - QUERY_LOG_MODE: all + QUERY_LOG_MODE: verbose STANDALONE: true DEPLOYMENT: docker_compose_deployment LISTEN_ADDRESS: 0.0.0.0:5433 diff --git a/quickstart/compose.yml b/quickstart/compose.yml index 43eaced92e..c1d66176c6 100644 --- a/quickstart/compose.yml +++ b/quickstart/compose.yml @@ -14,7 +14,7 @@ services: DB_DIR: /state PROMETHEUS_METRICS: true QUERY_CACHING: explicit - QUERY_LOG_MODE: all-queries + QUERY_LOG_MODE: verbose STANDALONE: true DEPLOYMENT: docker_compose_deployment LISTEN_ADDRESS: 0.0.0.0:5433 diff --git a/readyset-adapter/src/backend.rs b/readyset-adapter/src/backend.rs index e95e276d47..930e10d345 100644 --- a/readyset-adapter/src/backend.rs +++ b/readyset-adapter/src/backend.rs @@ -93,9 +93,7 @@ use readyset_client::results::Results; use readyset_client::utils::retry_with_exponential_backoff; use readyset_client::{ColumnSchema, PlaceholderIdx, ViewCreateRequest}; pub use readyset_client_metrics::QueryDestination; -use readyset_client_metrics::{ - recorded, EventType, QueryExecutionEvent, QueryLogMode, SqlQueryType, -}; +use readyset_client_metrics::{recorded, EventType, QueryExecutionEvent, SqlQueryType}; use readyset_data::{DfType, DfValue}; use readyset_errors::ReadySetError::{self, PreparedStatementMissing}; use readyset_errors::{internal, internal_err, unsupported, unsupported_err, ReadySetResult}; @@ -278,7 +276,6 @@ pub struct BackendBuilder { ticket: Option, timestamp_client: Option, query_log_sender: Option>, - query_log_mode: QueryLogMode, unsupported_set_mode: UnsupportedSetMode, migration_mode: MigrationMode, query_max_failure_seconds: u64, @@ -301,7 +298,6 @@ impl Default for BackendBuilder { ticket: None, timestamp_client: None, query_log_sender: None, - query_log_mode: Default::default(), unsupported_set_mode: UnsupportedSetMode::Error, migration_mode: MigrationMode::InRequestPath, query_max_failure_seconds: (i64::MAX / 1000) as u64, @@ -364,7 +360,6 @@ impl BackendBuilder { unsupported_set_mode: self.unsupported_set_mode, migration_mode: self.migration_mode, query_max_failure_duration: Duration::new(self.query_max_failure_seconds, 0), - query_log_mode: self.query_log_mode, fallback_recovery_duration: Duration::new(self.fallback_recovery_seconds, 0), enable_experimental_placeholder_inlining: self .enable_experimental_placeholder_inlining, @@ -398,10 +393,8 @@ impl BackendBuilder { pub fn query_log( mut self, query_log_sender: Option>, - mode: QueryLogMode, ) -> Self { self.query_log_sender = query_log_sender; - self.query_log_mode = mode; self } @@ -621,8 +614,6 @@ struct BackendSettings { dialect: Dialect, slowlog: bool, require_authentication: bool, - /// Whether to log ad-hoc queries by full query text in the query logger. - query_log_mode: QueryLogMode, /// How to behave when receiving unsupported `SET` statements unsupported_set_mode: UnsupportedSetMode, /// How this backend handles migrations, See MigrationMode. @@ -2903,6 +2894,13 @@ where } Ok(ref parsed_query) if Handler::requires_fallback(parsed_query) => { if self.has_fallback() { + if let SqlQuery::Select(stmt) = parsed_query { + event.sql_type = SqlQueryType::Read; + event.query = Some(Arc::new(parsed_query.clone())); + event.query_id = + Some(QueryId::from_select(stmt, self.noria.schema_search_path())); + } + // Query requires a fallback and we can send it to fallback Self::query_fallback(self.upstream.as_mut(), query, &mut event).await } else { @@ -2915,16 +2913,16 @@ where Ok(SqlQuery::Select(stmt)) => { let mut view_request = ViewCreateRequest::new(stmt, self.noria.schema_search_path().to_owned()); + + event.sql_type = SqlQueryType::Read; + event.query = Some(Arc::new(SqlQuery::Select(view_request.statement.clone()))); + event.query_id = Some(QueryId::from(&view_request)); + let (noria_should_try, status, processed_query_params) = self.noria_should_try_select(&mut view_request); let processed_query_params = processed_query_params?; + if noria_should_try { - event.sql_type = SqlQueryType::Read; - if self.settings.query_log_mode.allow_ad_hoc() { - event.query = - Some(Arc::new(SqlQuery::Select(view_request.statement.clone()))); - event.query_id = Some(QueryId::from(&view_request)); - } Self::query_adhoc_select( &mut self.noria, self.upstream.as_mut(), diff --git a/readyset-client-metrics/src/lib.rs b/readyset-client-metrics/src/lib.rs index 6e74a7d492..0329a63a21 100644 --- a/readyset-client-metrics/src/lib.rs +++ b/readyset-client-metrics/src/lib.rs @@ -17,19 +17,17 @@ pub mod recorded; /// starting at `Disabled`, includes all of the preceeding (lower) level's metric /// details. This gradation attempts to make a reasonable tradeoff of metrics /// payload size vs. verbosity/debugability. -#[derive(Clone, Copy, Debug, Default, Eq, PartialEq, ValueEnum)] +#[derive(Clone, Copy, Debug, Eq, PartialEq, ValueEnum)] pub enum QueryLogMode { /// Do not capture query metrics at all. Disabled, - /// Only record query metrics for queries that are cached by ReadySet. - #[default] - Cached, /// Record query metrics for all queries, including ad-hoc (simple) queries /// as well as prepared statements. - AllQueries, + Enabled, /// Expert-mode. Captures the full suite of developer-level query metrics. - /// Not advisable for a production environment. - All, + /// Not advisable for a production environment, since it includes metric + /// labels that may have very high cardinality. + Verbose, } impl QueryLogMode { @@ -38,15 +36,7 @@ impl QueryLogMode { } pub fn is_verbose(&self) -> bool { - matches!(self, QueryLogMode::All) - } - - pub fn allow_ad_hoc(&self) -> bool { - matches!(self, QueryLogMode::AllQueries | QueryLogMode::All) - } - - pub fn allow_proxied_queries(&self) -> bool { - matches!(self, QueryLogMode::AllQueries | QueryLogMode::All) + matches!(self, QueryLogMode::Verbose) } } diff --git a/readyset/src/lib.rs b/readyset/src/lib.rs index 631117ef61..721bcb0e6a 100644 --- a/readyset/src/lib.rs +++ b/readyset/src/lib.rs @@ -297,8 +297,8 @@ pub struct Options { long, env = "QUERY_LOG_MODE", requires = "metrics", - default_value = "all-queries", - default_value_if("prometheus_metrics", "true", Some("all-queries")), + default_value = "enabled", + default_value_if("prometheus_metrics", "true", Some("enabled")), hide = true )] query_log_mode: QueryLogMode, @@ -1090,7 +1090,7 @@ where .allow_cache_ddl(allow_cache_ddl) .require_authentication(!options.allow_unauthenticated_connections) .dialect(self.parse_dialect) - .query_log(qlog_sender.clone(), options.query_log_mode) + .query_log(qlog_sender.clone()) .unsupported_set_mode(if options.allow_unsupported_set { readyset_adapter::backend::UnsupportedSetMode::Allow } else { diff --git a/readyset/src/query_logger.rs b/readyset/src/query_logger.rs index b3c7ee8810..49e0a9706b 100644 --- a/readyset/src/query_logger.rs +++ b/readyset/src/query_logger.rs @@ -26,6 +26,7 @@ pub(crate) struct QueryLogger { query_count: Counter, prepare_count: Counter, execute_count: Counter, + mode: QueryLogMode, } struct QueryMetrics { @@ -56,7 +57,7 @@ impl QueryMetrics { fn parse_histogram( &mut self, kind: (EventType, SqlQueryType), - mode: &QueryLogMode, + mode: QueryLogMode, ) -> &mut Histogram { self.histograms .entry(kind) @@ -70,10 +71,10 @@ impl QueryMetrics { if mode.is_verbose() { labels.push(("query", self.query.clone())); - } - if let Some(id) = &self.query_id { - labels.push(("query_id", id.clone())); + if let Some(id) = &self.query_id { + labels.push(("query_id", id.clone())); + } } register_histogram!(recorded::QUERY_LOG_PARSE_TIME, &labels) @@ -83,7 +84,7 @@ impl QueryMetrics { fn readyset_histogram( &mut self, kind: (EventType, SqlQueryType), - mode: &QueryLogMode, + mode: QueryLogMode, ) -> &mut Histogram { self.histograms .entry(kind) @@ -95,10 +96,10 @@ impl QueryMetrics { if mode.is_verbose() { labels.push(("query", self.query.clone())); - } - if let Some(id) = &self.query_id { - labels.push(("query_id", id.clone())); + if let Some(id) = &self.query_id { + labels.push(("query_id", id.clone())); + } } register_histogram!(recorded::QUERY_LOG_EXECUTION_TIME, &labels) @@ -108,7 +109,7 @@ impl QueryMetrics { fn upstream_histogram( &mut self, kind: (EventType, SqlQueryType), - mode: &QueryLogMode, + mode: QueryLogMode, ) -> &mut Histogram { self.histograms .entry(kind) @@ -119,48 +120,59 @@ impl QueryMetrics { if mode.is_verbose() { labels.push(("query", self.query.clone())); - } - if let Some(id) = &self.query_id { - labels.push(("query_id", id.clone())); + if let Some(id) = &self.query_id { + labels.push(("query_id", id.clone())); + } } register_histogram!(recorded::QUERY_LOG_EXECUTION_TIME, &labels) }) } - fn readyset_counter(&mut self, kind: (EventType, SqlQueryType)) -> &mut Counter { + fn readyset_counter( + &mut self, + kind: (EventType, SqlQueryType), + mode: QueryLogMode, + ) -> &mut Counter { self.counters .entry(kind) .or_default() .readyset_exe_count .get_or_insert_with(|| { - let mut labels = vec![ - ("query", self.query.clone()), - ("database_type", SharedString::from(DatabaseType::ReadySet)), - ]; + let mut labels = + vec![("database_type", SharedString::from(DatabaseType::ReadySet))]; - if let Some(id) = &self.query_id { - labels.push(("query_id", id.clone())); + if mode.is_verbose() { + labels.push(("query", self.query.clone())); + + if let Some(id) = &self.query_id { + labels.push(("query_id", id.clone())); + } } register_counter!(recorded::QUERY_LOG_EXECUTION_COUNT, &labels) }) } - fn upstream_counter(&mut self, kind: (EventType, SqlQueryType)) -> &mut Counter { + fn upstream_counter( + &mut self, + kind: (EventType, SqlQueryType), + mode: QueryLogMode, + ) -> &mut Counter { self.counters .entry(kind) .or_default() .upstream_exe_count .get_or_insert_with(|| { - let mut labels = vec![ - ("query", self.query.clone()), - ("database_type", SharedString::from(DatabaseType::MySql)), - ]; + let mut labels = vec![("database_type", SharedString::from(DatabaseType::MySql))]; + + if mode.is_verbose() { + labels.push(("query", self.query.clone())); - if let Some(id) = &self.query_id { - labels.push(("query_id", id.clone())); + if let Some(id) = &self.query_id { + labels.push(("query_id", id.clone())); + } } register_counter!(recorded::QUERY_LOG_EXECUTION_COUNT, &labels) @@ -189,22 +201,21 @@ impl QueryLogger { self.per_id_metrics.entry(query_id).or_insert_with(|| { let query_string = Self::query_string(&query); let query_id = SharedString::from(query_id.to_string()); + let labels = if self.mode.is_verbose() { + vec![ + ("query", query_string.clone()), + ("query_id", query_id.clone()), + ] + } else { + vec![] + }; QueryMetrics { - num_keys: register_counter!( - recorded::QUERY_LOG_TOTAL_KEYS_READ, - "query" => query_string.clone(), - "query_id" => query_id.clone(), - ), - cache_misses: register_counter!( - recorded::QUERY_LOG_QUERY_CACHE_MISSED, - "query" => query_string.clone(), - "query_id" => query_id.clone(), - ), + num_keys: register_counter!(recorded::QUERY_LOG_TOTAL_KEYS_READ, &labels), + cache_misses: register_counter!(recorded::QUERY_LOG_QUERY_CACHE_MISSED, &labels), cache_keys_missed: register_counter!( recorded::QUERY_LOG_TOTAL_CACHE_MISSES, - "query" => query_string.clone(), - "query_id" => query_id.clone(), + &labels ), query: query_string, query_id: Some(query_id), @@ -219,19 +230,24 @@ impl QueryLogger { .entry(query) .or_insert_with_key(|query| { let query_string = Self::query_string(query); + let labels = if self.mode.is_verbose() { + vec![("query", query_string.clone())] + } else { + vec![] + }; QueryMetrics { num_keys: register_counter!( readyset_client_metrics::recorded::QUERY_LOG_TOTAL_KEYS_READ, - "query" => query_string.clone(), + &labels ), cache_misses: register_counter!( readyset_client_metrics::recorded::QUERY_LOG_QUERY_CACHE_MISSED, - "query" => query_string.clone(), + &labels ), cache_keys_missed: register_counter!( readyset_client_metrics::recorded::QUERY_LOG_TOTAL_CACHE_MISSES, - "query" => query_string.clone(), + &labels ), query: query_string, query_id: None, @@ -268,6 +284,7 @@ impl QueryLogger { query_count: register_counter!(recorded::QUERY_LOG_EVENT_TYPE, "type" => "query"), prepare_count: register_counter!(recorded::QUERY_LOG_EVENT_TYPE, "type" => "prepare"), execute_count: register_counter!(recorded::QUERY_LOG_EVENT_TYPE, "type" => "execute"), + mode, }; loop { @@ -333,22 +350,22 @@ impl QueryLogger { if mode.is_verbose() && let Some(duration) = event.parse_duration { metrics - .parse_histogram((event.event, event.sql_type), &mode) + .parse_histogram((event.event, event.sql_type), mode) .record(duration); } if let Some(duration) = event.readyset_duration { metrics - .readyset_histogram((event.event, event.sql_type), &mode) + .readyset_histogram((event.event, event.sql_type), mode) .record(duration); - metrics.readyset_counter((event.event, event.sql_type)).increment(1); + metrics.readyset_counter((event.event, event.sql_type), mode).increment(1); } - if mode.allow_proxied_queries() && let Some(duration) = event.upstream_duration { + if let Some(duration) = event.upstream_duration { metrics - .upstream_histogram((event.event, event.sql_type), &mode) + .upstream_histogram((event.event, event.sql_type), mode) .record(duration); - metrics.upstream_counter((event.event, event.sql_type)).increment(1); + metrics.upstream_counter((event.event, event.sql_type), mode).increment(1); } } }