Merge pull request #90 from SteelPh0enix/exec-monitoring-test-fix

Tests: Reworked execution time monitoring test to work on x86

testbins/test-execution-monitoring/src/main.rs

@@ -1,5 +1,5 @@
 use aerugo::{
-    logln, Aerugo, Duration, InitApi, RuntimeApi, SystemHardwareConfig, TaskletConfig,
+    log, logln, Aerugo, Duration, InitApi, RuntimeApi, SystemHardwareConfig, TaskletConfig,
     TaskletStorage,
 };
 
@@ -13,17 +13,19 @@ fn monitor(_: (), context: &mut MonitorContext, api: &'static dyn RuntimeApi) {
         let execution_stats = api.get_execution_statistics(tasklet_id);
 
         if let Some(stats) = execution_stats {
-            logln!("Tasklet: #{}", stats.tasklet_id());
+            log!("T:{}|", stats.tasklet_id());
 
             if let Some(min) = stats.minimum_execution_time() {
-                logln!("Min: {}", min.to_millis());
+                log!("{}|", min.to_millis());
             }
             if let Some(max) = stats.maximum_execution_time() {
-                logln!("Max: {}", max.to_millis());
+                log!("{}|", max.to_millis());
             }
             if let Some(avg) = stats.average_execution_time() {
-                logln!("Avg: {}", avg.to_millis());
+                log!("{}", avg.to_millis());
             }
+
+            logln!();
         }
     }
 
