Skip to content

Commit

Permalink
More efficient log tailing (#191)
Browse files Browse the repository at this point in the history
This is not, in the scheme of things, probably a very important or even
noticeable contributor to overall performance but it's aesthetically
satisfying.
  • Loading branch information
sourcefrog authored Dec 15, 2023
2 parents 2f0e8f1 + f3111ee commit 5cecd31
Show file tree
Hide file tree
Showing 6 changed files with 124 additions and 66 deletions.
24 changes: 14 additions & 10 deletions src/console.rs
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,8 @@ use std::io;
use std::sync::{Arc, Mutex};
use std::time::{Duration, Instant};

use camino::{Utf8Path, Utf8PathBuf};
use anyhow::Context;
use camino::Utf8Path;
use console::{style, StyledObject};

use nutmeg::Destination;
Expand All @@ -19,7 +20,8 @@ use tracing_subscriber::prelude::*;

use crate::outcome::{LabOutcome, SummaryOutcome};
use crate::scenario::Scenario;
use crate::{last_line, Mutant, Options, Phase, Result, ScenarioOutcome};
use crate::tail_file::TailFile;
use crate::{Mutant, Options, Phase, Result, ScenarioOutcome};

static COPY_MESSAGE: &str = "Copy source to scratch directory";

Expand Down Expand Up @@ -61,12 +63,13 @@ impl Console {
}

/// Update that a cargo task is starting.
pub fn scenario_started(&self, scenario: &Scenario, log_file: &Utf8Path) {
pub fn scenario_started(&self, scenario: &Scenario, log_file: &Utf8Path) -> Result<()> {
let start = Instant::now();
let scenario_model = ScenarioModel::new(scenario, start, log_file.to_owned());
let scenario_model = ScenarioModel::new(scenario, start, log_file)?;
self.view.update(|model| {
model.scenario_models.push(scenario_model);
});
Ok(())
}

/// Update that cargo finished.
Expand Down Expand Up @@ -486,19 +489,20 @@ struct ScenarioModel {
phase: Option<Phase>,
/// Previously-executed phases and durations.
previous_phase_durations: Vec<(Phase, Duration)>,
log_file: Utf8PathBuf,
log_tail: TailFile,
}

impl ScenarioModel {
fn new(scenario: &Scenario, start: Instant, log_file: Utf8PathBuf) -> ScenarioModel {
ScenarioModel {
fn new(scenario: &Scenario, start: Instant, log_file: &Utf8Path) -> Result<ScenarioModel> {
let log_tail = TailFile::new(log_file).context("Failed to open log file")?;
Ok(ScenarioModel {
scenario: scenario.clone(),
name: style_scenario(scenario, true),
phase: None,
phase_start: start,
log_file,
log_tail,
previous_phase_durations: Vec::new(),
}
})
}

fn phase_started(&mut self, phase: Phase) {
Expand Down Expand Up @@ -531,7 +535,7 @@ impl nutmeg::Model for ScenarioModel {
));
}
write!(s, "{}", prs.join(" + ")).unwrap();
if let Ok(last_line) = last_line(&self.log_file) {
if let Ok(last_line) = self.log_tail.last_line() {
write!(s, "\n {}", style(last_line).dim()).unwrap();
}
s
Expand Down
2 changes: 1 addition & 1 deletion src/lab.rs
Original file line number Diff line number Diff line change
Expand Up @@ -185,7 +185,7 @@ fn test_scenario(
log_file.message(&format!("mutation diff:\n{}", mutant.diff()));
mutant.apply(build_dir)?;
}
console.scenario_started(scenario, log_file.path());
console.scenario_started(scenario, log_file.path())?;

let mut outcome = ScenarioOutcome::new(&log_file, scenario.clone());
let phases: &[Phase] = if options.check_only {
Expand Down
52 changes: 2 additions & 50 deletions src/log_file.rs
Original file line number Diff line number Diff line change
@@ -1,9 +1,9 @@
// Copyright 2021, 2022 Martin Pool
// Copyright 2021-2023 Martin Pool

//! Manage per-scenario log files, which contain the output from cargo
//! and test cases, mixed with commentary from cargo-mutants.
use std::fs::{self, File, OpenOptions};
use std::fs::{File, OpenOptions};
use std::io::{self, Write};

use anyhow::Context;
Expand Down Expand Up @@ -67,21 +67,6 @@ impl LogFile {
}
}

/// Return the last non-empty line from a file, if it has any content.
pub fn last_line(path: &Utf8Path) -> Result<String> {
// This is somewhat inefficient: we could potentially remember how long
// the file was last time, seek to that point, and deal with incomplete
// lines. However, probably these files will never get so colossal that
// reading them is a big problem; they are almost certainly in cache;
// and this should only be called a few times per second...
Ok(fs::read_to_string(path)?
.lines()
.filter(|s| !s.trim().is_empty())
.last()
.unwrap_or_default()
.to_owned())
}

fn clean_filename(s: &str) -> String {
let s = s.replace('/', "__");
s.chars()
Expand All @@ -103,37 +88,4 @@ mod test {
"1__2_3_4_5_6_7_8_9_0"
);
}

#[test]
fn last_line_of_file() {
let mut tempfile = tempfile::NamedTempFile::new().unwrap();
let path: Utf8PathBuf = tempfile.path().to_owned().try_into().unwrap();

assert_eq!(
last_line(&path).unwrap(),
"",
"empty file has an empty last line"
);

tempfile.write_all(b"hello").unwrap();
assert_eq!(
last_line(&path).unwrap(),
"hello",
"single line file with no terminator has that line as last line"
);

tempfile.write_all(b"\n\n\n").unwrap();
assert_eq!(
last_line(&path).unwrap(),
"hello",
"trailing blank lines are ignored"
);

tempfile.write_all(b"that's all folks!\n").unwrap();
assert_eq!(
last_line(&path).unwrap(),
"that's all folks!",
"newline terminated last line is returned"
);
}
}
3 changes: 2 additions & 1 deletion src/main.rs
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ mod process;
mod scenario;
mod source;
mod span;
mod tail_file;
mod visit;
mod workspace;

Expand All @@ -51,7 +52,7 @@ use crate::in_diff::diff_filter;
use crate::interrupt::check_interrupted;
use crate::lab::test_mutants;
use crate::list::{list_files, list_mutants, FmtToIoWrite};
use crate::log_file::{last_line, LogFile};
use crate::log_file::LogFile;
use crate::manifest::fix_manifest;
use crate::mutate::{Genre, Mutant};
use crate::options::Options;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,8 @@ src/config.rs: replace Config::read_tree_config -> Result<Config> with Err(::any
src/console.rs: replace Console::walk_tree_start with ()
src/console.rs: replace Console::walk_tree_update with ()
src/console.rs: replace Console::walk_tree_done with ()
src/console.rs: replace Console::scenario_started with ()
src/console.rs: replace Console::scenario_started -> Result<()> with Ok(())
src/console.rs: replace Console::scenario_started -> Result<()> with Err(::anyhow::anyhow!("mutated!"))
src/console.rs: replace Console::scenario_finished with ()
src/console.rs: replace || with && in Console::scenario_finished
src/console.rs: replace || with == in Console::scenario_finished
Expand Down Expand Up @@ -234,9 +235,6 @@ src/log_file.rs: replace LogFile::open_append -> Result<File> with Ok(Default::d
src/log_file.rs: replace LogFile::open_append -> Result<File> with Err(::anyhow::anyhow!("mutated!"))
src/log_file.rs: replace LogFile::message with ()
src/log_file.rs: replace LogFile::path -> &Utf8Path with &Default::default()
src/log_file.rs: replace last_line -> Result<String> with Ok(String::new())
src/log_file.rs: replace last_line -> Result<String> with Ok("xyzzy".into())
src/log_file.rs: replace last_line -> Result<String> with Err(::anyhow::anyhow!("mutated!"))
src/log_file.rs: replace clean_filename -> String with String::new()
src/log_file.rs: replace clean_filename -> String with "xyzzy".into()
src/manifest.rs: replace fix_manifest -> Result<()> with Ok(())
Expand Down Expand Up @@ -549,6 +547,11 @@ src/span.rs: replace <impl From for Span>::from -> Self with Default::default()
src/span.rs: replace <impl From for Span>::from -> Self with Default::default()
src/span.rs: replace <impl Debug for Span>::fmt -> fmt::Result with Ok(Default::default())
src/span.rs: replace <impl Debug for Span>::fmt -> fmt::Result with Err(::anyhow::anyhow!("mutated!"))
src/tail_file.rs: replace TailFile::last_line -> Result<&str> with Ok("")
src/tail_file.rs: replace TailFile::last_line -> Result<&str> with Ok("xyzzy")
src/tail_file.rs: replace TailFile::last_line -> Result<&str> with Err(::anyhow::anyhow!("mutated!"))
src/tail_file.rs: replace > with == in TailFile::last_line
src/tail_file.rs: replace > with < in TailFile::last_line
src/visit.rs: replace walk_tree -> Result<Discovered> with Ok(Default::default())
src/visit.rs: replace walk_tree -> Result<Discovered> with Err(::anyhow::anyhow!("mutated!"))
src/visit.rs: replace && with || in walk_tree
Expand Down
98 changes: 98 additions & 0 deletions src/tail_file.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,98 @@
// Copyright 2021-2023 Martin Pool

//! Tail a log file: watch for new writes and return the last line.
use std::fs::File;
use std::io::Read;
use std::path::Path;

use anyhow::Context;

use crate::Result;

#[derive(Debug)]
pub struct TailFile {
file: File,
last_line_seen: String,
read_buf: Vec<u8>,
}

impl TailFile {
/// Watch the given path.
pub fn new<P: AsRef<Path>>(path: P) -> Result<Self> {
let file = File::open(path.as_ref()).context("Open log file")?;
Ok(TailFile {
file,
last_line_seen: String::new(),
read_buf: Vec::new(),
})
}

/// Return the last non-empty, non-whitespace line from this file, or an empty string
/// if none have been seen yet.
///
/// Non-UTF8 content is lost.
pub fn last_line(&mut self) -> Result<&str> {
// This assumes that the file always sees writes of whole lines, which seems
// pretty likely: we don't attempt to stitch up writes of partial lines with
// later writes, although we could...
self.read_buf.clear();
let n_read = self
.file
.read_to_end(&mut self.read_buf)
.context("Read from log file")?;
if n_read > 0 {
if let Some(new_last) = String::from_utf8_lossy(&self.read_buf)
.lines()
.filter(|l| !l.trim().is_empty())
.last()
{
self.last_line_seen = new_last.to_owned();
}
}
Ok(self.last_line_seen.as_str())
}
}

#[cfg(test)]
mod test {
use camino::Utf8PathBuf;

use std::io::Write;

use super::*;

#[test]
fn last_line_of_file() {
let mut tempfile = tempfile::NamedTempFile::new().unwrap();
let path: Utf8PathBuf = tempfile.path().to_owned().try_into().unwrap();
let mut tailer = TailFile::new(path).unwrap();

assert_eq!(
tailer.last_line().unwrap(),
"",
"empty file has an empty last line"
);

tempfile.write_all(b"hello").unwrap();
assert_eq!(
tailer.last_line().unwrap(),
"hello",
"single line file with no terminator has that line as last line"
);

tempfile.write_all(b"\n\n\n").unwrap();
assert_eq!(
tailer.last_line().unwrap(),
"hello",
"trailing blank lines are ignored"
);

tempfile.write_all(b"that's all folks!\n").unwrap();
assert_eq!(
tailer.last_line().unwrap(),
"that's all folks!",
"newline terminated last line is returned"
);
}
}

0 comments on commit 5cecd31

Please sign in to comment.