fortrangoingonforty/afs-ld / afcd90f

Browse files

Report parity matrix timings

Authored by mfwolffe <wolffemf@dukes.jmu.edu>
SHA
afcd90fd76b1c6845c9b8d72e92d2cd087ab55c4
Parents
e41e4b6
Tree
49b10ac

2 changed files

StatusFile+-
M tests/common/harness.rs 16 14
M tests/parity_matrix.rs 159 58
tests/common/harness.rsmodified
@@ -116,11 +116,13 @@ struct ArtifactSpec {
116116
117117
 #[derive(Debug, Clone, Copy, PartialEq, Eq)]
118118
 enum ArtifactKind {
119
-    ClangDylib,
120
-    ClangArchive,
121
-    ClangReexportDylib,
119
+    Dylib,
120
+    Archive,
121
+    ReexportDylib,
122122
 }
123123
124
+type SymbolPartitions = (Vec<String>, Vec<String>, Vec<String>);
125
+
124126
 pub struct LinkOutputs {
125127
     pub ours: Vec<u8>,
126128
     pub theirs: Vec<u8>,
@@ -509,9 +511,9 @@ pub fn link_both(case: &LinkCase) -> Result<LinkOutputs, String> {
509511
             .map_err(|e| format!("read artifact src {}: {e}", src.display()))?;
510512
         let out = work_dir.join(&artifact.out_name);
511513
         match artifact.kind {
512
-            ArtifactKind::ClangDylib => compile_dylib_c(&src_contents, &out)?,
513
-            ArtifactKind::ClangArchive => compile_archive_c(&src_contents, &out)?,
514
-            ArtifactKind::ClangReexportDylib => {
514
+            ArtifactKind::Dylib => compile_dylib_c(&src_contents, &out)?,
515
+            ArtifactKind::Archive => compile_archive_c(&src_contents, &out)?,
516
+            ArtifactKind::ReexportDylib => {
515517
                 let dep_name = artifact.dep_name.as_ref().ok_or_else(|| {
516518
                     format!(
517519
                         "missing reexport dependency for artifact {}",
@@ -1390,7 +1392,7 @@ fn read_artifacts(path: &Path) -> Result<Vec<ArtifactSpec>, String> {
13901392
                         path.display()
13911393
                     ));
13921394
                 }
1393
-                (ArtifactKind::ClangDylib, None)
1395
+                (ArtifactKind::Dylib, None)
13941396
             }
13951397
             "clang_archive" => {
13961398
                 if dep_name.is_some() {
@@ -1399,7 +1401,7 @@ fn read_artifacts(path: &Path) -> Result<Vec<ArtifactSpec>, String> {
13991401
                         path.display()
14001402
                     ));
14011403
                 }
1402
-                (ArtifactKind::ClangArchive, None)
1404
+                (ArtifactKind::Archive, None)
14031405
             }
14041406
             "clang_reexport_dylib" => {
14051407
                 let dep_name = dep_name.ok_or_else(|| {
@@ -1408,7 +1410,7 @@ fn read_artifacts(path: &Path) -> Result<Vec<ArtifactSpec>, String> {
14081410
                         path.display()
14091411
                     )
14101412
                 })?;
1411
-                (ArtifactKind::ClangReexportDylib, Some(dep_name))
1413
+                (ArtifactKind::ReexportDylib, Some(dep_name))
14121414
             }
14131415
             other => return Err(format!("unknown artifact kind `{other}`")),
14141416
         };
@@ -1592,10 +1594,10 @@ fn tolerated_mask(bytes: &[u8]) -> Vec<Option<&'static str>> {
15921594
                 }
15931595
             }
15941596
             LC_ID_DYLIB | LC_LOAD_DYLIB | LC_LOAD_WEAK_DYLIB | LC_REEXPORT_DYLIB
1595
-            | LC_LOAD_UPWARD_DYLIB => {
1596
-                if cmdsize >= 16 {
1597
-                    mark_range(&mut mask, cursor + 12, cursor + 16, "dylib timestamp");
1598
-                }
1597
+            | LC_LOAD_UPWARD_DYLIB
1598
+                if cmdsize >= 16 =>
1599
+            {
1600
+                mark_range(&mut mask, cursor + 12, cursor + 16, "dylib timestamp");
15991601
             }
16001602
             _ => {}
16011603
         }
@@ -1765,7 +1767,7 @@ fn canonical_export_records(bytes: &[u8]) -> Result<Vec<CanonicalExportRecord>,
17651767
     Ok(out)
17661768
 }
17671769
1768
-fn symbol_partition_names(bytes: &[u8]) -> Result<(Vec<String>, Vec<String>, Vec<String>), String> {
1770
+fn symbol_partition_names(bytes: &[u8]) -> Result<SymbolPartitions, String> {
17691771
     let (symtab, dysymtab) = symtab_and_dysymtab(bytes)?;
17701772
     let symbols =
17711773
         parse_nlist_table(bytes, symtab.symoff, symtab.nsyms).map_err(|e| e.to_string())?;
tests/parity_matrix.rsmodified
@@ -54,6 +54,7 @@ fn parity_corpus() {
5454
         }
5555
         case_reports.push((case, report));
5656
     }
57
+    print_timing_summary(started.elapsed(), &case_reports);
5758
5859
     if let Some(dir) = artifact_dir.as_ref() {
5960
         write_index_artifact(dir, &case_reports).expect("write parity index");
@@ -80,24 +81,40 @@ fn parity_corpus() {
8081
 #[derive(Debug)]
8182
 struct CaseStep {
8283
     name: &'static str,
84
+    duration: Duration,
8385
     error: Option<String>,
8486
 }
8587
8688
 #[derive(Debug, Default)]
8789
 struct CaseReport {
8890
     steps: Vec<CaseStep>,
91
+    elapsed: Duration,
8992
 }
9093
9194
 impl CaseReport {
9295
     fn push(&mut self, name: &'static str, result: Result<(), String>) -> bool {
96
+        self.push_timed(name, Duration::ZERO, result)
97
+    }
98
+
99
+    fn push_timed(
100
+        &mut self,
101
+        name: &'static str,
102
+        duration: Duration,
103
+        result: Result<(), String>,
104
+    ) -> bool {
93105
         match result {
94106
             Ok(()) => {
95
-                self.steps.push(CaseStep { name, error: None });
107
+                self.steps.push(CaseStep {
108
+                    name,
109
+                    duration,
110
+                    error: None,
111
+                });
96112
                 true
97113
             }
98114
             Err(error) => {
99115
                 self.steps.push(CaseStep {
100116
                     name,
117
+                    duration,
101118
                     error: Some(error),
102119
                 });
103120
                 false
@@ -105,15 +122,32 @@ impl CaseReport {
105122
         }
106123
     }
107124
125
+    fn measure<F>(&mut self, name: &'static str, action: F) -> bool
126
+    where
127
+        F: FnOnce() -> Result<(), String>,
128
+    {
129
+        let started = Instant::now();
130
+        let result = action();
131
+        self.push_timed(name, started.elapsed(), result)
132
+    }
133
+
134
+    fn finish(&mut self, elapsed: Duration) {
135
+        self.elapsed = elapsed;
136
+    }
137
+
108138
     fn passed(&self) -> bool {
109139
         self.steps.iter().all(|step| step.error.is_none())
110140
     }
111141
142
+    fn slowest_step(&self) -> Option<&CaseStep> {
143
+        self.steps.iter().max_by_key(|step| step.duration)
144
+    }
145
+
112146
     fn error_message(&self, case_name: &str) -> Option<String> {
113147
         self.steps.iter().find_map(|step| {
114
-            step.error.as_ref().map(|error| {
115
-                format!("[{case_name}] {} failed:\n{}", step.name, error)
116
-            })
148
+            step.error
149
+                .as_ref()
150
+                .map(|error| format!("[{case_name}] {} failed:\n{}", step.name, error))
117151
         })
118152
     }
119153
 }
@@ -132,85 +166,84 @@ fn case_report_error_message_includes_case_name() {
132166
 }
133167
134168
 fn run_case(case: &LinkCase) -> CaseReport {
169
+    let case_started = Instant::now();
135170
     let mut report = CaseReport::default();
171
+    let link_started = Instant::now();
136172
     let outputs = match link_both(case) {
137173
         Ok(outputs) => {
138
-            report.push("link", Ok(()));
174
+            report.push_timed("link", link_started.elapsed(), Ok(()));
139175
             outputs
140176
         }
141177
         Err(error) => {
142
-            report.push(
178
+            report.push_timed(
143179
                 "link",
180
+                link_started.elapsed(),
144181
                 Err(format!(
145182
                     "failed to link parity case from {}:\n{}",
146183
                     case.dir.display(),
147184
                     error
148185
                 )),
149186
             );
150
-            return report;
187
+            return finish_case(report, case_started);
151188
         }
152189
     };
153190
154
-    if !report.push(
155
-        "load-command ids",
156
-        compare_command_ids(&outputs.ours, &outputs.theirs, &case.ignored_load_commands),
157
-    ) {
158
-        return report;
191
+    if !report.measure("load-command ids", || {
192
+        compare_command_ids(&outputs.ours, &outputs.theirs, &case.ignored_load_commands)
193
+    }) {
194
+        return finish_case(report, case_started);
159195
     }
160
-    if !report.push(
161
-        "command details",
162
-        compare_command_details(&outputs.ours, &outputs.theirs, &case.command_checks),
163
-    ) {
164
-        return report;
196
+    if !report.measure("command details", || {
197
+        compare_command_details(&outputs.ours, &outputs.theirs, &case.command_checks)
198
+    }) {
199
+        return finish_case(report, case_started);
165200
     }
166
-    if !report.push(
167
-        "afs-ld absent commands",
168
-        ensure_absent_load_commands(&outputs.ours, &case.absent_load_commands, "afs-ld"),
169
-    ) {
170
-        return report;
201
+    if !report.measure("afs-ld absent commands", || {
202
+        ensure_absent_load_commands(&outputs.ours, &case.absent_load_commands, "afs-ld")
203
+    }) {
204
+        return finish_case(report, case_started);
171205
     }
172
-    if !report.push(
173
-        "Apple absent commands",
174
-        ensure_absent_load_commands(&outputs.theirs, &case.absent_load_commands, "Apple ld"),
175
-    ) {
176
-        return report;
206
+    if !report.measure("Apple absent commands", || {
207
+        ensure_absent_load_commands(&outputs.theirs, &case.absent_load_commands, "Apple ld")
208
+    }) {
209
+        return finish_case(report, case_started);
177210
     }
178
-    if !report.push(
179
-        "afs-ld absent sections",
180
-        ensure_absent_sections(&outputs.ours, &case.absent_sections, "afs-ld"),
181
-    ) {
182
-        return report;
211
+    if !report.measure("afs-ld absent sections", || {
212
+        ensure_absent_sections(&outputs.ours, &case.absent_sections, "afs-ld")
213
+    }) {
214
+        return finish_case(report, case_started);
183215
     }
184
-    if !report.push(
185
-        "Apple absent sections",
186
-        ensure_absent_sections(&outputs.theirs, &case.absent_sections, "Apple ld"),
187
-    ) {
188
-        return report;
216
+    if !report.measure("Apple absent sections", || {
217
+        ensure_absent_sections(&outputs.theirs, &case.absent_sections, "Apple ld")
218
+    }) {
219
+        return finish_case(report, case_started);
189220
     }
190
-    if !report.push(
191
-        "section parity",
221
+    if !report.measure("section parity", || {
192222
         compare_sections(
193223
             &outputs.ours,
194224
             &outputs.theirs,
195225
             &case.section_checks,
196226
             &case.case_tolerances,
197
-        ),
198
-    ) {
199
-        return report;
227
+        )
228
+    }) {
229
+        return finish_case(report, case_started);
200230
     }
201
-    if !report.push(
202
-        "page-ref parity",
203
-        compare_page_refs(&outputs.ours, &outputs.theirs, &case.page_ref_checks),
204
-    ) {
205
-        return report;
231
+    if !report.measure("page-ref parity", || {
232
+        compare_page_refs(&outputs.ours, &outputs.theirs, &case.page_ref_checks)
233
+    }) {
234
+        return finish_case(report, case_started);
206235
     }
207236
     if !case.runtime_args.is_empty() || case.dir.join("runtime.txt").exists() {
208
-        report.push(
209
-            "runtime parity",
210
-            compare_runtime(&outputs.our_path, &outputs.their_path, &case.runtime_args),
211
-        );
237
+        report.measure("runtime parity", || {
238
+            compare_runtime(&outputs.our_path, &outputs.their_path, &case.runtime_args)
239
+        });
212240
     }
213241
242
+    finish_case(report, case_started)
243
+}
244
+
245
+fn finish_case(mut report: CaseReport, started: Instant) -> CaseReport {
246
+    report.finish(started.elapsed());
214247
     report
215248
 }
216249
@@ -228,16 +261,22 @@ fn write_case_artifact(dir: &Path, case: &LinkCase, report: &CaseReport) -> Resu
228261
         if report.passed() { "ok" } else { "fail" },
229262
         if report.passed() { "PASS" } else { "FAIL" }
230263
     ));
264
+    html.push_str(&format!(
265
+        "<p>Total: <strong>{}</strong></p>",
266
+        format_duration(report.elapsed)
267
+    ));
231268
     html.push_str("<h2>Steps</h2><ul>");
232269
     for step in &report.steps {
233270
         match &step.error {
234271
             None => html.push_str(&format!(
235
-                "<li><span class=\"ok\">PASS</span> {}</li>",
236
-                escape_html(step.name)
272
+                "<li><span class=\"ok\">PASS</span> {} <span class=\"time\">{}</span></li>",
273
+                escape_html(step.name),
274
+                format_duration(step.duration)
237275
             )),
238276
             Some(error) => html.push_str(&format!(
239
-                "<li><span class=\"fail\">FAIL</span> {}<pre>{}</pre></li>",
277
+                "<li><span class=\"fail\">FAIL</span> {} <span class=\"time\">{}</span><pre>{}</pre></li>",
240278
                 escape_html(step.name),
279
+                format_duration(step.duration),
241280
                 escape_html(error)
242281
             )),
243282
         }
@@ -258,16 +297,32 @@ fn write_case_artifact(dir: &Path, case: &LinkCase, report: &CaseReport) -> Resu
258297
 fn write_index_artifact(dir: &Path, cases: &[(LinkCase, CaseReport)]) -> Result<(), String> {
259298
     let mut html = String::new();
260299
     html.push_str("<!doctype html><html><head><meta charset=\"utf-8\">");
261
-    html.push_str("<title>Parity Matrix</title><style>body{font-family:ui-monospace,Menlo,monospace;padding:2rem;} .ok{color:#0a0;} .fail{color:#a00;}</style></head><body>");
262
-    html.push_str("<h1>Parity Matrix</h1><ul>");
300
+    html.push_str("<title>Parity Matrix</title><style>body{font-family:ui-monospace,Menlo,monospace;padding:2rem;} .ok{color:#0a0;} .fail{color:#a00;} .time{color:#57606a;} table{border-collapse:collapse;margin:1rem 0;} td,th{border:1px solid #d0d7de;padding:.35rem .6rem;text-align:left;}</style></head><body>");
301
+    html.push_str("<h1>Parity Matrix</h1>");
302
+    html.push_str("<h2>Slowest Cases</h2><table><thead><tr><th>Case</th><th>Total</th><th>Slowest Step</th></tr></thead><tbody>");
303
+    for (case, report) in slowest_cases(cases, 10) {
304
+        let slowest = report
305
+            .slowest_step()
306
+            .map(|step| format!("{} {}", step.name, format_duration(step.duration)))
307
+            .unwrap_or_else(|| "n/a".to_string());
308
+        html.push_str(&format!(
309
+            "<tr><td><a href=\"{}.html\">{}</a></td><td>{}</td><td>{}</td></tr>",
310
+            slug(&case.name),
311
+            escape_html(&case.name),
312
+            format_duration(report.elapsed),
313
+            escape_html(&slowest)
314
+        ));
315
+    }
316
+    html.push_str("</tbody></table><h2>Cases</h2><ul>");
263317
     for (case, report) in cases {
264318
         let slug = slug(&case.name);
265319
         html.push_str(&format!(
266
-            "<li><a href=\"{}.html\">{}</a> <strong class=\"{}\">{}</strong></li>",
320
+            "<li><a href=\"{}.html\">{}</a> <strong class=\"{}\">{}</strong> <span class=\"time\">{}</span></li>",
267321
             slug,
268322
             escape_html(&case.name),
269323
             if report.passed() { "ok" } else { "fail" },
270
-            if report.passed() { "PASS" } else { "FAIL" }
324
+            if report.passed() { "PASS" } else { "FAIL" },
325
+            format_duration(report.elapsed)
271326
         ));
272327
     }
273328
     html.push_str("</ul></body></html>");
@@ -275,6 +330,43 @@ fn write_index_artifact(dir: &Path, cases: &[(LinkCase, CaseReport)]) -> Result<
275330
     fs::write(&path, html).map_err(|e| format!("write {}: {e}", path.display()))
276331
 }
277332
333
+fn print_timing_summary(elapsed: Duration, cases: &[(LinkCase, CaseReport)]) {
334
+    eprintln!(
335
+        "parity matrix timing: {} case(s) in {}",
336
+        cases.len(),
337
+        format_duration(elapsed)
338
+    );
339
+    for (case, report) in slowest_cases(cases, 10) {
340
+        let slowest = report
341
+            .slowest_step()
342
+            .map(|step| {
343
+                format!(
344
+                    "; slowest step: {} {}",
345
+                    step.name,
346
+                    format_duration(step.duration)
347
+                )
348
+            })
349
+            .unwrap_or_default();
350
+        eprintln!(
351
+            "  {:>9} {}{}",
352
+            format_duration(report.elapsed),
353
+            case.name,
354
+            slowest
355
+        );
356
+    }
357
+}
358
+
359
+fn slowest_cases(cases: &[(LinkCase, CaseReport)], limit: usize) -> Vec<(&LinkCase, &CaseReport)> {
360
+    let mut timed: Vec<_> = cases.iter().map(|(case, report)| (case, report)).collect();
361
+    timed.sort_by(|a, b| {
362
+        b.1.elapsed
363
+            .cmp(&a.1.elapsed)
364
+            .then_with(|| a.0.name.cmp(&b.0.name))
365
+    });
366
+    timed.truncate(limit);
367
+    timed
368
+}
369
+
278370
 fn slug(name: &str) -> String {
279371
     name.chars()
280372
         .map(|ch| {
@@ -293,6 +385,15 @@ fn parity_matrix_time_limit() -> Option<Duration> {
293385
     Some(Duration::from_secs(seconds))
294386
 }
295387
388
+fn format_duration(duration: Duration) -> String {
389
+    let millis = duration.as_secs_f64() * 1000.0;
390
+    if millis >= 1000.0 {
391
+        format!("{:.2}s", duration.as_secs_f64())
392
+    } else {
393
+        format!("{millis:.1}ms")
394
+    }
395
+}
396
+
296397
 fn escape_html(text: &str) -> String {
297398
     text.replace('&', "&amp;")
298399
         .replace('<', "&lt;")