Hi,

I have a long-ish function that sometimes takes much longer than it should to execute. I've built myself a small logging type (see below) so I can narrow down where the problem lies.

Essentially, I can call

timed_log.log("now doing this and that");

throughout the function and that logs the message to a cache plus the timestamp at which it was called, and I can later print the log from that cache if the overall execution time was too long (thereby avoiding the unnecessary I/O load of saving the log for the case when performance is good).

However, I do fear that the log might not be accurate, as I'm not sure whether the compiler is allowed to rearrange code around the calls to the logger. I've found this thread on StackOverflow where someone has that exact problem when benchmarking their code, and there's no definitive answer 2 years later.

I'd rather not have to dig into the assembly trying to understand what the compiler did, since this is a multi-crate scenario and also I'm cross-compiling from amd64 to aarch64 and I'm unfamiliar with the tooling.

Is there some sort of marker I can insert that tells rustc not to reorder instructions across it? Or is my fear unfounded, because there's some reason rustc doesn't actually reorder operations across my Instant::elapsed call? (If this decreases performance a bit, I can live with that.)

I have found std::sync::atomic::fence(), but I cannot from the docs whether this is what I'm looking for.

use std::{fmt::{Display, Write}, time::{Duration, Instant}};

pub struct TimedLog<T> {
    t_start : Instant,
    log_entries : Vec<(Duration, T)>
}

impl<T> TimedLog<T> {
    pub fn new() -> Self {
        Self {
            t_start: Instant::now(),
            log_entries : vec![]
        }
    }

    pub fn log(&mut self, entry : impl Into<T>) {
        self.log_entries.push((self.t_start.elapsed(), entry.into()));
    }

    pub fn clear_entries(&mut self) {
        self.log_entries.clear();
    }

    pub fn reset(&mut self) {
        self.log_entries.clear();
        self.t_start = Instant::now();
    }
}

impl<T> TimedLog<T> where T : Display {
    pub fn write<W>(&self, writer : &mut W) where W : Write {
        let mut t_old = None;
        for (t, msg) in self.log_entries.iter() {
            let dt = match t_old {
                None => Duration::new(0, 0),
                Some(t_old) => *t - t_old
            };
            writeln!(
                writer,
                "t = {:11.6} ms | dt = {:11.6} ms | {}",
                t.as_secs_f32() * 1000.,
                dt.as_secs_f32() * 1000.,
                msg
            );
            t_old = Some(*t);
        }
    }
}

1 post - 1 participant

Read full topic