From 0b72313892b99d519ca23a3ce972bb6cfbfc5cc1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jakub=20Ber=C3=A1nek?= Date: Sat, 8 Jul 2023 17:21:28 +0200 Subject: [PATCH 1/3] Switch self profile to use HW counters instead of walltime --- collector/src/bin/rustc-fake.rs | 3 ++- site/frontend/templates/pages/detailed-query.html | 13 ++++++------- site/src/request_handlers/self_profile.rs | 2 +- 3 files changed, 9 insertions(+), 9 deletions(-) diff --git a/collector/src/bin/rustc-fake.rs b/collector/src/bin/rustc-fake.rs index 6cfcacdce..50f3c3a50 100644 --- a/collector/src/bin/rustc-fake.rs +++ b/collector/src/bin/rustc-fake.rs @@ -95,8 +95,9 @@ fn main() { if wrapper == "PerfStatSelfProfile" { cmd.arg(&format!( "-Zself-profile={}", - prof_out_dir.to_str().unwrap() + prof_out_dir.to_str().unwrap(), )); + cmd.arg("-Zself-profile-counter=instructions:u"); let _ = fs::remove_dir_all(&prof_out_dir); let _ = fs::create_dir_all(&prof_out_dir); } diff --git a/site/frontend/templates/pages/detailed-query.html b/site/frontend/templates/pages/detailed-query.html index dbec34f59..5f4d8603e 100644 --- a/site/frontend/templates/pages/detailed-query.html +++ b/site/frontend/templates/pages/detailed-query.html @@ -79,20 +79,19 @@

Artifact Size

-

'Time (%)' is the percentage of the cpu-clock time spent on this query (we do not use - wall-time as we want to account for parallelism).

+

'Instructions (%)' is the percentage of instructions executed on this query.

Executions do not include cached executions.

- - - + + + - + diff --git a/site/src/request_handlers/self_profile.rs b/site/src/request_handlers/self_profile.rs index 20b96240e..567e4542f 100644 --- a/site/src/request_handlers/self_profile.rs +++ b/site/src/request_handlers/self_profile.rs @@ -587,7 +587,7 @@ pub async fn handle_self_profile( .benchmark(selector::Selector::One(bench_name.to_string())) .profile(selector::Selector::One(profile.parse().unwrap())) .scenario(selector::Selector::One(scenario)) - .metric(selector::Selector::One(Metric::CpuClock)); + .metric(selector::Selector::One(Metric::InstructionsUser)); // Helper for finding an `ArtifactId` based on a commit sha let find_aid = |commit: &str| { From 7162f86bd653047265ceede12c8960db4836e239 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jakub=20Ber=C3=A1nek?= Date: Tue, 18 Jul 2023 09:46:47 +0200 Subject: [PATCH 2/3] Document the switch to HW counters --- .../templates/pages/detailed-query.html | 2 ++ site/src/api.rs | 9 +++++--- site/src/request_handlers/self_profile.rs | 22 +++++++++++-------- 3 files changed, 21 insertions(+), 12 deletions(-) diff --git a/site/frontend/templates/pages/detailed-query.html b/site/frontend/templates/pages/detailed-query.html index 5f4d8603e..e29215110 100644 --- a/site/frontend/templates/pages/detailed-query.html +++ b/site/frontend/templates/pages/detailed-query.html @@ -80,6 +80,8 @@

Artifact Size

Query/FunctionTime (%)Time (s)Time deltaInstructions (%)InstructionsInstructions delta Executions Executions delta - Incremental loading (s) + Incremental loading instructions Incremental loading delta

'Instructions (%)' is the percentage of instructions executed on this query.

+

Note: self-profile measurements have been recently switched + from wall-time to HW counters (instruction count). If comparing with an older artifact, the timings might not be directly comparable.

Executions do not include cached executions.

diff --git a/site/src/api.rs b/site/src/api.rs index 9b65a71ba..f075f9b90 100644 --- a/site/src/api.rs +++ b/site/src/api.rs @@ -333,18 +333,21 @@ pub mod self_profile { pub artifact_sizes: Option>, } + // Due to backwards compatibility, self profile event timing data is represented as durations, + // however since https://github.com/rust-lang/rustc-perf/pull/1647 it actually represents + // HW counter data (instruction counts). #[derive(Serialize, Deserialize, Clone, Debug)] pub struct QueryData { pub label: QueryLabel, - // Nanoseconds + // Instruction count pub self_time: u64, pub percent_total_time: f32, pub number_of_cache_misses: u32, pub number_of_cache_hits: u32, pub invocation_count: u32, - // Nanoseconds + // Instruction count pub blocked_time: u64, - // Nanoseconds + // Instruction count pub incremental_load_time: u64, } diff --git a/site/src/request_handlers/self_profile.rs b/site/src/request_handlers/self_profile.rs index 567e4542f..394e93788 100644 --- a/site/src/request_handlers/self_profile.rs +++ b/site/src/request_handlers/self_profile.rs @@ -155,7 +155,7 @@ pub async fn handle_self_profile_processed_download( } fn get_self_profile_data( - cpu_clock: Option, + total_instructions: Option, profile: &analyzeme::AnalysisResults, ) -> ServerResult { let total_time: Duration = profile.query_data.iter().map(|qd| qd.self_time).sum(); @@ -180,7 +180,7 @@ fn get_self_profile_data( label: "Totals".into(), self_time: total_time.as_nanos() as u64, // TODO: check against wall-time from perf stats - percent_total_time: cpu_clock + percent_total_time: total_instructions .map(|w| ((total_time.as_secs_f64() / w) * 100.0) as f32) // sentinel "we couldn't compute this time" .unwrap_or(-100.0), @@ -602,9 +602,9 @@ pub async fn handle_self_profile( } let commits = Arc::new(commits); - let mut cpu_responses = ctxt.statistic_series(query, commits.clone()).await?; - assert_eq!(cpu_responses.len(), 1, "all selectors are exact"); - let mut cpu_response = cpu_responses.remove(0).series; + let mut instructions_responses = ctxt.statistic_series(query, commits.clone()).await?; + assert_eq!(instructions_responses.len(), 1, "all selectors are exact"); + let mut instructions_response = instructions_responses.remove(0).series; let mut self_profile_data = Vec::new(); let conn = ctxt.conn().await; @@ -623,12 +623,16 @@ pub async fn handle_self_profile( } } let profiling_data = self_profile_data.remove(0).perform_analysis(); - let mut profile = get_self_profile_data(cpu_response.next().unwrap().1, &profiling_data) - .map_err(|e| format!("{}: {}", body.commit, e))?; + let mut profile = + get_self_profile_data(instructions_response.next().unwrap().1, &profiling_data) + .map_err(|e| format!("{}: {}", body.commit, e))?; let (base_profile, base_raw_data) = if body.base_commit.is_some() { let base_profiling_data = self_profile_data.remove(0).perform_analysis(); - let profile = get_self_profile_data(cpu_response.next().unwrap().1, &base_profiling_data) - .map_err(|e| format!("{}: {}", body.base_commit.as_ref().unwrap(), e))?; + let profile = get_self_profile_data( + instructions_response.next().unwrap().1, + &base_profiling_data, + ) + .map_err(|e| format!("{}: {}", body.base_commit.as_ref().unwrap(), e))?; (Some(profile), Some(base_profiling_data)) } else { (None, None) From 47e20b87dda20078eede7c8e0b61716abcb622ce Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jakub=20Ber=C3=A1nek?= Date: Tue, 18 Jul 2023 09:48:23 +0200 Subject: [PATCH 3/3] Change formatting of self-profile metrics --- site/frontend/src/pages/detailed-query.ts | 22 ++++++++++------------ 1 file changed, 10 insertions(+), 12 deletions(-) diff --git a/site/frontend/src/pages/detailed-query.ts b/site/frontend/src/pages/detailed-query.ts index bbc970330..2fa46c5ed 100644 --- a/site/frontend/src/pages/detailed-query.ts +++ b/site/frontend/src/pages/detailed-query.ts @@ -2,8 +2,8 @@ import {createUrlWithAppendedParams, getUrlParams} from "../utils/navigation"; import {postMsgpack} from "../utils/requests"; import {SELF_PROFILE_DATA_URL} from "../urls"; -function to_seconds(time) { - return time / 1000000000; +function normalize_value(value) { + return value; } function fmt_delta(to, delta, is_integral_delta) { @@ -267,14 +267,14 @@ function populate_data(data, state: Selector) { t.setAttribute("title", "% of cpu-time stat"); } } - td(row, to_seconds(cur.self_time).toFixed(3)); + td(row, normalize_value(cur.self_time)); if (delta) { td( row, fmt_delta( - to_seconds(cur.self_time), - to_seconds(delta.self_time), - false + normalize_value(cur.self_time), + normalize_value(delta.self_time), + true ), true ); @@ -291,16 +291,14 @@ function populate_data(data, state: Selector) { } else { td(row, "-", true); } - td(row, to_seconds(cur.incremental_load_time).toFixed(3)).classList.add( - "incr" - ); + td(row, normalize_value(cur.incremental_load_time)).classList.add("incr"); if (delta) { td( row, fmt_delta( - to_seconds(cur.incremental_load_time), - to_seconds(delta.incremental_load_time), - false + normalize_value(cur.incremental_load_time), + normalize_value(delta.incremental_load_time), + true ), true ).classList.add("incr");