Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Switch self profile to use HW counters instead of walltime (attempt 2) #1984

Open
wants to merge 3 commits into
base: master
Choose a base branch
from
Open

Switch self profile to use HW counters instead of walltime (attempt 2) #1984

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
66048fe
Switch self profile to use HW counters instead of walltime
Kobzol Jul 8, 2023
579860f
Document the switch to HW counters
Kobzol Oct 3, 2024
a8b03fb
Change formatting of self-profile metrics
Kobzol Jul 18, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion collector/src/bin/rustc-fake.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -120,8 +120,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);
}
Expand Down
22 changes: 10 additions & 12 deletions site/frontend/src/pages/detailed-query.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,8 +7,8 @@ import {
} from "../self-profile";
import {openTraceInPerfetto} from "../perfetto";

function to_seconds(time) {
return time / 1000000000;
function normalize_value(value) {
return value;
}

function fmt_delta(to, delta, is_integral_delta) {
Expand Down Expand Up @@ -305,14 +305,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
);
Expand All @@ -329,16 +329,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");
Expand Down
15 changes: 8 additions & 7 deletions site/frontend/templates/pages/detailed-query.html
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -79,20 +79,21 @@ <h4>Artifact Size</h4>
<tbody id="artifact-body">
</tbody>
</table>
<p>'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).</p>
<p>'Instructions (%)' is the percentage of instructions executed on this query.</p>
<p><b>Note: self-profile measurements have been <a href="https://github.com/rust-lang/rustc-perf/pull/1647">recently switched</a>
from wall-time to HW counters (instruction count). If comparing with an older artifact, the timings might not be directly comparable.</b></p>
<p>Executions do not include cached executions.</p>
<table>
<thead>
<tr id="table-header">
<th data-sort-idx="1" data-default-sort-dir="1">Query/Function</th>
<th data-sort-idx="10" data-default-sort-dir="-1">Time (%)</th>
<th data-sort-idx="2" data-default-sort-dir="-1">Time (s)</th>
<th data-sort-idx="11" data-default-sort-dir="-1" class="delta">Time delta</th>
<th data-sort-idx="10" data-default-sort-dir="-1">Instructions (%)</th>
<th data-sort-idx="2" data-default-sort-dir="-1">Instructions</th>
<th data-sort-idx="11" data-default-sort-dir="-1" class="delta">Instructions delta</th>
<th data-sort-idx="5" data-default-sort-dir="-1">Executions</th>
<th data-sort-idx="12" data-default-sort-dir="-1" class="delta">Executions delta</th>
<th class="incr" data-sort-idx="7" data-default-sort-dir="-1" title="Incremental loading time">
Incremental loading (s)</th>
<th class="incr" data-sort-idx="7" data-default-sort-dir="-1" title="Incremental loading instructions">
Incremental loading instructions</th>
<th class="incr delta" data-sort-idx="13" data-default-sort-dir="-1">Incremental loading delta</th>
</tr>
</thead>
Expand Down
10 changes: 7 additions & 3 deletions site/src/api.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -471,19 +471,23 @@ pub mod self_profile {
pub artifact_sizes: Option<Vec<ArtifactSize>>,
}

// 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 time: u64,
// 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,
}

Expand Down
12 changes: 6 additions & 6 deletions site/src/request_handlers/self_profile.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -526,7 +526,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));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This will break all historical queries for self-profile data, right? Do we want to perhaps query for both or some other mechanism to not do that?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

An alternative could be to first refactor self profile management (#1896), so that we can e.g. version it, and then have some logic to detect if the archive has the old (walltime) or new (icount) version, and perform the query base on that.

But I'm not sure if people really look at old self-profile results at all, usually we're only interested in them for a brief moment after/before a PR is merged.


// Helper for finding an `ArtifactId` based on a commit sha
let find_aid = |commit: &str| {
Expand All @@ -541,17 +541,17 @@ 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 = get_or_download_self_profile(
ctxt,
commits.first().unwrap().clone(),
bench_name,
profile,
scenario,
cpu_response.next().unwrap().1,
instructions_response.next().unwrap().1,
)
.await?;
let base_self_profile = match commits.get(1) {
Expand All @@ -562,7 +562,7 @@ pub async fn handle_self_profile(
bench_name,
profile,
scenario,
cpu_response.next().unwrap().1,
instructions_response.next().unwrap().1,
)
.await?,
),
Expand Down
4 changes: 2 additions & 2 deletions site/src/self_profile.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -318,7 +318,7 @@ pub(crate) async fn get_or_download_self_profile(
}

fn get_self_profile_data(
cpu_clock: Option<f64>,
total_instructions: Option<f64>,
profile: &analyzeme::AnalysisResults,
) -> ServerResult<self_profile::SelfProfile> {
let total_self_time: Duration = profile.query_data.iter().map(|qd| qd.self_time).sum();
Expand All @@ -345,7 +345,7 @@ fn get_self_profile_data(
time: profile.total_time.as_nanos() as u64,
self_time: total_self_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_self_time.as_secs_f64() / w) * 100.0) as f32)
// sentinel "we couldn't compute this time"
.unwrap_or(-100.0),
Expand Down
Loading