Skip to content

Commit

Permalink
Fix time frame calculation for processors profiling
Browse files Browse the repository at this point in the history
Previously "query_start_time_microseconds + query_duration_ms" was used,
which is not always correct, we should use "event_time_microseconds"
instead (since we extract everything except QueryStart from query_log).

Here is an example of timeframe difference:

    SELECT max(query_start_time_microseconds) AS t, max(query_duration_ms) AS d, t + (d / 1000.)
    FROM system.query_log
    WHERE query_id IN ('34146bc1-09e5-4468-b9a6-be9fb521240f', '34146bc1-09e5-4468-b9a6-be9fb521240f', 'bd961ef8-5d70-470c-b9d7-0dbe901e31a3', '3c73ea8b-34e7-4d2f-ab34-3c551d3c0c68')

    ┌──────────────────────────t─┬────d─┬─plus(max(query_start_time_microseconds), divide(max(query_duration_ms), 1000.))─┐
    │ 2024-05-26 16:14:55.582473 │ 5638 │                                                      2024-05-26 16:15:00.582473 │
    └────────────────────────────┴──────┴─────────────────────────────────────────────────────────────────────────────────┘

    SELECT min(event_time_microseconds), max(event_time_microseconds)
    FROM system.processors_profile_log
    WHERE query_id IN ('34146bc1-09e5-4468-b9a6-be9fb521240f', '34146bc1-09e5-4468-b9a6-be9fb521240f', 'bd961ef8-5d70-470c-b9d7-0dbe901e31a3', '3c73ea8b-34e7-4d2f-ab34-3c551d3c0c68')

    ┌─min(event_time_microseconds)─┬─max(event_time_microseconds)─┐
    │   2024-05-26 16:14:58.455948 │   2024-05-26 16:15:00.838703 │
    └──────────────────────────────┴──────────────────────────────┘
  • Loading branch information
azat committed May 26, 2024
1 parent 6e1c0cf commit 39a3c3d
Show file tree
Hide file tree
Showing 3 changed files with 12 additions and 12 deletions.
5 changes: 4 additions & 1 deletion src/interpreter/clickhouse.rs
Original file line number Diff line number Diff line change
Expand Up @@ -211,6 +211,7 @@ impl ClickHouse {
hostName() as host_name,
current_database,
query_start_time_microseconds,
event_time_microseconds AS query_end_time_microseconds,
toValidUTF8(query) AS original_query,
normalizeQuery(query) AS normalized_query
FROM {db_table}
Expand Down Expand Up @@ -281,6 +282,7 @@ impl ClickHouse {
hostName() as host_name,
current_database,
query_start_time_microseconds,
event_time_microseconds AS query_end_time_microseconds,
toValidUTF8(query) AS original_query,
normalizeQuery(query) AS normalized_query
FROM {db_table}
Expand Down Expand Up @@ -325,7 +327,8 @@ impl ClickHouse {
/* NOTE: now64()/elapsed does not have enough precision to handle starting
* time properly, while this column is used for querying system.text_log,
* and it should be the smallest time that we are looking for */
(now64() - elapsed - 1) AS query_start_time_microseconds,
(now64(6) - elapsed - 1) AS query_start_time_microseconds,
now64(6) AS query_end_time_microseconds,
toValidUTF8(query) AS original_query,
normalizeQuery(query) AS normalized_query
FROM {}
Expand Down
1 change: 1 addition & 0 deletions src/interpreter/query_process.rs
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ pub struct QueryProcess {
pub memory: i64,
pub elapsed: f64,
pub query_start_time_microseconds: DateTime<Local>,
pub query_end_time_microseconds: DateTime<Local>,
// Is the name good enough? Maybe simply "queries" or "shards_queries"?
pub subqueries: u64,
pub is_initial_query: bool,
Expand Down
18 changes: 7 additions & 11 deletions src/view/processes_view.rs
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
use anyhow::{Error, Result};
use chrono::{DateTime, Duration, Local};
use chrono::{DateTime, Local};
use chrono_tz::Tz;
use std::cmp::Ordering;
use std::collections::{HashMap, HashSet};
Expand Down Expand Up @@ -224,6 +224,9 @@ impl ProcessesView {
query_start_time_microseconds: processes
.get::<DateTime<Tz>, _>(i, "query_start_time_microseconds")?
.with_timezone(&Local),
query_end_time_microseconds: processes
.get::<DateTime<Tz>, _>(i, "query_end_time_microseconds")?
.with_timezone(&Local),
subqueries: 1, // See queries_count_subqueries()
is_initial_query: processes.get::<u8, _>(i, "is_initial_query")? == 1,
initial_query_id: processes.get::<_, _>(i, "initial_query_id")?,
Expand Down Expand Up @@ -404,19 +407,12 @@ impl ProcessesView {
min_query_start_microseconds = q.query_start_time_microseconds;
}
if !self.is_system_processes {
let query_end_time_microseconds = q
.query_start_time_microseconds
.checked_add_signed(
Duration::try_milliseconds((q.elapsed * 1e3) as i64).unwrap(),
)
.unwrap();

if let Some(max) = max_query_end_microseconds {
if query_end_time_microseconds > max {
max_query_end_microseconds = Some(query_end_time_microseconds);
if q.query_end_time_microseconds > max {
max_query_end_microseconds = Some(q.query_end_time_microseconds);
}
} else {
max_query_end_microseconds = Some(query_end_time_microseconds);
max_query_end_microseconds = Some(q.query_end_time_microseconds);
}
}
}
Expand Down

0 comments on commit 39a3c3d

Please sign in to comment.