Parse output

pageserver/src/bin/psbench.rs

@@ -2,15 +2,13 @@
 //!
 //! Usually it's easier to write python perf tests, but here the performance
 //! of the tester matters, and the API is easier to work with from rust.
-use std::{collections::{HashMap, HashSet}, io::{BufRead, BufReader, Cursor}, net::SocketAddr, ops::AddAssign, time::Duration};
-use byteorder::ReadBytesExt;
-use itertools::Itertools;
+use std::{collections::HashSet, io::{BufRead, BufReader, Cursor}, time::Duration};
 use pageserver::wal_metadata::{Page, WalEntryMetadata};
 use tokio::io::{AsyncReadExt, AsyncWriteExt};
-use bytes::{BufMut, Bytes, BytesMut};
+use bytes::{BufMut, BytesMut};
 use clap::{App, Arg};
 use std::fs::File;
-use zenith_utils::{GIT_VERSION, lsn::Lsn, pq_proto::{BeMessage, BeParameterStatusMessage, FeMessage}};
+use zenith_utils::{GIT_VERSION, lsn::Lsn, pq_proto::{BeMessage, FeMessage}};
 use std::time::Instant;
 
 use anyhow::Result;
@@ -135,13 +133,10 @@ async fn main() -> Result<()> {
     let affected_pages: HashSet<_> = wal_metadata.iter().map(|m| m.affected_pages.clone())
         .flatten().collect();
     let latest_lsn = wal_metadata.iter().map(|m| m.lsn).max().unwrap();
-    println!("Total pages: {}", affected_pages.len());
-    println!("total wal: {}", wal_metadata.len());
-    println!("total wal bytes: {}", total_wal_size);
 
     // Get all latest pages
     let mut durations: Vec<Duration> = vec![];
-    for page in affected_pages {
+    for page in &affected_pages {
         let start = Instant::now();
         let _page_bytes = get_page(&mut socket, &latest_lsn, &page, true).await?;
         let duration = start.elapsed();
@@ -150,10 +145,14 @@ async fn main() -> Result<()> {
     }
 
     durations.sort();
-    println!("Fastest: {:?}", durations.first().unwrap());
-    println!("Median: {:?}", durations[durations.len() / 2]);
-    println!("99th percentile: {:?}", durations[durations.len() - 1 - durations.len() / 100]);
-    println!("Slowest: {:?}", durations.last().unwrap());
+    // Results are a space separated table of "metric_name value unit", for ease of parsing
+    println!("test_param num_pages {}", affected_pages.len());
+    println!("test_param num_wal_entries {}", wal_metadata.len());
+    println!("test_param total_wal_size {} bytes", total_wal_size);
+    println!("lower_is_better fastest {:?} microseconds", durations.first().unwrap().as_micros());
+    println!("lower_is_better median {:?} microseconds", durations[durations.len() / 2].as_micros());
+    println!("lower_is_better p99 {:?} microseconds", durations[durations.len() - 1 - durations.len() / 100].as_micros());
+    println!("lower_is_better slowest {:?} microseconds", durations.last().unwrap().as_micros());
 
     Ok(())
 }

test_runner/fixtures/zenith_fixtures.py

@@ -618,7 +618,7 @@ class ZenithEnv:
         psbench_binpath = os.path.join(str(zenith_binpath), 'psbench')
         tenant_hex = self.initial_tenant.hex
         args = [psbench_binpath, wal_metadata_filename, tenant_hex, timeline]
-        subprocess.run(args)
+        return subprocess.run(args, capture_output=True).stdout.decode("UTF-8").strip()
 
     @cached_property
     def auth_keys(self) -> AuthKeys:

test_runner/performance/test_pageserver.py

@@ -38,4 +38,11 @@ def test_get_page(zenith_simple_env: ZenithEnv,
 
             pscur.execute(f"checkpoint {env.initial_tenant.hex} {timeline} 0")
 
-    env.run_psbench(timeline)
+    output = env.run_psbench(timeline)
+    for line in output.split("\n"):
+        tokens = line.split(" ")
+        report = tokens[0]
+        name = tokens[1]
+        value = tokens[2]
+        unit = tokens[3] if len(tokens) > 3 else ""
+        zenbenchmark.record(name, value, unit, report=report)