@@ -42,9 +44,9 @@ fn task_a(_: (), context: &mut TaskAContext, _: &'static dyn RuntimeApi) {
     context.cnt = context.cnt.wrapping_add(1);
 
     let sleep_time = if context.cnt % 2 == 0 {
-        std::time::Duration::from_millis(10)
+        std::time::Duration::from_millis(100)
     } else {
-        std::time::Duration::from_millis(20)
+        std::time::Duration::from_millis(200)
     };
 
     std::thread::sleep(sleep_time);
@@ -59,9 +61,9 @@ fn task_b(_: (), context: &mut TaskBContext, _: &'static dyn RuntimeApi) {
     context.cnt = context.cnt.wrapping_add(1);
 
     let sleep_time = if context.cnt % 2 == 0 {
-        std::time::Duration::from_millis(20)
+        std::time::Duration::from_millis(200)
     } else {
-        std::time::Duration::from_millis(50)
+        std::time::Duration::from_millis(500)
     };
 
     std::thread::sleep(sleep_time);

tests/requirements/test/test_execution_monitoring.rs

@@ -11,32 +11,152 @@ fn req_test_execution_monitoring() {
     let test_bin_path = build_test_binary("test-execution-monitoring", "testbins")
         .expect("error building test binary");
 
-    Command::new(test_bin_path)
+    let command = Command::new(test_bin_path)
         .timeout(std::time::Duration::from_secs(5))
         .assert()
         .success()
-        .code(0)
-        .stdout(
-            r"Tasklet: #1
-Min: 20
-Max: 20
-Avg: 20
-Tasklet: #2
-Min: 50
-Max: 50
-Avg: 50
-Tasklet: #0
-Min: 0
-Max: 0
-Avg: 0
-Tasklet: #1
-Min: 10
-Max: 20
-Avg: 15
-Tasklet: #2
-Min: 20
-Max: 50
-Avg: 35
-",
-        );
+        .code(0);
+
+    let stdout = &command.get_output().stdout;
+    let output = stdout.iter().map(|&c| c as char).collect::<String>();
+    let output_lines = output.lines().collect::<Vec<&str>>();
+
+    // Because of the fact that this test runs on x86, where hard real-time is usually not a thing,
+    // there must be some tolerance for timing validated by this test.
+    // Considering that the execution times here are short, the margin for error is experimentally
+    // designated to be very wide, to avoid false-positive test failures due to OS scheduling.
+    // In other words, this test is very unreliable on x86 and checks only the existence and API
+    // of execution monitoring, as precise validation of execution times is simply not possible due
+    // to how OS scheduling works.
+
+    let expected_time_range = 100u32..=300;
+    let exec_time = parse_output_line(output_lines[0]);
+    assert_eq!(exec_time.tasklet_id, 1);
+    assert!(
+        expected_time_range.contains(&exec_time.min),
+        "Expected {:?}, got {}",
+        expected_time_range,
+        exec_time.min
+    );
+    assert!(
+        expected_time_range.contains(&exec_time.max),
+        "Expected {:?}, got {}",
+        expected_time_range,
+        exec_time.max
+    );
+    assert!(
+        expected_time_range.contains(&exec_time.avg),
+        "Expected {:?}, got {}",
+        expected_time_range,
+        exec_time.avg
+    );
+
+    // Second line should contain approx 500ms execution of tasklet 2
+    let expected_time_range = 500u32..=650;
+    let exec_time = parse_output_line(output_lines[1]);
+    assert_eq!(exec_time.tasklet_id, 2);
+    assert!(
+        expected_time_range.contains(&exec_time.min),
+        "Expected {:?}, got {}",
+        expected_time_range,
+        exec_time.min
+    );
+    assert!(
+        expected_time_range.contains(&exec_time.max),
+        "Expected {:?}, got {}",
+        expected_time_range,
+        exec_time.max
+    );
+    assert!(
+        expected_time_range.contains(&exec_time.avg),
+        "Expected {:?}, got {}",
+        expected_time_range,
+        exec_time.avg
+    );
+
+    // Third line should contain exactly 0ms execution of tasklet 0, as it wasn't executed
+    let exec_time = parse_output_line(output_lines[2]);
+    assert_eq!(exec_time.tasklet_id, 0);
+    assert_eq!(exec_time.min, 0, "Expected 0, got {}", exec_time.min);
+    assert_eq!(exec_time.max, 0, "Expected 0, got {}", exec_time.max);
+    assert_eq!(exec_time.avg, 0, "Expected 0, got {}", exec_time.avg);
+
+    // Fourth line contains second exec info from tasklet 1. It takes 100ms second time.
+    let exec_time = parse_output_line(output_lines[3]);
+    let min_range = 100..=200;
+    let max_range = 200..=500;
+    let avg_range = 100..=500;
+    assert_eq!(exec_time.tasklet_id, 1);
+    assert!(
+        min_range.contains(&exec_time.min),
+        "Expected {:?}, got {}",
+        min_range,
+        exec_time.min
+    );
+    assert!(
+        max_range.contains(&exec_time.max),
+        "Expected {:?}, got {}",
+        max_range,
+        exec_time.max
+    );
+    assert!(
+        avg_range.contains(&exec_time.avg),
+        "Expected {:?}, got {}",
+        avg_range,
+        exec_time.avg
+    );
+
+    // Fifth line contains second exec info from tasklet 2. It takes 200ms second time.
+    let exec_time = parse_output_line(output_lines[4]);
+    let min_range = 200..=260;
+    let max_range = 500..=650;
+    let avg_range = 200..=650;
+    assert_eq!(exec_time.tasklet_id, 2);
+    assert!(
+        min_range.contains(&exec_time.min),
+        "Expected {:?}, got {}",
+        min_range,
+        exec_time.min
+    );
+    assert!(
+        max_range.contains(&exec_time.max),
+        "Expected {:?}, got {}",
+        max_range,
+        exec_time.max
+    );
+    assert!(
+        avg_range.contains(&exec_time.avg),
+        "Expected {:?}, got {}",
+        avg_range,
+        exec_time.avg
+    );
+}
+
+#[derive(Clone, Copy, Debug, PartialEq, Eq)]
+struct ExecutionTime {
+    pub tasklet_id: u32,
+    pub min: u32,
+    pub max: u32,
+    pub avg: u32,
+}
+
+fn parse_output_line(line: &str) -> ExecutionTime {
+    let line_split = line.split('|').collect::<Vec<&str>>();
+
+    // Sanity check
+    assert_eq!(line_split.len(), 4);
+    assert!(line_split[0].starts_with("T:"));
+
+    // 3rd char is tasklet ID
+    let tasklet_id = line_split[0].chars().nth(2).unwrap().to_digit(10).unwrap();
+    let min = line_split[1].parse::<u32>().unwrap();
+    let max = line_split[2].parse::<u32>().unwrap();
+    let avg = line_split[3].parse::<u32>().unwrap();
+
+    ExecutionTime {
+        tasklet_id,
+        min,
+        max,
+        avg,
+    }
 }