view rust/rhg/src/blackbox.rs @ 48178:f12a19d03d2c

fix: reduce number of tool executions By grouping together (path, ctx) pairs according to the inputs they would provide to fixer tools, we can deduplicate executions of fixer tools to significantly reduce the amount of time spent running slow tools. This change does not handle clean files in the working copy, which could still be deduplicated against the files in the checked out commit. It's a little harder to do that because the filerev is not available in the workingfilectx (and it doesn't exist for added files). Anecdotally, this change makes some real uses cases at Google 10x faster. I think we were originally hesitant to do this because the benefits weren't obvious, and implementing it efficiently is kind of tricky. If we simply memoized the formatter execution function, we would be keeping tons of file content in memory. Also included is a regression test for a corner case that I broke with my first attempt at optimizing this code. Differential Revision: https://phab.mercurial-scm.org/D11280
author Danny Hooper <hooper@google.com>
date Thu, 02 Sep 2021 14:08:45 -0700
parents 7284b524b441
children abbecb5cd6f3
line wrap: on
line source

//! Logging for repository events, including commands run in the repository.

use crate::CliInvocation;
use format_bytes::format_bytes;
use hg::errors::HgError;
use hg::repo::Repo;
use hg::utils::{files::get_bytes_from_os_str, shell_quote};

const ONE_MEBIBYTE: u64 = 1 << 20;

// TODO: somehow keep defaults in sync with `configitem` in `hgext/blackbox.py`
const DEFAULT_MAX_SIZE: u64 = ONE_MEBIBYTE;
const DEFAULT_MAX_FILES: u32 = 7;

// Python does not support %.3f, only %f
const DEFAULT_DATE_FORMAT: &str = "%Y/%m/%d %H:%M:%S%.3f";

type DateTime = chrono::DateTime<chrono::Local>;

pub struct ProcessStartTime {
    /// For measuring duration
    monotonic_clock: std::time::Instant,
    /// For formatting with year, month, day, etc.
    calendar_based: DateTime,
}

impl ProcessStartTime {
    pub fn now() -> Self {
        Self {
            monotonic_clock: std::time::Instant::now(),
            calendar_based: chrono::Local::now(),
        }
    }
}

pub struct Blackbox<'a> {
    process_start_time: &'a ProcessStartTime,
    /// Do nothing if this is `None`
    configured: Option<ConfiguredBlackbox<'a>>,
}

struct ConfiguredBlackbox<'a> {
    repo: &'a Repo,
    max_size: u64,
    max_files: u32,
    date_format: &'a str,
}

impl<'a> Blackbox<'a> {
    pub fn new(
        invocation: &'a CliInvocation<'a>,
        process_start_time: &'a ProcessStartTime,
    ) -> Result<Self, HgError> {
        let configured = if let Ok(repo) = invocation.repo {
            if invocation.config.get(b"extensions", b"blackbox").is_none() {
                // The extension is not enabled
                None
            } else {
                Some(ConfiguredBlackbox {
                    repo,
                    max_size: invocation
                        .config
                        .get_byte_size(b"blackbox", b"maxsize")?
                        .unwrap_or(DEFAULT_MAX_SIZE),
                    max_files: invocation
                        .config
                        .get_u32(b"blackbox", b"maxfiles")?
                        .unwrap_or(DEFAULT_MAX_FILES),
                    date_format: invocation
                        .config
                        .get_str(b"blackbox", b"date-format")?
                        .unwrap_or(DEFAULT_DATE_FORMAT),
                })
            }
        } else {
            // Without a local repository there’s no `.hg/blackbox.log` to
            // write to.
            None
        };
        Ok(Self {
            process_start_time,
            configured,
        })
    }

    pub fn log_command_start(&self) {
        if let Some(configured) = &self.configured {
            let message = format_bytes!(b"(rust) {}", format_cli_args());
            configured.log(&self.process_start_time.calendar_based, &message);
        }
    }

    pub fn log_command_end(&self, exit_code: i32) {
        if let Some(configured) = &self.configured {
            let now = chrono::Local::now();
            let duration = self
                .process_start_time
                .monotonic_clock
                .elapsed()
                .as_secs_f64();
            let message = format_bytes!(
                b"(rust) {} exited {} after {} seconds",
                format_cli_args(),
                exit_code,
                format_bytes::Utf8(format_args!("{:.03}", duration))
            );
            configured.log(&now, &message);
        }
    }
}

impl ConfiguredBlackbox<'_> {
    fn log(&self, date_time: &DateTime, message: &[u8]) {
        let date = format_bytes::Utf8(date_time.format(self.date_format));
        let user = users::get_current_username().map(get_bytes_from_os_str);
        let user = user.as_deref().unwrap_or(b"???");
        let rev = format_bytes::Utf8(match self.repo.dirstate_parents() {
            Ok(parents) if parents.p2 == hg::revlog::node::NULL_NODE => {
                format!("{:x}", parents.p1)
            }
            Ok(parents) => format!("{:x}+{:x}", parents.p1, parents.p2),
            Err(_dirstate_corruption_error) => {
                // TODO: log a non-fatal warning to stderr
                "???".to_owned()
            }
        });
        let pid = std::process::id();
        let line = format_bytes!(
            b"{} {} @{} ({})> {}\n",
            date,
            user,
            rev,
            pid,
            message
        );
        let result =
            hg::logging::LogFile::new(self.repo.hg_vfs(), "blackbox.log")
                .max_size(Some(self.max_size))
                .max_files(self.max_files)
                .write(&line);
        match result {
            Ok(()) => {}
            Err(_io_error) => {
                // TODO: log a non-fatal warning to stderr
            }
        }
    }
}

fn format_cli_args() -> Vec<u8> {
    let mut args = std::env::args_os();
    let _ = args.next(); // Skip the first (or zeroth) arg, the name of the `rhg` executable
    let mut args = args.map(|arg| shell_quote(&get_bytes_from_os_str(arg)));
    let mut formatted = Vec::new();
    if let Some(arg) = args.next() {
        formatted.extend(arg)
    }
    for arg in args {
        formatted.push(b' ');
        formatted.extend(arg)
    }
    formatted
}