Skip to content

Commit 547238b

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 547238b

File tree

4 files changed

+50
-32
lines changed

4 files changed

+50
-32
lines changed

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

Lines changed: 24 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -15,20 +15,30 @@ 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+
28+
pub static DATA_QUERY_LOGICAL_PLAN_OPTIMIZE_TIME_US: Histogram =
29+
metrics::histogram("cs.sql.query.data.planning.logical_plan.optimize.us");
30+
pub static DATA_QUERY_LOGICAL_PLAN_IS_DATA_SELECT_QUERY_US: Histogram =
31+
metrics::histogram("cs.sql.query.data.planning.logical_plan.is_data_select_query.us");
32+
33+
34+
pub static DATA_QUERY_CHOOSE_INDEX_AND_WORKERS_TIME_US: Histogram =
35+
metrics::histogram("cs.sql.query.data.planning.choose_index_and_workers.us");
36+
pub static DATA_QUERY_TO_SERIALIZED_PLAN_TIME_US: Histogram =
37+
metrics::histogram("cs.sql.query.data.planning.to_serialized_plan.us");
38+
pub static DATA_QUERY_CREATE_ROUTER_PHYSICAL_PLAN_US: Histogram =
39+
metrics::histogram("cs.sql.query.data.planning.router_plan.us");
40+
pub static DATA_QUERY_CREATE_WORKER_PHYSICAL_PLAN_US: Histogram =
41+
metrics::histogram("cs.sql.query.data.planning.worker_plan.us");
3242

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

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

Lines changed: 18 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -137,8 +137,12 @@ 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(post_execution_context_time.duration_since(pre_execution_context_time)?.as_micros() as i64);
145+
142146
let state = Arc::new(ctx.state());
143147
let schema_provider = MetaStoreSchemaProvider::new(
144148
self.meta_store.get_tables_with_path(false).await?,
@@ -150,7 +154,12 @@ impl QueryPlanner for QueryPlannerImpl {
150154
);
151155

152156
let query_planner = SqlToRel::new_with_options(&schema_provider, sql_to_rel_options());
157+
158+
let pre_statement_to_plan_time = SystemTime::now();
153159
let mut logical_plan = query_planner.statement_to_plan(statement)?;
160+
let post_statement_to_plan_time = SystemTime::now();
161+
app_metrics::DATA_QUERY_LOGICAL_PLAN_QUERY_PLANNER_SETUP_TIME_US.report(pre_statement_to_plan_time.duration_since(post_execution_context_time)?.as_micros() as i64);
162+
app_metrics::DATA_QUERY_LOGICAL_PLAN_STATEMENT_TO_PLAN_TIME_US.report(post_statement_to_plan_time.duration_since(pre_statement_to_plan_time)?.as_micros() as i64);
154163

155164
// TODO upgrade DF remove
156165
trace!(
@@ -170,8 +179,9 @@ impl QueryPlanner for QueryPlannerImpl {
170179

171180
let logical_plan_optimize_time = SystemTime::now();
172181
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);
182+
let post_optimize_time = SystemTime::now();
183+
app_metrics::DATA_QUERY_LOGICAL_PLAN_OPTIMIZE_TIME_US
184+
.report(post_optimize_time.duration_since(logical_plan_optimize_time)?.as_micros() as i64);
175185
trace!(
176186
"Logical Plan: {}",
177187
pp_plan_ext(
@@ -187,34 +197,32 @@ impl QueryPlanner for QueryPlannerImpl {
187197
)
188198
);
189199

200+
let post_is_data_select_query_time: SystemTime;
190201
let plan = if SerializedPlan::is_data_select_query(&logical_plan) {
191202
let choose_index_ext_start = SystemTime::now();
203+
post_is_data_select_query_time = choose_index_ext_start;
192204
let (logical_plan, meta) = choose_index_ext(
193205
logical_plan,
194206
&self.meta_store.as_ref(),
195207
self.config.enable_topk(),
196208
)
197209
.await?;
198-
let choose_index_ext_end = SystemTime::now();
199210
let workers = compute_workers(
200211
self.config.as_ref(),
201212
&logical_plan,
202213
&meta.multi_part_subtree,
203214
)?;
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);
215+
app_metrics::DATA_QUERY_CHOOSE_INDEX_AND_WORKERS_TIME_US
216+
.report(choose_index_ext_start.elapsed()?.as_micros() as i64);
211217
QueryPlan::Select(
212218
PreSerializedPlan::try_new(logical_plan, meta, trace_obj)?,
213219
workers,
214220
)
215221
} else {
222+
post_is_data_select_query_time = SystemTime::now();
216223
QueryPlan::Meta(logical_plan)
217224
};
225+
app_metrics::DATA_QUERY_LOGICAL_PLAN_IS_DATA_SELECT_QUERY_US.report(post_is_data_select_query_time.duration_since(post_optimize_time)?.as_micros() as i64);
218226

219227
Ok(plan)
220228
}

‎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)