fix detection of releases by api call

This commit is contained in:
Alwin Berger 2024-10-15 16:22:42 +02:00
parent 8f0e54053b
commit 875f87f0c6

View File

@ -221,11 +221,12 @@ fn refine_system_states(mut input: Vec<RawFreeRTOSSystemState>) -> (Vec<ReducedF
}
// Find all task release times. A release is SysTickHandler isr block that moves a task from the delay list to the ready list
// Find all task release times.
fn get_releases(trace: &Vec<ExecInterval>, states: &HashMap<u64, ReducedFreeRTOSSystemState>) -> Vec<(u64, String)> {
let mut ret = Vec::new();
let mut initial_released = false;
for (_n, i) in trace.iter().enumerate() {
// The first release starts from xPortPendSVHandler
if !initial_released && i.start_capture.0 == CaptureEvent::ISREnd && i.start_capture.1 == "xPortPendSVHandler" {
let start_state = states.get(&i.start_state).expect("State not found");
initial_released = true;
@ -234,6 +235,7 @@ fn get_releases(trace: &Vec<ExecInterval>, states: &HashMap<u64, ReducedFreeRTOS
});
continue;
}
// A timed release is SysTickHandler isr block that moves a task from the delay list to the ready list.
if i.start_capture.0 == CaptureEvent::ISRStart && ( i.start_capture.1 == "xPortSysTickHandler" || USR_ISR_SYMBOLS.contains(&i.start_capture.1.as_str()) ) {
// detect race-conditions, get start and end state from the nearest valid intervals
if states.get(&i.start_state).map(|x| x.read_invalid).unwrap_or(true) {
@ -315,6 +317,26 @@ fn get_releases(trace: &Vec<ExecInterval>, states: &HashMap<u64, ReducedFreeRTOS
// }
}
}
// Release driven by an API call. This produces a lot of false positives, as a job may block multiple times per instance. Despite this, aperiodic jobs not be modeled otherwise. If we assume the first release is the real one, we can filter out the rest.
if i.start_capture.0 == CaptureEvent::APIStart {
let api_start = states.get(&i.start_state).expect("State not found");
let api_end = {
let mut end_index = _n;
for n in (_n)..trace.len() {
if trace[n].end_capture.0 == CaptureEvent::APIEnd || trace[n].end_capture.0 == CaptureEvent::End {
end_index = n;
break;
}
};
states.get(&trace[end_index].end_state).expect("State not found")
};
api_end.ready_list_after.iter().for_each(|x| {
if x.task_name != api_start.current_task.task_name && !api_start.ready_list_after.iter().any(|y| x.task_name == y.task_name) {
ret.push((i.end_tick, x.task_name.clone()));
// eprintln!("Task {} released by API call at {:.1}ms", x.task_name, crate::time::clock::tick_to_time(i.end_tick).as_micros() as f32/1000.0);
}
});
}
}
ret
}
@ -352,7 +374,7 @@ fn get_release_response_pairs(rel: &Vec<(u64, String)>, resp: &Vec<(u64, String)
if ready.contains_key(&next_resp.1) {
if ready[&next_resp.1] >= next_resp.0 {
if let Some(lr) = last_response.get(&next_resp.1) {
// eprintln!("Task {} response at {:.1}ms before next release at {:.1}ms. Fallback to last response at {:.1}ms.", next_resp.1, crate::time::clock::tick_to_time(next_resp.0).as_micros() as f32/1000.0, crate::time::clock::tick_to_time(ready[&next_resp.1]).as_micros() as f32/1000.0, crate::time::clock::tick_to_time(*lr).as_micros() as f32/1000.0);
eprintln!("Task {} response at {:.1}ms before next release at {:.1}ms. Fallback to last response at {:.1}ms.", next_resp.1, crate::time::clock::tick_to_time(next_resp.0).as_micros() as f32/1000.0, crate::time::clock::tick_to_time(ready[&next_resp.1]).as_micros() as f32/1000.0, crate::time::clock::tick_to_time(*lr).as_micros() as f32/1000.0);
// Sometimes a task is released immediately after a response. This might not be detected.
// Assume that the release occured with the last response
ret.push((*lr, next_resp.0, next_resp.1.clone()));
@ -368,13 +390,13 @@ fn get_release_response_pairs(rel: &Vec<(u64, String)>, resp: &Vec<(u64, String)
}
} else {
if let Some(lr) = last_response.get(&next_resp.1) {
// eprintln!("Task {} response at {:.1}ms not found in ready list. Fallback to last release at {:.1}ms.", next_resp.1, crate::time::clock::tick_to_time(next_resp.0).as_micros() as f32/1000.0, crate::time::clock::tick_to_time(*lr).as_micros() as f32/1000.0);
eprintln!("Task {} response at {:.1}ms not found in ready list. Fallback to last release at {:.1}ms.", next_resp.1, crate::time::clock::tick_to_time(next_resp.0).as_micros() as f32/1000.0, crate::time::clock::tick_to_time(*lr).as_micros() as f32/1000.0);
// Sometimes a task is released immediately after a response. This might not be detected.
// Assume that the release occured with the last response
ret.push((*lr, next_resp.0, next_resp.1.clone()));
last_response.insert(&next_resp.1, next_resp.0);
} else {
// eprintln!("Task {} response at {:.1}ms not found in ready list", next_resp.1, crate::time::clock::tick_to_time(next_resp.0).as_micros() as f32/1000.0);
eprintln!("Task {} response at {:.1}ms not found in ready list", next_resp.1, crate::time::clock::tick_to_time(next_resp.0).as_micros() as f32/1000.0);
}
}
} else {