#![cfg(feature = "progress-updates")]
use crate::{ConstantTimeResultForPath, PathStatistics};
use colored::*;
use crossterm::{QueueableCommand, cursor, terminal};
use haybale::{Config, Result, State};
use haybale::backend::Backend;
use std::convert::TryInto;
use std::io::{Write, stdout, Stdout};
use std::sync::mpsc;
use std::thread;
use std::time::{Duration, Instant};
use log4rs::encode::pattern::PatternEncoder;
use log4rs::encode::Encode;
use log4rs::encode::writer::simple::SimpleWriter;
struct ProgressDisplayState {
rx: mpsc::Receiver<ProgressMsg>,
termination_rx: mpsc::Receiver<()>,
path_stats: PathStatistics,
backtrack_points_remaining: usize,
warnings_generated: usize,
rows_of_log: u16,
rows_of_stats: u16,
rows_of_loc: u16,
terminal_cols: u16,
start_time: Instant,
elapsed_secs: u64,
}
enum ProgressMsg {
ProgressUpdate {
llvm_location: String,
src_location: String,
num_backtrack_points: usize,
},
LogMessage {
msg: Vec<u8>,
level: log::Level,
},
PathCompleted(ConstantTimeResultForPath),
}
impl ProgressDisplayState {
fn initialize(rx: mpsc::Receiver<ProgressMsg>, termination_rx: mpsc::Receiver<()>, funcname: &str) -> Self {
let mut pdstate = Self {
rx,
termination_rx,
path_stats: PathStatistics::new(),
backtrack_points_remaining: 0,
warnings_generated: 0,
rows_of_log: 1,
rows_of_stats: 2,
rows_of_loc: 1,
terminal_cols: {
let (cols, _) = terminal::size().unwrap();
cols
},
start_time: Instant::now(),
elapsed_secs: 0,
};
println!("Progress on {}:", funcname);
println!();
print!("{}", pdstate.path_stats);
println!();
pdstate.print_backtrack_line();
println!();
pdstate.print_warnings_line();
println!("Most recent log message (INFO or higher):");
println!(" <no messages yet>");
println!();
println!("Currently at location:");
{
println!();
stdout().queue(cursor::MoveToPreviousLine(1)).unwrap();
}
let (_, loc_start_row) = cursor::position().unwrap();
println!(" <allocating/initializing global variables and function arguments>");
let loc_end_row = {
let (_, blank_line_row) = cursor::position().unwrap();
blank_line_row - 1
};
pdstate.rows_of_loc = loc_end_row - loc_start_row + 1;
println!();
pdstate.print_time_elapsed_line();
pdstate
}
fn listen(&mut self) {
loop {
if self.termination_rx.try_recv().is_ok() {
self.finalize();
break
} else if let Ok(msg) = self.rx.try_recv() {
self.handle_msg(msg)
} else {
thread::sleep(Duration::from_millis(5))
}
self.update_elapsed_time();
}
}
fn handle_msg(&mut self, msg: ProgressMsg) {
match msg {
ProgressMsg::ProgressUpdate { llvm_location, src_location, num_backtrack_points } => {
match self.rx.try_recv() {
Ok(new_update@ProgressMsg::ProgressUpdate { .. }) => {
self.handle_msg(new_update);
},
Ok(other_msg) => {
self.update_progress(&llvm_location, &src_location, num_backtrack_points);
self.handle_msg(other_msg);
},
_ => {
self.update_progress(&llvm_location, &src_location, num_backtrack_points);
},
}
},
ProgressMsg::LogMessage { msg, level } => {
match self.rx.try_recv() {
Ok(new_logmsg@ProgressMsg::LogMessage { .. }) => {
if level <= log::Level::Warn {
self.increment_and_update_warning_count();
}
self.handle_msg(new_logmsg);
},
Ok(other_msg) => {
self.process_log_message(&msg, level);
self.handle_msg(other_msg);
},
_ => {
self.process_log_message(&msg, level);
},
}
},
ProgressMsg::PathCompleted(ctresult) => self.process_path_result(&ctresult),
}
}
fn print_backtrack_line(&self) {
println!("backtrack points remaining: {}", self.backtrack_points_remaining);
}
fn print_warnings_line(&self) {
print!("warnings generated: ");
if self.warnings_generated > 0 {
println!("{} (see detailed logs)", self.warnings_generated.to_string().yellow())
} else {
println!("0");
}
}
fn print_time_elapsed_line(&self) {
print!("Time elapsed: ");
if self.elapsed_secs < 60 {
println!("{}s", self.elapsed_secs);
} else {
let elapsed_minutes = self.elapsed_secs / 60;
let secs_remainder = self.elapsed_secs % 60;
if elapsed_minutes < 60 {
println!("{}m {}s", elapsed_minutes, secs_remainder);
} else {
let elapsed_hours = elapsed_minutes / 60;
let mins_remainder = elapsed_minutes % 60;
println!("{}h {}m {}s", elapsed_hours, mins_remainder, secs_remainder);
}
}
}
fn update_progress(&mut self, llvm_loc: &str, src_loc: &str, num_backtrack_points: usize) {
let mut stdout = stdout();
self.update_location(llvm_loc, src_loc, &mut stdout);
self.update_backtrack_points(num_backtrack_points, &mut stdout);
stdout.flush().unwrap();
}
fn update_location(&mut self, llvm_loc: &str, src_loc: &str, stdout: &mut Stdout) {
stdout
.queue(cursor::MoveToPreviousLine(2 + self.rows_of_loc)).unwrap()
.queue(terminal::Clear(terminal::ClearType::FromCursorDown)).unwrap()
.queue(cursor::MoveToColumn(0)).unwrap();
let llvm_loc_string = format!("LLVM location: {}", llvm_loc);
let llvm_loc_string_len: u16 = llvm_loc_string.len().try_into().unwrap_or_else(|_| panic!("Unexpectedly large location string length: {} characters", llvm_loc_string.len()));
let src_loc_string = format!("Source location: {}", src_loc);
let src_loc_string_len: u16 = src_loc_string.len().try_into().unwrap_or_else(|_| panic!("Unexpectedly large source string length: {} characters", src_loc_string.len()));
let llvm_rows_needed: u16 = llvm_loc_string_len / self.terminal_cols + 1;
let src_rows_needed: u16 = src_loc_string_len / self.terminal_cols + 1;
let rows_needed = llvm_rows_needed + src_rows_needed;
if rows_needed > self.rows_of_loc + 2 {
for _ in 0 .. rows_needed {
println!();
}
stdout.queue(cursor::MoveToPreviousLine(rows_needed)).unwrap();
}
let (_, loc_start_row) = cursor::position().unwrap();
println!("{}\n{}", llvm_loc_string, src_loc_string);
let loc_end_row = {
let (_, blank_line_row) = cursor::position().unwrap();
blank_line_row - 1
};
let loc_rows = loc_end_row - loc_start_row + 1;
assert!(loc_rows <= rows_needed);
self.rows_of_loc = loc_rows;
println!();
self.print_time_elapsed_line();
}
fn update_backtrack_points(&mut self, num_backtrack_points: usize, stdout: &mut Stdout) {
if num_backtrack_points != self.backtrack_points_remaining {
self.backtrack_points_remaining = num_backtrack_points;
stdout
.queue(cursor::MoveToPreviousLine(2 + self.rows_of_loc + 2 + self.rows_of_log + 4)).unwrap()
.queue(terminal::Clear(terminal::ClearType::CurrentLine)).unwrap();
self.print_backtrack_line();
stdout.queue(cursor::MoveToNextLine(3 + self.rows_of_log + 2 + self.rows_of_loc + 2)).unwrap();
}
}
fn update_elapsed_time(&mut self) {
let elapsed_secs = self.start_time.elapsed().as_secs();
if elapsed_secs != self.elapsed_secs {
self.elapsed_secs = elapsed_secs;
stdout()
.queue(cursor::MoveToPreviousLine(1)).unwrap()
.queue(terminal::Clear(terminal::ClearType::CurrentLine)).unwrap();
self.print_time_elapsed_line();
}
}
fn process_log_message(&mut self, log_message: &[u8], level: log::Level) {
let mut stdout = stdout();
let mut q = stdout
.queue(cursor::MoveToPreviousLine(2 + self.rows_of_loc + 2)).unwrap();
for _ in 0 .. self.rows_of_log {
q = q
.queue(cursor::MoveToPreviousLine(1)).unwrap()
.queue(terminal::Clear(terminal::ClearType::CurrentLine)).unwrap();
}
if level <= log::Level::Warn {
self.warnings_generated += 1;
stdout
.queue(cursor::MoveToPreviousLine(2)).unwrap()
.queue(terminal::Clear(terminal::ClearType::CurrentLine)).unwrap();
self.print_warnings_line();
stdout.queue(cursor::MoveToNextLine(1)).unwrap();
}
let (_, log_start_row) = cursor::position().unwrap();
stdout.write(log_message).unwrap();
let (_, log_end_row) = cursor::position().unwrap();
let rows_of_this_log = log_end_row - log_start_row + 1;
if rows_of_this_log > self.rows_of_log {
self.rows_of_log = rows_of_this_log;
println!();
stdout.queue(terminal::Clear(terminal::ClearType::FromCursorDown)).unwrap();
println!();
println!("Currently at location:");
println!();
self.rows_of_loc = 1;
println!();
self.print_time_elapsed_line();
} else if rows_of_this_log < self.rows_of_log {
stdout
.queue(cursor::MoveToNextLine(self.rows_of_log - rows_of_this_log)).unwrap()
.queue(cursor::MoveToNextLine(3 + self.rows_of_loc + 2)).unwrap();
} else {
stdout.queue(cursor::MoveToNextLine(3 + self.rows_of_loc + 2)).unwrap();
}
stdout.flush().unwrap();
}
fn increment_and_update_warning_count(&mut self) {
self.warnings_generated += 1;
let mut stdout = stdout();
stdout
.queue(cursor::MoveToPreviousLine(2 + self.rows_of_loc + 2 + self.rows_of_log + 2)).unwrap()
.queue(terminal::Clear(terminal::ClearType::CurrentLine)).unwrap();
self.print_warnings_line();
stdout.queue(cursor::MoveToNextLine(1 + self.rows_of_log + 2 + self.rows_of_loc + 2)).unwrap();
}
fn process_path_result(&mut self, path_result: &ConstantTimeResultForPath) {
let mut stdout = stdout();
let mut q = stdout
.queue(cursor::MoveToPreviousLine(2 + self.rows_of_loc + 2 + self.rows_of_log + 5)).unwrap();
for _ in 0 .. self.rows_of_stats {
q = q
.queue(cursor::MoveToPreviousLine(1)).unwrap()
.queue(terminal::Clear(terminal::ClearType::CurrentLine)).unwrap();
}
self.path_stats.add_path_result(path_result);
let (_, stats_start_row) = cursor::position().unwrap();
print!("{}", self.path_stats);
let stats_end_row = {
let (_, blank_line_row) = cursor::position().unwrap();
blank_line_row - 1
};
let new_rows_of_stats = stats_end_row - stats_start_row + 1;
if new_rows_of_stats > self.rows_of_stats {
self.rows_of_stats = new_rows_of_stats;
stdout.queue(terminal::Clear(terminal::ClearType::FromCursorDown)).unwrap();
println!();
self.print_backtrack_line();
println!();
self.print_warnings_line();
println!("Most recent log message (INFO or higher):");
for _ in 0 .. self.rows_of_log {
println!();
}
println!();
println!("Currently at location:");
println!(" <just finished a path>");
self.rows_of_loc = 1;
println!();
self.print_time_elapsed_line();
} else if new_rows_of_stats == self.rows_of_stats {
stdout.queue(cursor::MoveToNextLine(5 + self.rows_of_log + 2 + self.rows_of_loc + 2)).unwrap();
} else {
panic!("rows_of_stats decreased, which we didn't think should ever happen");
}
stdout.flush().unwrap();
}
fn finalize(&mut self) {
stdout()
.queue(cursor::MoveToPreviousLine(2 + self.rows_of_loc + 2 + self.rows_of_log + 5 + self.rows_of_stats + 2)).unwrap()
.queue(terminal::Clear(terminal::ClearType::FromCursorDown)).unwrap()
.flush().unwrap();
self.print_time_elapsed_line();
println!();
}
}
use std::cell::RefCell;
use std::rc::Rc;
thread_local! {
static MAIN_THREAD_STATE: Rc<RefCell<Option<MainThreadState>>> = Rc::new(RefCell::new(None));
}
pub struct MainThreadState {
tx: mpsc::Sender<ProgressMsg>,
termination_tx: mpsc::Sender<()>,
display_thread_join_handle: Option<thread::JoinHandle<()>>,
encoder: PatternEncoder,
}
impl MainThreadState {
fn initialize<B: Backend>(log_filename: &str, funcname: impl Into<String>, config: &mut Config<B>, debug_logging: bool) -> Rc<RefCell<Option<Self>>> {
let (tx, rx) = mpsc::channel();
let (termination_tx, termination_rx) = mpsc::channel();
let funcname = funcname.into();
let join_handle = thread::spawn(move || {
let mut pdstate = ProgressDisplayState::initialize(rx, termination_rx, &funcname);
pdstate.listen();
});
config.callbacks.add_instruction_callback(update_progress_inst);
config.callbacks.add_terminator_callback(update_progress_term);
if log::log_enabled!(log::Level::Error) {
println!("Logging was already initialized, so detailed logs for this run will be available wherever they were previously initialized to.\n");
} else {
println!("\nDetailed logs for this run are available at {}.\nYou may run `tail -f` on this file in a separate terminal.\n", log_filename);
crate::logging::init(log_filename, debug_logging);
}
let updater = Self {
tx,
termination_tx,
display_thread_join_handle: Some(join_handle),
encoder: PatternEncoder::new("{d(%Y-%m-%d %H:%M:%S)} [{l}] {m}"),
};
MAIN_THREAD_STATE.with(|mts| {
*mts.borrow_mut() = Some(updater);
mts.clone()
})
}
}
impl<B: Backend> crate::ProgressUpdater<B> for MainThreadState {
fn update_progress(&self, state: &State<B>) -> Result<()> {
self.tx.send(ProgressMsg::ProgressUpdate {
llvm_location: state.cur_loc.to_string_short_module(),
src_location: if let Some(debugloc) = state.cur_loc.source_loc {
debugloc.to_string()
} else {
"<unknown>".into()
},
num_backtrack_points: state.count_backtracking_points(),
}).unwrap();
Ok(())
}
fn update_path_result(&self, path_result: &ConstantTimeResultForPath) {
self.tx.send(ProgressMsg::PathCompleted(path_result.clone())).unwrap();
}
fn process_log_message(&self, record: &log::Record) -> std::result::Result<(), Box<dyn std::error::Error + Sync + Send>> {
let mut formatted_msg = Vec::new();
self.encoder.encode(&mut SimpleWriter(&mut formatted_msg), record)?;
self.tx.send(ProgressMsg::LogMessage {
msg: formatted_msg,
level: record.level(),
}).unwrap();
Ok(())
}
fn finalize(&mut self) {
self.termination_tx.send(()).unwrap();
self.display_thread_join_handle.take().unwrap().join().expect("Failed to join with progress-display-updater thread");
}
}
fn update_progress_inst<B: Backend>(_inst: &llvm_ir::Instruction, state: &State<B>) -> Result<()> {
update_progress(state)
}
fn update_progress_term<B: Backend>(_term: &llvm_ir::Terminator, state: &State<B>) -> Result<()> {
update_progress(state)
}
fn update_progress<B: Backend>(state: &State<B>) -> Result<()> {
MAIN_THREAD_STATE.with(|mts| {
let mut guard = mts.borrow_mut();
let mts: &mut MainThreadState = guard.as_mut().expect("process_log_message: expected a MainThreadState to exist");
<MainThreadState as crate::ProgressUpdater::<B>>::update_progress(mts, state)
})
}
pub fn process_log_message(record: &log::Record) -> std::result::Result<(), Box<dyn std::error::Error + Sync + Send>> {
MAIN_THREAD_STATE.with(|mts| {
let mut guard = mts.borrow_mut();
let mts: &mut MainThreadState = guard.as_mut().expect("process_log_message: expected a MainThreadState to exist");
<MainThreadState as crate::ProgressUpdater::<crate::secret::Backend>>::process_log_message(mts, record)
})
}
pub type ProgressUpdater = Rc<RefCell<Option<MainThreadState>>>;
pub fn initialize_progress_updater<B: Backend>(log_filename: &str, funcname: &str, config: &mut Config<B>, debug_logging: bool) -> ProgressUpdater {
MainThreadState::initialize(log_filename, funcname, config, debug_logging)
}
impl<B: Backend> crate::ProgressUpdater<B> for ProgressUpdater {
fn update_progress(&self, state: &State<B>) -> Result<()> {
let guard = self.borrow();
let mts: &MainThreadState = guard.as_ref().unwrap();
<MainThreadState as crate::ProgressUpdater::<B>>::update_progress(mts, state)
}
fn update_path_result(&self, path_result: &ConstantTimeResultForPath) {
let guard = self.borrow();
let mts: &MainThreadState = guard.as_ref().unwrap();
<MainThreadState as crate::ProgressUpdater::<B>>::update_path_result(mts, path_result)
}
fn process_log_message(&self, record: &log::Record) -> std::result::Result<(), Box<dyn std::error::Error + Sync + Send>> {
let guard = self.borrow();
let mts: &MainThreadState = guard.as_ref().unwrap();
<MainThreadState as crate::ProgressUpdater::<B>>::process_log_message(mts, record)
}
fn finalize(&mut self) {
let mut guard = self.borrow_mut();
let mts: &mut MainThreadState = guard.as_mut().unwrap();
<MainThreadState as crate::ProgressUpdater::<B>>::finalize(mts)
}
}