mirror of
https://github.com/fish-shell/fish-shell.git
synced 2026-04-19 14:51:13 -03:00
Port timer.cpp to rust
This commit is contained in:
@@ -125,7 +125,7 @@ set(FISH_SRCS
|
||||
src/pager.cpp src/parse_execution.cpp src/parse_tree.cpp src/parse_util.cpp
|
||||
src/parser.cpp src/parser_keywords.cpp src/path.cpp src/postfork.cpp
|
||||
src/proc.cpp src/re.cpp src/reader.cpp src/screen.cpp
|
||||
src/signals.cpp src/termsize.cpp src/timer.cpp src/tinyexpr.cpp
|
||||
src/signals.cpp src/termsize.cpp src/tinyexpr.cpp
|
||||
src/trace.cpp src/utf8.cpp
|
||||
src/wait_handle.cpp src/wcstringutil.cpp src/wgetopt.cpp src/wildcard.cpp
|
||||
src/wutil.cpp src/fds.cpp src/rustffi.cpp
|
||||
|
||||
@@ -26,6 +26,7 @@ fn main() -> miette::Result<()> {
|
||||
"src/parse_constants.rs",
|
||||
"src/redirection.rs",
|
||||
"src/smoke.rs",
|
||||
"src/timer.rs",
|
||||
"src/tokenizer.rs",
|
||||
"src/topic_monitor.rs",
|
||||
"src/util.rs",
|
||||
|
||||
@@ -1,4 +1,4 @@
|
||||
use crate::wchar::{self};
|
||||
use crate::wchar;
|
||||
#[rustfmt::skip]
|
||||
use ::std::pin::Pin;
|
||||
#[rustfmt::skip]
|
||||
|
||||
@@ -15,10 +15,12 @@
|
||||
mod ffi_tests;
|
||||
mod flog;
|
||||
mod future_feature_flags;
|
||||
mod nix;
|
||||
mod parse_constants;
|
||||
mod redirection;
|
||||
mod signal;
|
||||
mod smoke;
|
||||
mod timer;
|
||||
mod tokenizer;
|
||||
mod topic_monitor;
|
||||
mod util;
|
||||
|
||||
23
fish-rust/src/nix.rs
Normal file
23
fish-rust/src/nix.rs
Normal file
@@ -0,0 +1,23 @@
|
||||
//! Safe wrappers around various libc functions that we might want to reuse across modules.
|
||||
|
||||
use std::time::Duration;
|
||||
|
||||
pub const fn timeval_to_duration(val: &libc::timeval) -> Duration {
|
||||
let micros = val.tv_sec * (1E6 as i64) + val.tv_usec;
|
||||
Duration::from_micros(micros as u64)
|
||||
}
|
||||
|
||||
pub trait TimevalExt {
|
||||
fn as_micros(&self) -> i64;
|
||||
fn as_duration(&self) -> Duration;
|
||||
}
|
||||
|
||||
impl TimevalExt for libc::timeval {
|
||||
fn as_micros(&self) -> i64 {
|
||||
timeval_to_duration(self).as_micros() as i64
|
||||
}
|
||||
|
||||
fn as_duration(&self) -> Duration {
|
||||
timeval_to_duration(self)
|
||||
}
|
||||
}
|
||||
267
fish-rust/src/timer.rs
Normal file
267
fish-rust/src/timer.rs
Normal file
@@ -0,0 +1,267 @@
|
||||
//! This module houses `TimerSnapshot` which can be used to calculate the elapsed time (system CPU
|
||||
//! time, user CPU time, and observed wall time, broken down by fish and child processes spawned by
|
||||
//! fish) between two `TimerSnapshot` instances.
|
||||
//!
|
||||
//! Measuring time is always complicated with many caveats. Quite apart from the typical
|
||||
//! gotchas faced by developers attempting to choose between monotonic vs non-monotonic and system vs
|
||||
//! cpu clocks, the fact that we are executing as a shell further complicates matters: we can't just
|
||||
//! observe the elapsed CPU time, because that does not reflect the total execution time for both
|
||||
//! ourselves (internal shell execution time and the time it takes for builtins and functions to
|
||||
//! execute) and any external processes we spawn.
|
||||
//!
|
||||
//! `std::time::Instant` is used to monitor elapsed wall time. Unlike `SystemTime`, `Instant` is
|
||||
//! guaranteed to be monotonic though it is likely to not be as high of a precision as we would like
|
||||
//! but it's still the best we can do because we don't know how long of a time might elapse between
|
||||
//! `TimerSnapshot` instances and need to avoid rollover.
|
||||
|
||||
use std::io::Write;
|
||||
use std::time::{Duration, Instant};
|
||||
|
||||
#[cxx::bridge]
|
||||
mod timer_ffi {
|
||||
extern "Rust" {
|
||||
type PrintElapsedOnDropFfi;
|
||||
#[cxx_name = "push_timer"]
|
||||
fn push_timer_ffi(enabled: bool) -> Box<PrintElapsedOnDropFfi>;
|
||||
}
|
||||
}
|
||||
|
||||
enum Unit {
|
||||
Minutes,
|
||||
Seconds,
|
||||
Millis,
|
||||
Micros,
|
||||
}
|
||||
|
||||
struct TimerSnapshot {
|
||||
wall_time: Instant,
|
||||
cpu_fish: libc::rusage,
|
||||
cpu_children: libc::rusage,
|
||||
}
|
||||
|
||||
/// If `enabled`, create a `TimerSnapshot` and return a `PrintElapsedOnDrop` object that will print
|
||||
/// upon being dropped the delta between now and the time that it is dropped at. Otherwise return
|
||||
/// `None`.
|
||||
pub fn push_timer(enabled: bool) -> Option<PrintElapsedOnDrop> {
|
||||
if !enabled {
|
||||
return None;
|
||||
}
|
||||
|
||||
Some(PrintElapsedOnDrop {
|
||||
start: TimerSnapshot::take(),
|
||||
})
|
||||
}
|
||||
|
||||
/// cxx bridge does not support UniquePtr<NativeRustType> so we can't use a null UniquePtr to
|
||||
/// represent a None, and cxx bridge does not support Box<Option<NativeRustType>> so we need to make
|
||||
/// our own wrapper type that incorporates the Some/None states directly into it.
|
||||
enum PrintElapsedOnDropFfi {
|
||||
Some(PrintElapsedOnDrop),
|
||||
None,
|
||||
}
|
||||
|
||||
fn push_timer_ffi(enabled: bool) -> Box<PrintElapsedOnDropFfi> {
|
||||
Box::new(match push_timer(enabled) {
|
||||
Some(t) => PrintElapsedOnDropFfi::Some(t),
|
||||
None => PrintElapsedOnDropFfi::None,
|
||||
})
|
||||
}
|
||||
|
||||
/// An enumeration of supported libc rusage types used by [`getrusage()`].
|
||||
enum RUsage {
|
||||
RSelf, // "Self" is a reserved keyword
|
||||
RChildren,
|
||||
RThread,
|
||||
}
|
||||
|
||||
/// A safe wrapper around `libc::getrusage()`
|
||||
fn getrusage(resource: RUsage) -> libc::rusage {
|
||||
let mut rusage = std::mem::MaybeUninit::uninit();
|
||||
let result = unsafe {
|
||||
match resource {
|
||||
RUsage::RSelf => libc::getrusage(libc::RUSAGE_SELF, rusage.as_mut_ptr()),
|
||||
RUsage::RChildren => libc::getrusage(libc::RUSAGE_CHILDREN, rusage.as_mut_ptr()),
|
||||
RUsage::RThread => libc::getrusage(libc::RUSAGE_THREAD, rusage.as_mut_ptr()),
|
||||
}
|
||||
};
|
||||
|
||||
// getrusage(2) says the syscall can only fail if the dest address is invalid (EFAULT) or if the
|
||||
// requested resource type is invalid. Since we're in control of both, we can assume it won't
|
||||
// fail. In case it does anyway (e.g. OS where the syscall isn't implemented), we can just
|
||||
// return an empty value.
|
||||
match result {
|
||||
0 => unsafe { rusage.assume_init() },
|
||||
_ => unsafe { std::mem::zeroed() },
|
||||
}
|
||||
}
|
||||
|
||||
impl TimerSnapshot {
|
||||
pub fn take() -> TimerSnapshot {
|
||||
TimerSnapshot {
|
||||
cpu_fish: getrusage(RUsage::RSelf),
|
||||
cpu_children: getrusage(RUsage::RChildren),
|
||||
wall_time: Instant::now(),
|
||||
}
|
||||
}
|
||||
|
||||
/// Returns a formatted string containing the detailed difference between two `TimerSnapshot`
|
||||
/// instances. The returned string can take one of two formats, depending on the value of the
|
||||
/// `verbose` parameter.
|
||||
pub fn get_delta(t1: &TimerSnapshot, t2: &TimerSnapshot, verbose: bool) -> String {
|
||||
use crate::nix::timeval_to_duration as from;
|
||||
|
||||
let mut fish_sys = from(&t2.cpu_fish.ru_stime) - from(&t1.cpu_fish.ru_stime);
|
||||
let mut fish_usr = from(&t2.cpu_fish.ru_utime) - from(&t1.cpu_fish.ru_utime);
|
||||
let mut child_sys = from(&t2.cpu_children.ru_stime) - from(&t1.cpu_children.ru_stime);
|
||||
let mut child_usr = from(&t2.cpu_children.ru_utime) - from(&t1.cpu_children.ru_utime);
|
||||
|
||||
// The result from getrusage is not necessarily realtime, it may be cached from a few
|
||||
// microseconds ago. In the event that execution completes extremely quickly or there is
|
||||
// no data (say, we are measuring external execution time but no external processes have
|
||||
// been launched), it can incorrectly appear to be negative.
|
||||
fish_sys = fish_sys.max(Duration::ZERO);
|
||||
fish_usr = fish_usr.max(Duration::ZERO);
|
||||
child_sys = child_sys.max(Duration::ZERO);
|
||||
child_usr = child_usr.max(Duration::ZERO);
|
||||
// As `Instant` is strictly monotonic, this can't be negative so we don't need to clamp.
|
||||
let net_wall_micros = (t2.wall_time - t1.wall_time).as_micros() as i64;
|
||||
let net_sys_micros = (fish_sys + child_sys).as_micros() as i64;
|
||||
let net_usr_micros = (fish_usr + child_usr).as_micros() as i64;
|
||||
|
||||
let wall_unit = Unit::for_micros(net_wall_micros);
|
||||
// Make sure we share the same unit for the various CPU times
|
||||
let cpu_unit = Unit::for_micros(net_sys_micros.max(net_usr_micros));
|
||||
|
||||
let wall_time = wall_unit.convert_micros(net_wall_micros);
|
||||
let sys_time = cpu_unit.convert_micros(net_sys_micros);
|
||||
let usr_time = cpu_unit.convert_micros(net_usr_micros);
|
||||
|
||||
let mut output = String::new();
|
||||
if !verbose {
|
||||
output += &"\n_______________________________";
|
||||
output += &format!("\nExecuted in {:6.2} {}", wall_time, wall_unit.long_name());
|
||||
output += &format!("\n usr time {:6.2} {}", usr_time, cpu_unit.long_name());
|
||||
output += &format!("\n sys time {:6.2} {}", sys_time, cpu_unit.long_name());
|
||||
} else {
|
||||
let fish_unit = Unit::for_micros(fish_sys.max(fish_usr).as_micros() as i64);
|
||||
let child_unit = Unit::for_micros(child_sys.max(child_usr).as_micros() as i64);
|
||||
let fish_usr_time = fish_unit.convert_micros(fish_usr.as_micros() as i64);
|
||||
let fish_sys_time = fish_unit.convert_micros(fish_sys.as_micros() as i64);
|
||||
let child_usr_time = child_unit.convert_micros(child_usr.as_micros() as i64);
|
||||
let child_sys_time = child_unit.convert_micros(child_sys.as_micros() as i64);
|
||||
|
||||
let column2_unit_len = wall_unit
|
||||
.short_name()
|
||||
.len()
|
||||
.max(cpu_unit.short_name().len());
|
||||
let wall_unit = wall_unit.short_name();
|
||||
let cpu_unit = cpu_unit.short_name();
|
||||
let fish_unit = fish_unit.short_name();
|
||||
let child_unit = child_unit.short_name();
|
||||
|
||||
output += &"\n________________________________________________________";
|
||||
output += &format!(
|
||||
"\nExecuted in {wall_time:6.2} {wall_unit:<width1$} {fish:<width2$} external",
|
||||
width1 = column2_unit_len,
|
||||
fish = "fish",
|
||||
width2 = fish_unit.len() + 7
|
||||
);
|
||||
output += &format!("\n usr time {usr_time:6.2} {cpu_unit:<width1$} {fish_usr_time:6.2} {fish_unit} {child_usr_time:6.2} {child_unit}",
|
||||
width1 = column2_unit_len);
|
||||
output += &format!("\n sys time {sys_time:6.2} {cpu_unit:<width1$} {fish_sys_time:6.2} {fish_unit} {child_sys_time:6.2} {child_unit}",
|
||||
width1 = column2_unit_len);
|
||||
}
|
||||
output += "\n";
|
||||
|
||||
output
|
||||
}
|
||||
}
|
||||
|
||||
/// When dropped, prints to stderr the time that has elapsed since it was initialized.
|
||||
pub struct PrintElapsedOnDrop {
|
||||
start: TimerSnapshot,
|
||||
}
|
||||
|
||||
impl Drop for PrintElapsedOnDrop {
|
||||
fn drop(&mut self) {
|
||||
let end = TimerSnapshot::take();
|
||||
|
||||
// Well, this is awkward. By defining `time` as a decorator and not a built-in, there's
|
||||
// no associated stream for its output!
|
||||
let output = TimerSnapshot::get_delta(&self.start, &end, true);
|
||||
let mut stderr = std::io::stderr().lock();
|
||||
// There is no bubbling up of errors in a Drop implementation, and it's absolutely forbidden
|
||||
// to panic.
|
||||
let _ = stderr.write_all(output.as_bytes());
|
||||
let _ = stderr.write_all(b"\n");
|
||||
}
|
||||
}
|
||||
|
||||
impl Unit {
|
||||
/// Return the appropriate unit to format the provided number of microseconds in.
|
||||
const fn for_micros(micros: i64) -> Unit {
|
||||
match micros {
|
||||
900_000_001.. => Unit::Minutes,
|
||||
// Move to seconds if we would overflow the %6.2 format
|
||||
999_995.. => Unit::Seconds,
|
||||
1000.. => Unit::Millis,
|
||||
_ => Unit::Micros,
|
||||
}
|
||||
}
|
||||
|
||||
const fn short_name(&self) -> &'static str {
|
||||
match self {
|
||||
&Unit::Minutes => "mins",
|
||||
&Unit::Seconds => "secs",
|
||||
&Unit::Millis => "millis",
|
||||
&Unit::Micros => "micros",
|
||||
}
|
||||
}
|
||||
|
||||
const fn long_name(&self) -> &'static str {
|
||||
match self {
|
||||
&Unit::Minutes => "minutes",
|
||||
&Unit::Seconds => "seconds",
|
||||
&Unit::Millis => "milliseconds",
|
||||
&Unit::Micros => "microseconds",
|
||||
}
|
||||
}
|
||||
|
||||
fn convert_micros(&self, micros: i64) -> f64 {
|
||||
match self {
|
||||
&Unit::Minutes => micros as f64 / 1.0E6 / 60.0,
|
||||
&Unit::Seconds => micros as f64 / 1.0E6,
|
||||
&Unit::Millis => micros as f64 / 1.0E3,
|
||||
&Unit::Micros => micros as f64 / 1.0,
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn timer_format_and_alignment() {
|
||||
let mut t1 = TimerSnapshot::take();
|
||||
t1.cpu_fish.ru_utime.tv_usec = 0;
|
||||
t1.cpu_fish.ru_stime.tv_usec = 0;
|
||||
t1.cpu_children.ru_utime.tv_usec = 0;
|
||||
t1.cpu_children.ru_stime.tv_usec = 0;
|
||||
|
||||
let mut t2 = TimerSnapshot::take();
|
||||
t2.cpu_fish.ru_utime.tv_usec = 999995;
|
||||
t2.cpu_fish.ru_stime.tv_usec = 999994;
|
||||
t2.cpu_children.ru_utime.tv_usec = 1000;
|
||||
t2.cpu_children.ru_stime.tv_usec = 500;
|
||||
t2.wall_time = t1.wall_time + Duration::from_micros(500);
|
||||
|
||||
let expected = r#"
|
||||
________________________________________________________
|
||||
Executed in 500.00 micros fish external
|
||||
usr time 1.00 secs 1.00 secs 1.00 millis
|
||||
sys time 1.00 secs 1.00 secs 0.50 millis
|
||||
"#;
|
||||
// (a) (b) (c)
|
||||
// (a) remaining columns should align even if there are different units
|
||||
// (b) carry to the next unit when it would overflow %6.2F
|
||||
// (c) carry to the next unit when the larger one exceeds 1000
|
||||
let actual = TimerSnapshot::get_delta(&t1, &t2, true);
|
||||
assert_eq!(actual, expected);
|
||||
}
|
||||
@@ -47,7 +47,7 @@
|
||||
#include "proc.h"
|
||||
#include "reader.h"
|
||||
#include "redirection.h"
|
||||
#include "timer.h"
|
||||
#include "timer.rs.h"
|
||||
#include "trace.h"
|
||||
#include "wait_handle.h"
|
||||
#include "wcstringutil.h"
|
||||
@@ -1019,7 +1019,7 @@ bool exec_job(parser_t &parser, const shared_ptr<job_t> &j, const io_chain_t &bl
|
||||
}
|
||||
return false;
|
||||
}
|
||||
cleanup_t timer = push_timer(j->wants_timing() && !no_exec());
|
||||
auto timer = push_timer(j->wants_timing() && !no_exec());
|
||||
|
||||
// Get the deferred process, if any. We will have to remember its pipes.
|
||||
autoclose_pipes_t deferred_pipes;
|
||||
|
||||
@@ -92,7 +92,6 @@
|
||||
#include "signals.h"
|
||||
#include "smoke.rs.h"
|
||||
#include "termsize.h"
|
||||
#include "timer.h"
|
||||
#include "tokenizer.h"
|
||||
#include "topic_monitor.h"
|
||||
#include "utf8.h"
|
||||
@@ -6752,41 +6751,6 @@ static void test_fd_event_signaller() {
|
||||
do_test(!sema.try_consume());
|
||||
}
|
||||
|
||||
static void test_timer_format() {
|
||||
say(L"Testing timer format");
|
||||
// This test uses numeric output, so we need to set the locale.
|
||||
char *saved_locale = strdup(std::setlocale(LC_NUMERIC, nullptr));
|
||||
std::setlocale(LC_NUMERIC, "C");
|
||||
auto t1 = timer_snapshot_t::take();
|
||||
t1.cpu_fish.ru_utime.tv_usec = 0;
|
||||
t1.cpu_fish.ru_stime.tv_usec = 0;
|
||||
t1.cpu_children.ru_utime.tv_usec = 0;
|
||||
t1.cpu_children.ru_stime.tv_usec = 0;
|
||||
auto t2 = t1;
|
||||
t2.cpu_fish.ru_utime.tv_usec = 999995;
|
||||
t2.cpu_fish.ru_stime.tv_usec = 999994;
|
||||
t2.cpu_children.ru_utime.tv_usec = 1000;
|
||||
t2.cpu_children.ru_stime.tv_usec = 500;
|
||||
t2.wall += std::chrono::microseconds(500);
|
||||
auto expected =
|
||||
LR"(
|
||||
________________________________________________________
|
||||
Executed in 500.00 micros fish external
|
||||
usr time 1.00 secs 1.00 secs 1.00 millis
|
||||
sys time 1.00 secs 1.00 secs 0.50 millis
|
||||
)"; // (a) (b) (c)
|
||||
// (a) remaining columns should align even if there are different units
|
||||
// (b) carry to the next unit when it would overflow %6.2F
|
||||
// (c) carry to the next unit when the larger one exceeds 1000
|
||||
std::wstring actual = timer_snapshot_t::print_delta(t1, t2, true);
|
||||
if (actual != expected) {
|
||||
err(L"Failed to format timer snapshot\nExpected: %ls\nActual:%ls\n", expected,
|
||||
actual.c_str());
|
||||
}
|
||||
std::setlocale(LC_NUMERIC, saved_locale);
|
||||
free(saved_locale);
|
||||
}
|
||||
|
||||
static void test_killring() {
|
||||
say(L"Testing killring");
|
||||
|
||||
@@ -7213,7 +7177,6 @@ static const test_t s_tests[]{
|
||||
{TEST_GROUP("topics"), test_topic_monitor_torture},
|
||||
{TEST_GROUP("pipes"), test_pipes},
|
||||
{TEST_GROUP("fd_event"), test_fd_event_signaller},
|
||||
{TEST_GROUP("timer_format"), test_timer_format},
|
||||
{TEST_GROUP("termsize"), termsize_tester_t::test},
|
||||
{TEST_GROUP("killring"), test_killring},
|
||||
{TEST_GROUP("re"), test_re_errs},
|
||||
|
||||
@@ -39,7 +39,7 @@
|
||||
#include "path.h"
|
||||
#include "proc.h"
|
||||
#include "reader.h"
|
||||
#include "timer.h"
|
||||
#include "timer.rs.h"
|
||||
#include "tokenizer.h"
|
||||
#include "trace.h"
|
||||
#include "wildcard.h"
|
||||
@@ -1307,7 +1307,7 @@ end_execution_reason_t parse_execution_context_t::run_1_job(const ast::job_pipel
|
||||
if (job_is_simple_block(job_node)) {
|
||||
bool do_time = job_node.time.has_value();
|
||||
// If no-exec has been given, there is nothing to time.
|
||||
cleanup_t timer = push_timer(do_time && !no_exec());
|
||||
auto timer = push_timer(do_time && !no_exec());
|
||||
const block_t *block = nullptr;
|
||||
end_execution_reason_t result =
|
||||
this->apply_variable_assignments(nullptr, job_node.variables, &block);
|
||||
|
||||
210
src/timer.cpp
210
src/timer.cpp
@@ -1,210 +0,0 @@
|
||||
// Functions for executing the time builtin.
|
||||
#include "config.h" // IWYU pragma: keep
|
||||
|
||||
#include "timer.h"
|
||||
|
||||
#include <stdint.h>
|
||||
#include <stdio.h>
|
||||
#include <string.h>
|
||||
|
||||
#include <algorithm>
|
||||
#include <chrono>
|
||||
#include <cwchar>
|
||||
#include <functional>
|
||||
#include <string>
|
||||
|
||||
#include "common.h"
|
||||
#include "fallback.h" // IWYU pragma: keep
|
||||
#include "wutil.h" // IWYU pragma: keep
|
||||
|
||||
// Measuring time is always complicated with many caveats. Quite apart from the typical
|
||||
// gotchas faced by developers attempting to choose between monotonic vs non-monotonic and system vs
|
||||
// cpu clocks, the fact that we are executing as a shell further complicates matters: we can't just
|
||||
// observe the elapsed CPU time, because that does not reflect the total execution time for both
|
||||
// ourselves (internal shell execution time and the time it takes for builtins and functions to
|
||||
// execute) and any external processes we spawn.
|
||||
|
||||
// It would be nice to use the C++1 type-safe <chrono> interfaces to measure elapsed time, but that
|
||||
// unfortunately is underspecified with regards to user/system time and only provides means of
|
||||
// querying guaranteed monotonicity and resolution for the various clocks. It can be used to measure
|
||||
// elapsed wall time nicely, but if we would like to provide information more useful for
|
||||
// benchmarking and tuning then we must turn to either clock_gettime(2), with extensions for thread-
|
||||
// and process-specific elapsed CPU time, or times(3) for a standard interface to overall process
|
||||
// and child user/system time elapsed between snapshots. At least on some systems, times(3) has been
|
||||
// deprecated in favor of getrusage(2), which offers a wider variety of metrics coalesced for SELF,
|
||||
// THREAD, or CHILDREN.
|
||||
|
||||
// With regards to the C++11 `<chrono>` interface, there are three different time sources (clocks)
|
||||
// that we can use portably: `system_clock`, `steady_clock`, and `high_resolution_clock`; with
|
||||
// different properties and guarantees. While the obvious difference is the direct tradeoff between
|
||||
// period and resolution (higher resolution equals ability to measure smaller time differences more
|
||||
// accurately, but at the cost of rolling over more frequently), but unfortunately it is not as
|
||||
// simple as starting two clocks and going with the highest resolution that hasn't rolled over.
|
||||
// `system_clock` is out because it is always subject to interference due to adjustments from NTP
|
||||
// servers or super users (as it reflects the "actual" time), but `high_resolution_clock` may or may
|
||||
// not be aliased to `system_clock` or `steady_clock`. In practice, there's likely no need to worry
|
||||
// about this too much, a survey <http://howardhinnant.github.io/clock_survey.html> of the different
|
||||
// libraries indicates that `high_resolution_clock` is either an alias for `steady_clock` (in which
|
||||
// case it offers no greater resolution) or it is an alias for `system_clock` (in which case, even
|
||||
// when it offers a greater resolution than `steady_clock` it is not fit for use).
|
||||
|
||||
static int64_t micros(struct timeval t) {
|
||||
return (static_cast<int64_t>(t.tv_usec) + static_cast<int64_t>(t.tv_sec * 1E6));
|
||||
};
|
||||
|
||||
template <typename D1, typename D2>
|
||||
static int64_t micros(const std::chrono::duration<D1, D2> &d) {
|
||||
return std::chrono::duration_cast<std::chrono::microseconds>(d).count();
|
||||
};
|
||||
|
||||
timer_snapshot_t timer_snapshot_t::take() {
|
||||
timer_snapshot_t snapshot;
|
||||
|
||||
getrusage(RUSAGE_SELF, &snapshot.cpu_fish);
|
||||
getrusage(RUSAGE_CHILDREN, &snapshot.cpu_children);
|
||||
snapshot.wall = std::chrono::steady_clock::now();
|
||||
|
||||
return snapshot;
|
||||
}
|
||||
|
||||
wcstring timer_snapshot_t::print_delta(const timer_snapshot_t &t1, const timer_snapshot_t &t2,
|
||||
bool verbose /* = true */) {
|
||||
int64_t fish_sys_micros = micros(t2.cpu_fish.ru_stime) - micros(t1.cpu_fish.ru_stime);
|
||||
int64_t fish_usr_micros = micros(t2.cpu_fish.ru_utime) - micros(t1.cpu_fish.ru_utime);
|
||||
int64_t child_sys_micros = micros(t2.cpu_children.ru_stime) - micros(t1.cpu_children.ru_stime);
|
||||
int64_t child_usr_micros = micros(t2.cpu_children.ru_utime) - micros(t1.cpu_children.ru_utime);
|
||||
|
||||
// The result from getrusage is not necessarily realtime, it may be cached a few microseconds
|
||||
// behind. In the event that execution completes extremely quickly or there is no data (say, we
|
||||
// are measuring external execution time but no external processes have been launched), it can
|
||||
// incorrectly appear to be negative.
|
||||
fish_sys_micros = std::max(int64_t(0), fish_sys_micros);
|
||||
fish_usr_micros = std::max(int64_t(0), fish_usr_micros);
|
||||
child_sys_micros = std::max(int64_t(0), child_sys_micros);
|
||||
child_usr_micros = std::max(int64_t(0), child_usr_micros);
|
||||
|
||||
int64_t net_sys_micros = fish_sys_micros + child_sys_micros;
|
||||
int64_t net_usr_micros = fish_usr_micros + child_usr_micros;
|
||||
int64_t net_wall_micros = micros(t2.wall - t1.wall);
|
||||
|
||||
enum class tunit {
|
||||
minutes,
|
||||
seconds,
|
||||
milliseconds,
|
||||
microseconds,
|
||||
};
|
||||
|
||||
auto get_unit = [](int64_t micros) {
|
||||
if (micros > 900 * 1E6) {
|
||||
return tunit::minutes;
|
||||
} else if (micros >= 999995) { // Move to seconds if we would overflow the %6.2 format.
|
||||
return tunit::seconds;
|
||||
} else if (micros >= 1000) {
|
||||
return tunit::milliseconds;
|
||||
} else {
|
||||
return tunit::microseconds;
|
||||
}
|
||||
};
|
||||
|
||||
auto unit_name = [](tunit unit) {
|
||||
switch (unit) {
|
||||
case tunit::minutes:
|
||||
return "minutes";
|
||||
case tunit::seconds:
|
||||
return "seconds";
|
||||
case tunit::milliseconds:
|
||||
return "milliseconds";
|
||||
case tunit::microseconds:
|
||||
return "microseconds";
|
||||
}
|
||||
// GCC does not recognize the exhaustive switch above
|
||||
return "";
|
||||
};
|
||||
|
||||
auto unit_short_name = [](tunit unit) {
|
||||
switch (unit) {
|
||||
case tunit::minutes:
|
||||
return "mins";
|
||||
case tunit::seconds:
|
||||
return "secs";
|
||||
case tunit::milliseconds:
|
||||
return "millis";
|
||||
case tunit::microseconds:
|
||||
return "micros";
|
||||
}
|
||||
// GCC does not recognize the exhaustive switch above
|
||||
return "";
|
||||
};
|
||||
|
||||
auto convert = [](int64_t micros, tunit unit) {
|
||||
switch (unit) {
|
||||
case tunit::minutes:
|
||||
return micros / 1.0E6 / 60.0;
|
||||
case tunit::seconds:
|
||||
return micros / 1.0E6;
|
||||
case tunit::milliseconds:
|
||||
return micros / 1.0E3;
|
||||
case tunit::microseconds:
|
||||
return micros / 1.0;
|
||||
}
|
||||
// GCC does not recognize the exhaustive switch above
|
||||
return 0.0;
|
||||
};
|
||||
|
||||
auto wall_unit = get_unit(net_wall_micros);
|
||||
auto cpu_unit = get_unit(std::max(net_sys_micros, net_usr_micros));
|
||||
double wall_time = convert(net_wall_micros, wall_unit);
|
||||
double usr_time = convert(net_usr_micros, cpu_unit);
|
||||
double sys_time = convert(net_sys_micros, cpu_unit);
|
||||
|
||||
wcstring output;
|
||||
if (!verbose) {
|
||||
append_format(output,
|
||||
L"\n_______________________________"
|
||||
L"\nExecuted in %6.2F %s"
|
||||
L"\n usr time %6.2F %s"
|
||||
L"\n sys time %6.2F %s"
|
||||
L"\n",
|
||||
wall_time, unit_name(wall_unit), usr_time, unit_name(cpu_unit), sys_time,
|
||||
unit_name(cpu_unit));
|
||||
} else {
|
||||
auto fish_unit = get_unit(std::max(fish_sys_micros, fish_usr_micros));
|
||||
auto child_unit = get_unit(std::max(child_sys_micros, child_usr_micros));
|
||||
double fish_usr_time = convert(fish_usr_micros, fish_unit);
|
||||
double fish_sys_time = convert(fish_sys_micros, fish_unit);
|
||||
double child_usr_time = convert(child_usr_micros, child_unit);
|
||||
double child_sys_time = convert(child_sys_micros, child_unit);
|
||||
|
||||
int column2_unit_len =
|
||||
std::max(strlen(unit_short_name(wall_unit)), strlen(unit_short_name(cpu_unit)));
|
||||
append_format(output,
|
||||
L"\n________________________________________________________"
|
||||
L"\nExecuted in %6.2F %-*s %-*s %s"
|
||||
L"\n usr time %6.2F %-*s %6.2F %s %6.2F %s"
|
||||
L"\n sys time %6.2F %-*s %6.2F %s %6.2F %s"
|
||||
L"\n",
|
||||
wall_time, column2_unit_len, unit_short_name(wall_unit),
|
||||
static_cast<int>(strlen(unit_short_name(fish_unit))) + 7, "fish", "external",
|
||||
usr_time, column2_unit_len, unit_short_name(cpu_unit), fish_usr_time,
|
||||
unit_short_name(fish_unit), child_usr_time, unit_short_name(child_unit),
|
||||
sys_time, column2_unit_len, unit_short_name(cpu_unit), fish_sys_time,
|
||||
unit_short_name(fish_unit), child_sys_time, unit_short_name(child_unit));
|
||||
}
|
||||
return output;
|
||||
};
|
||||
|
||||
static void timer_finished(const timer_snapshot_t &t1) {
|
||||
auto t2 = timer_snapshot_t::take();
|
||||
|
||||
// Well, this is awkward. By defining `time` as a decorator and not a built-in, there's
|
||||
// no associated stream for its output!
|
||||
auto output = timer_snapshot_t::print_delta(t1, t2, true);
|
||||
std::fwprintf(stderr, L"%S\n", output.c_str());
|
||||
}
|
||||
|
||||
cleanup_t push_timer(bool enabled) {
|
||||
if (!enabled) return {[] {}};
|
||||
|
||||
auto t1 = timer_snapshot_t::take();
|
||||
return {[=] { timer_finished(t1); }};
|
||||
}
|
||||
27
src/timer.h
27
src/timer.h
@@ -1,27 +0,0 @@
|
||||
// Prototypes for executing builtin_time function.
|
||||
#ifndef FISH_TIMER_H
|
||||
#define FISH_TIMER_H
|
||||
|
||||
#include <sys/resource.h>
|
||||
|
||||
#include <chrono>
|
||||
|
||||
#include "common.h"
|
||||
|
||||
cleanup_t push_timer(bool enabled);
|
||||
|
||||
struct timer_snapshot_t {
|
||||
public:
|
||||
struct rusage cpu_fish;
|
||||
struct rusage cpu_children;
|
||||
std::chrono::time_point<std::chrono::steady_clock> wall;
|
||||
|
||||
static timer_snapshot_t take();
|
||||
static wcstring print_delta(const timer_snapshot_t &t1, const timer_snapshot_t &t2,
|
||||
bool verbose = false);
|
||||
|
||||
private:
|
||||
timer_snapshot_t() {}
|
||||
};
|
||||
|
||||
#endif
|
||||
Reference in New Issue
Block a user