Commit 77308369 authored by RILLING Louis's avatar RILLING Louis
Browse files

tansiv-client: Add debug logs in the deadline handler

parent f57454cc
......@@ -4,7 +4,7 @@ use connector::{Connector, ConnectorImpl, MsgIn, MsgOut};
pub use error::Error;
use libc;
#[allow(unused_imports)]
use log::{debug, error};
use log::{debug, info, error};
use output_msg_set::OutputMsgSet;
use std::sync::{Arc, Mutex, Once};
use std::time::Duration;
......@@ -135,6 +135,7 @@ impl Context {
self.start_once.call_once(|| res = (|| {
let mut connector = self.connector.lock().unwrap();
let msg = connector.recv()?;
deadline_handler_debug!("Context::start() received msg = {:?}", msg);
// The deadline handler can fire and try to lock connector at any time once self.0.start()
// is called so we must unlock connector before.
drop(connector);
......@@ -145,6 +146,9 @@ impl Context {
}
})());
if res.is_err() {
error!("Context::start() failed: {:?}", res);
}
res
}
......@@ -159,34 +163,41 @@ impl Context {
let messages = self.outgoing_messages.drain();
let previous_deadline = self.timer_context.simulation_previous_deadline();
let current_deadline = self.timer_context.simulation_next_deadline();
deadline_handler_debug!("Context::at_deadline() current_deadline = {:?}", current_deadline);
for (send_time, src, dst, payload) in messages {
deadline_handler_debug!("Context::at_deadline() message to send (send_time = {:?}, src = {}, dst = {}, payload = {})", send_time, vsg_address::to_ipv4addr(src), vsg_address::to_ipv4addr(dst), payload);
let send_time = if send_time < previous_deadline {
// This message was time-stamped before the previous deadline but inserted after.
// Fix the timestamp to stay between the deadlines.
deadline_handler_debug!("Context::at_deadline() fixing send_time to {:?}", previous_deadline);
previous_deadline
} else {
if send_time >= current_deadline {
// The kernel was too slow to fire the timer...
error!("send_time = {:?} is beyond current_deadline = {:?}! Aborting", send_time, current_deadline);
return AfterDeadline::EndSimulation;
}
send_time
};
if let Err(_e) = connector.send(MsgOut::SendPacket(send_time, src, dst, payload)) {
// error!("send(SendPacket) failed: {}", _e);
error!("send(SendPacket) failed: {}", _e);
return AfterDeadline::EndSimulation;
}
}
// Second, notify that we reached the deadline
deadline_handler_debug!("Context::at_deadline() sending AtDeadline");
if let Err(_e) = connector.send(MsgOut::AtDeadline) {
// error!("send(AtDeadline) failed: {}", _e);
error!("send(AtDeadline) failed: {}", _e);
return AfterDeadline::EndSimulation;
}
// Third, receive messages from others, followed by next deadline
let input_queue = &self.input_queue;
let may_notify = input_queue.is_empty();
deadline_handler_debug!("Context::at_deadline() may_notify = {}", may_notify);
let after_deadline = loop {
let msg = connector.recv();
......@@ -195,25 +206,28 @@ impl Context {
break after_deadline;
},
Err(_e) => {
// error!("recv failed: {}", _e);
error!("recv failed: {}", _e);
break AfterDeadline::EndSimulation;
}
}
};
if may_notify && !input_queue.is_empty() {
deadline_handler_debug!("Context::at_deadline() calling recv_callback()");
(self.recv_callback)();
}
deadline_handler_debug!("Context::at_deadline() after_deadline = {:?}", after_deadline);
after_deadline
}
fn handle_actor_msg(&self, msg: MsgIn) -> Option<AfterDeadline> {
deadline_handler_debug!("Context::handle_actor_msg() received msg = {}", msg);
match msg {
MsgIn::DeliverPacket(src, dst, packet) => {
// let size = packet.len();
let size = packet.len();
if self.input_queue.push(Packet::new(src, dst, packet)).is_err() {
// info!("Dropping input packet from {} of {} bytes", src, size);
info!("Dropping input packet from {} of {} bytes", src, size);
}
None
},
......
......@@ -122,14 +122,16 @@ impl TimerContext {
fn freeze_time(&self) -> StdDuration {
let now = clock::gettime(Self::CLOCK).unwrap();
deadline_handler_debug!("TimerContext::freeze_time() system time = {:?}", now);
*self.current_deadline.lock().unwrap() = self.application_now();
self.at_deadline.store(true, Ordering::Release);
// DEBUG: We can observe here the difference between 'now' and self.next_deadline_raw
deadline_handler_debug!("TimerContext::freeze_time() jitter (now - next_deadline_raw) = {}", Duration::from_std(now).unwrap() - Duration::from_std(*self.next_deadline_raw.lock().unwrap()).unwrap());
now
}
fn thaw_time_to_deadline(&self, freeze_time: Option<StdDuration>, time_to_deadline: StdDuration) -> Result<()> {
let now = clock::gettime(Self::CLOCK).unwrap();
deadline_handler_debug!("TimerContext::thaw_time_to_deadline() system time = {:?}", now);
let new_next_deadline_raw = now + time_to_deadline;
// DEBUG only
......@@ -142,6 +144,7 @@ impl TimerContext {
if let Some(freeze_time) = freeze_time {
let elapsed_time = Duration::from_std(now - freeze_time).unwrap();
deadline_handler_debug!("TimerContext::thaw_time_to_deadline() elapsed_time = {}", elapsed_time);
self.application_time.adjust(|offset| offset - elapsed_time);
self.simulation_time.adjust(|offset| offset - elapsed_time);
......@@ -150,9 +153,11 @@ impl TimerContext {
let current_deadline = *self.current_deadline.lock().unwrap();
// Here is where the application time reference is recorded
let local_now = chrono::offset::Local::now().naive_local();
deadline_handler_debug!("TimerContext::thaw_time_to_deadline() application time offset = {}", current_deadline - local_now);
self.application_time.adjust(|_| current_deadline - local_now);
// Time starts at 0 in global simulation time.
deadline_handler_debug!("TimerContext::thaw_time_to_deadline() simulation time offset = -{:?}", now);
self.simulation_time.adjust(|_| -Duration::from_std(now).unwrap());
}
......@@ -160,6 +165,7 @@ impl TimerContext {
let next_deadline_val = *next_deadline;
*self.prev_deadline.lock().unwrap() = next_deadline_val;
*next_deadline = next_deadline_val + time_to_deadline;
deadline_handler_debug!("TimerContext::thaw_time_to_deadline() set next_deadline = {:?}", next_deadline);
// First call can be interrupted by the signal handler and deadlock
drop(next_deadline);
......@@ -167,6 +173,7 @@ impl TimerContext {
// The first call of ::thaw_time_to_deadline() is not in signal handler context and can be
// interrupted by the signal handler, so make sure that everything is already up to date
deadline_handler_debug!("TimerContext::thaw_time_to_deadline() setting timer to fire at {:?}", new_next_deadline_raw);
timer::settime(self.timer_id, timer::SettimeFlags::AbsoluteTime, None, new_next_deadline_raw)?;
Ok(())
}
......@@ -260,6 +267,7 @@ pub fn register(context: &Arc<Context>) -> Result<()> {
extern "C" fn deadline_handler(_: libc::c_int) {
use crate::AfterDeadline;
deadline_handler_debug!("deadline_handler() called");
if let Some(context) = CONTEXT.read().unwrap().upgrade() {
let freeze_time = context.timer_context.freeze_time();
match context.at_deadline() {
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment