Skip to content

Commit 00f6ded

Browse files
srhsrh
committed
chore(cubestore): Upgrade DF: More fine-grained planning metrics
Also, uses microseconds, so that sums of values are more accurate.
1 parent b8a6307 commit 00f6ded

File tree

4 files changed

+67
-32
lines changed

4 files changed

+67
-32
lines changed

‎rust/cubestore/cubestore/src/app_metrics.rs‎

Lines changed: 22 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -15,20 +15,28 @@ pub static DATA_QUERIES_CACHE_SIZE: Gauge = metrics::gauge("cs.sql.query.data.ca
1515
// Approximate total weighted size of entries in this cache.
1616
pub static DATA_QUERIES_CACHE_WEIGHT: Gauge = metrics::gauge("cs.sql.query.data.cache.weight");
1717
pub static DATA_QUERY_TIME_MS: Histogram = metrics::histogram("cs.sql.query.data.ms");
18-
pub static DATA_QUERY_LOGICAL_PLAN_TOTAL_CREATION_TIME_MS: Histogram =
19-
metrics::histogram("cs.sql.query.data.planning.logical_plan_total_creation.ms");
20-
pub static DATA_QUERY_LOGICAL_PLAN_OPTIMIZE_TIME_MS: Histogram =
21-
metrics::histogram("cs.sql.query.data.planning.logical_plan_optimize.ms");
22-
pub static DATA_QUERY_CHOOSE_INDEX_TIME_MS: Histogram =
23-
metrics::histogram("cs.sql.query.data.planning.choose_index.ms");
24-
pub static DATA_QUERY_CHOOSE_INDEX_AND_WORKERS_TIME_MS: Histogram =
25-
metrics::histogram("cs.sql.query.data.planning.choose_index_and_workers.ms");
26-
pub static DATA_QUERY_TO_SERIALIZED_PLAN_TIME_MS: Histogram =
27-
metrics::histogram("cs.sql.query.data.planning.to_serialized_plan.ms");
28-
pub static DATA_QUERY_CREATE_ROUTER_PHYSICAL_PLAN_MS: Histogram =
29-
metrics::histogram("cs.sql.query.data.planning.router_plan.ms");
30-
pub static DATA_QUERY_CREATE_WORKER_PHYSICAL_PLAN_MS: Histogram =
31-
metrics::histogram("cs.sql.query.data.planning.worker_plan.ms");
18+
pub static DATA_QUERY_LOGICAL_PLAN_TOTAL_CREATION_TIME_US: Histogram =
19+
metrics::histogram("cs.sql.query.data.planning.logical_plan.total_creation.us");
20+
pub static DATA_QUERY_LOGICAL_PLAN_EXECUTION_CONTEXT_TIME_US: Histogram =
21+
metrics::histogram("cs.sql.query.data.planning.logical_plan.execution_context.us");
22+
pub static DATA_QUERY_LOGICAL_PLAN_QUERY_PLANNER_SETUP_TIME_US: Histogram =
23+
metrics::histogram("cs.sql.query.data.planning.logical_plan.query_planner_setup.us");
24+
pub static DATA_QUERY_LOGICAL_PLAN_STATEMENT_TO_PLAN_TIME_US: Histogram =
25+
metrics::histogram("cs.sql.query.data.planning.logical_plan.statement_to_plan.us");
26+
27+
pub static DATA_QUERY_LOGICAL_PLAN_OPTIMIZE_TIME_US: Histogram =
28+
metrics::histogram("cs.sql.query.data.planning.logical_plan.optimize.us");
29+
pub static DATA_QUERY_LOGICAL_PLAN_IS_DATA_SELECT_QUERY_US: Histogram =
30+
metrics::histogram("cs.sql.query.data.planning.logical_plan.is_data_select_query.us");
31+
32+
pub static DATA_QUERY_CHOOSE_INDEX_AND_WORKERS_TIME_US: Histogram =
33+
metrics::histogram("cs.sql.query.data.planning.choose_index_and_workers.us");
34+
pub static DATA_QUERY_TO_SERIALIZED_PLAN_TIME_US: Histogram =
35+
metrics::histogram("cs.sql.query.data.planning.to_serialized_plan.us");
36+
pub static DATA_QUERY_CREATE_ROUTER_PHYSICAL_PLAN_US: Histogram =
37+
metrics::histogram("cs.sql.query.data.planning.router_plan.us");
38+
pub static DATA_QUERY_CREATE_WORKER_PHYSICAL_PLAN_US: Histogram =
39+
metrics::histogram("cs.sql.query.data.planning.worker_plan.us");
3240

3341
/// Incoming SQL queries that only read metadata or do trivial computations.
3442
pub static META_QUERIES: Counter = metrics::counter("cs.sql.query.meta");

‎rust/cubestore/cubestore/src/queryplanner/mod.rs‎

Lines changed: 37 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -137,8 +137,16 @@ impl QueryPlanner for QueryPlannerImpl {
137137
inline_tables: &InlineTables,
138138
trace_obj: Option<String>,
139139
) -> Result<QueryPlan, CubeError> {
140+
let pre_execution_context_time = SystemTime::now();
140141
let ctx = self.execution_context()?;
141142

143+
let post_execution_context_time = SystemTime::now();
144+
app_metrics::DATA_QUERY_LOGICAL_PLAN_EXECUTION_CONTEXT_TIME_US.report(
145+
post_execution_context_time
146+
.duration_since(pre_execution_context_time)?
147+
.as_micros() as i64,
148+
);
149+
142150
let state = Arc::new(ctx.state());
143151
let schema_provider = MetaStoreSchemaProvider::new(
144152
self.meta_store.get_tables_with_path(false).await?,
@@ -150,7 +158,20 @@ impl QueryPlanner for QueryPlannerImpl {
150158
);
151159

152160
let query_planner = SqlToRel::new_with_options(&schema_provider, sql_to_rel_options());
161+
162+
let pre_statement_to_plan_time = SystemTime::now();
153163
let mut logical_plan = query_planner.statement_to_plan(statement)?;
164+
let post_statement_to_plan_time = SystemTime::now();
165+
app_metrics::DATA_QUERY_LOGICAL_PLAN_QUERY_PLANNER_SETUP_TIME_US.report(
166+
pre_statement_to_plan_time
167+
.duration_since(post_execution_context_time)?
168+
.as_micros() as i64,
169+
);
170+
app_metrics::DATA_QUERY_LOGICAL_PLAN_STATEMENT_TO_PLAN_TIME_US.report(
171+
post_statement_to_plan_time
172+
.duration_since(pre_statement_to_plan_time)?
173+
.as_micros() as i64,
174+
);
154175

155176
// TODO upgrade DF remove
156177
trace!(
@@ -170,8 +191,12 @@ impl QueryPlanner for QueryPlannerImpl {
170191

171192
let logical_plan_optimize_time = SystemTime::now();
172193
logical_plan = state.optimize(&logical_plan)?;
173-
app_metrics::DATA_QUERY_LOGICAL_PLAN_OPTIMIZE_TIME_MS
174-
.report(logical_plan_optimize_time.elapsed()?.as_millis() as i64);
194+
let post_optimize_time = SystemTime::now();
195+
app_metrics::DATA_QUERY_LOGICAL_PLAN_OPTIMIZE_TIME_US.report(
196+
post_optimize_time
197+
.duration_since(logical_plan_optimize_time)?
198+
.as_micros() as i64,
199+
);
175200
trace!(
176201
"Logical Plan: {}",
177202
pp_plan_ext(
@@ -187,34 +212,36 @@ impl QueryPlanner for QueryPlannerImpl {
187212
)
188213
);
189214

215+
let post_is_data_select_query_time: SystemTime;
190216
let plan = if SerializedPlan::is_data_select_query(&logical_plan) {
191217
let choose_index_ext_start = SystemTime::now();
218+
post_is_data_select_query_time = choose_index_ext_start;
192219
let (logical_plan, meta) = choose_index_ext(
193220
logical_plan,
194221
&self.meta_store.as_ref(),
195222
self.config.enable_topk(),
196223
)
197224
.await?;
198-
let choose_index_ext_end = SystemTime::now();
199225
let workers = compute_workers(
200226
self.config.as_ref(),
201227
&logical_plan,
202228
&meta.multi_part_subtree,
203229
)?;
204-
app_metrics::DATA_QUERY_CHOOSE_INDEX_TIME_MS.report(
205-
choose_index_ext_end
206-
.duration_since(choose_index_ext_start)?
207-
.as_millis() as i64,
208-
);
209-
app_metrics::DATA_QUERY_CHOOSE_INDEX_AND_WORKERS_TIME_MS
210-
.report(choose_index_ext_start.elapsed()?.as_millis() as i64);
230+
app_metrics::DATA_QUERY_CHOOSE_INDEX_AND_WORKERS_TIME_US
231+
.report(choose_index_ext_start.elapsed()?.as_micros() as i64);
211232
QueryPlan::Select(
212233
PreSerializedPlan::try_new(logical_plan, meta, trace_obj)?,
213234
workers,
214235
)
215236
} else {
237+
post_is_data_select_query_time = SystemTime::now();
216238
QueryPlan::Meta(logical_plan)
217239
};
240+
app_metrics::DATA_QUERY_LOGICAL_PLAN_IS_DATA_SELECT_QUERY_US.report(
241+
post_is_data_select_query_time
242+
.duration_since(post_optimize_time)?
243+
.as_micros() as i64,
244+
);
218245

219246
Ok(plan)
220247
}

‎rust/cubestore/cubestore/src/queryplanner/query_executor.rs‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -173,8 +173,8 @@ impl QueryExecutor for QueryExecutorImpl {
173173
let trace_obj = plan.trace_obj();
174174
let create_router_physical_plan_time = SystemTime::now();
175175
let (physical_plan, logical_plan) = self.router_plan(plan, cluster).await?;
176-
app_metrics::DATA_QUERY_CREATE_ROUTER_PHYSICAL_PLAN_MS
177-
.report(create_router_physical_plan_time.elapsed()?.as_millis() as i64);
176+
app_metrics::DATA_QUERY_CREATE_ROUTER_PHYSICAL_PLAN_US
177+
.report(create_router_physical_plan_time.elapsed()?.as_micros() as i64);
178178
let split_plan = physical_plan;
179179

180180
trace!(
@@ -250,8 +250,8 @@ impl QueryExecutor for QueryExecutorImpl {
250250
Some(data_loaded_size.clone()),
251251
)
252252
.await?;
253-
app_metrics::DATA_QUERY_CREATE_WORKER_PHYSICAL_PLAN_MS
254-
.report(create_worker_physical_plan_time.elapsed()?.as_millis() as i64);
253+
app_metrics::DATA_QUERY_CREATE_WORKER_PHYSICAL_PLAN_US
254+
.report(create_worker_physical_plan_time.elapsed()?.as_micros() as i64);
255255

256256
let worker_plan;
257257
let max_batch_rows;

‎rust/cubestore/cubestore/src/sql/mod.rs‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1124,8 +1124,8 @@ impl SqlService for SqlServiceImpl {
11241124
)
11251125
.await?;
11261126

1127-
app_metrics::DATA_QUERY_LOGICAL_PLAN_TOTAL_CREATION_TIME_MS
1128-
.report(logical_plan_time_start.elapsed()?.as_millis() as i64);
1127+
app_metrics::DATA_QUERY_LOGICAL_PLAN_TOTAL_CREATION_TIME_US
1128+
.report(logical_plan_time_start.elapsed()?.as_micros() as i64);
11291129

11301130
// TODO distribute and combine
11311131
let res = match logical_plan {
@@ -1143,8 +1143,8 @@ impl SqlService for SqlServiceImpl {
11431143
let executor = self.query_executor.clone();
11441144
let serialized_plan_time_start = SystemTime::now();
11451145
let serialized_plan = serialized.to_serialized_plan()?;
1146-
app_metrics::DATA_QUERY_TO_SERIALIZED_PLAN_TIME_MS
1147-
.report(serialized_plan_time_start.elapsed()?.as_millis() as i64);
1146+
app_metrics::DATA_QUERY_TO_SERIALIZED_PLAN_TIME_US
1147+
.report(serialized_plan_time_start.elapsed()?.as_micros() as i64);
11481148
timeout(
11491149
self.query_timeout,
11501150
self.cache

0 commit comments

Comments
 (0)