From 59562700151abba70fb782defb1adcce1ac7c1be Mon Sep 17 00:00:00 2001 From: Mahmoud Al-Qudsi Date: Wed, 18 Dec 2019 18:06:56 -0600 Subject: [PATCH 1/5] Add `time` builtin that understands fish script and external executables This now works: ```fish function foo for n in (seq 1 100000) test $n -eq 42 end end time foo ``` --- CMakeLists.txt | 2 +- src/builtin.cpp | 2 + src/builtin_time.cpp | 119 +++++++++++++++++++++++++++++++++++++++++++ src/builtin_time.h | 9 ++++ 4 files changed, 131 insertions(+), 1 deletion(-) create mode 100644 src/builtin_time.cpp create mode 100644 src/builtin_time.h diff --git a/CMakeLists.txt b/CMakeLists.txt index 7d9dff233..d7ecadf8c 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -117,7 +117,7 @@ SET(FISH_SRCS src/signal.cpp src/tinyexpr.cpp src/tnode.cpp src/tokenizer.cpp src/utf8.cpp src/util.cpp src/wcstringutil.cpp src/wgetopt.cpp src/wildcard.cpp src/wutil.cpp src/future_feature_flags.cpp src/redirection.cpp src/topic_monitor.cpp - src/flog.cpp src/trace.cpp + src/flog.cpp src/trace.cpp src/builtin_time.cpp ) # Header files are just globbed. diff --git a/src/builtin.cpp b/src/builtin.cpp index 9eca55180..74a327d5f 100644 --- a/src/builtin.cpp +++ b/src/builtin.cpp @@ -61,6 +61,7 @@ #include "builtin_status.h" #include "builtin_string.h" #include "builtin_test.h" +#include "builtin_time.h" #include "builtin_ulimit.h" #include "builtin_wait.h" #include "common.h" @@ -387,6 +388,7 @@ static const builtin_data_t builtin_datas[] = { {L"string", &builtin_string, N_(L"Manipulate strings")}, {L"switch", &builtin_generic, N_(L"Conditionally execute a block of commands")}, {L"test", &builtin_test, N_(L"Test a condition")}, + {L"time", &builtin_time, N_(L"Time the execution of a job")}, {L"true", &builtin_true, N_(L"Return a successful result")}, {L"ulimit", &builtin_ulimit, N_(L"Set or get the shells resource usage limits")}, {L"wait", &builtin_wait, N_(L"Wait for background processes completed")}, diff --git a/src/builtin_time.cpp b/src/builtin_time.cpp new file mode 100644 index 000000000..3a5267a77 --- /dev/null +++ b/src/builtin_time.cpp @@ -0,0 +1,119 @@ +// Functions for executing the time builtin. +#include "config.h" // IWYU pragma: keep + +#include +#include +#include +#include + +#include "builtin.h" +#include "common.h" +#include "exec.h" +#include "fallback.h" // IWYU pragma: keep +#include "io.h" +#include "parser.h" +#include "proc.h" +#include "wgetopt.h" +#include "wutil.h" // IWYU pragma: keep + +#include +#include +#include + +// 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 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. + +static uint64_t micros(struct timeval t) { + return (static_cast(t.tv_usec) + static_cast(t.tv_sec * 1E6)); +}; +static uint64_t micros(struct timespec t) { + return (static_cast(t.tv_nsec) / 1E3 + static_cast(t.tv_sec * 1E6)); +}; + +/// Implementation of time builtin. +int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { + int argc = builtin_count_args(argv); + + bool verbose = false; + // In the future, we can consider accepting more command-line arguments to dictate the behavior + // of the `time` builtin and what it measures or reports. + if (argc > 1 && (argv[1] == wcstring(L"-h") || argv[1] == wcstring(L"--help"))) { + streams.out.append(L"time \n"); + streams.out.append(L"Measures the elapsed wall, system, and user clocks in the execution of" + L" the given command or expression"); + return 0; + } + if (argc > 1 && (argv[1] == wcstring(L"-v") || argv[1] == wcstring(L"--verbose"))) { + verbose = true; + argc -= 1; + argv += 1; + } + + wcstring new_cmd; + for (int i = 1; i < argc; ++i) { + if (i > 1) new_cmd += L' '; + new_cmd += argv[i]; + } + + int status = STATUS_CMD_OK; + if (argc > 1) { + struct rusage fish_usage[2]; + struct rusage child_usage [2]; + struct timespec wall[2] {}; + + // Start counters + getrusage(RUSAGE_SELF, &fish_usage[0]); + getrusage(RUSAGE_CHILDREN, &child_usage[0]); + clock_gettime(CLOCK_MONOTONIC, &wall[0]); + + if (parser.eval(std::move(new_cmd), *streams.io_chain, block_type_t::TOP) != + eval_result_t::ok) { + status = STATUS_CMD_ERROR; + } else { + status = parser.get_last_status(); + } + + // Stop counters + getrusage(RUSAGE_SELF, &fish_usage[1]); + getrusage(RUSAGE_CHILDREN, &child_usage[1]); + clock_gettime(CLOCK_MONOTONIC, &wall[1]); + + + uint64_t fish_sys_micros = micros(fish_usage[1].ru_stime) - micros(fish_usage[0].ru_stime); + uint64_t fish_usr_micros = micros(fish_usage[1].ru_utime) - micros(fish_usage[0].ru_utime); + uint64_t child_sys_micros = micros(child_usage[1].ru_stime) - micros(child_usage[0].ru_stime); + uint64_t child_usr_micros = micros(child_usage[1].ru_utime) - micros(child_usage[0].ru_utime); + + uint64_t net_sys_micros = fish_sys_micros + child_sys_micros; + uint64_t net_usr_micros = fish_usr_micros + child_usr_micros; + uint64_t wall_micros = micros(wall[1]) - micros(wall[0]); + + streams.out.append_format( + L"\n__________________________________" \ + L"\nExecution completed in %f seconds" \ + L"\nuser time %f seconds" \ + L"\nsystem time %f seconds" \ + L"\n\n", + wall_micros / 1.0E6, + net_usr_micros / 1.0E6, + net_sys_micros / 1.0E6 + ); + + } + + return status; +} diff --git a/src/builtin_time.h b/src/builtin_time.h new file mode 100644 index 000000000..97fd171b9 --- /dev/null +++ b/src/builtin_time.h @@ -0,0 +1,9 @@ +// Prototypes for executing builtin_time function. +#ifndef FISH_BUILTIN_TIME_H +#define FISH_BUILTIN_TIME_H + +class parser_t; +struct io_streams_t; + +int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv); +#endif From 1ed5e7e478f7c9fb1a3f69f22624122ae5ef26da Mon Sep 17 00:00:00 2001 From: Mahmoud Al-Qudsi Date: Wed, 18 Dec 2019 19:21:23 -0600 Subject: [PATCH 2/5] Dynamically choose units for `time` output --- src/builtin_time.cpp | 58 ++++++++++++++++++++++++++++++++++++++------ 1 file changed, 51 insertions(+), 7 deletions(-) diff --git a/src/builtin_time.cpp b/src/builtin_time.cpp index 3a5267a77..790c558d3 100644 --- a/src/builtin_time.cpp +++ b/src/builtin_time.cpp @@ -100,17 +100,61 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { uint64_t net_sys_micros = fish_sys_micros + child_sys_micros; uint64_t net_usr_micros = fish_usr_micros + child_usr_micros; - uint64_t wall_micros = micros(wall[1]) - micros(wall[0]); + uint64_t net_wall_micros = micros(wall[1]) - micros(wall[0]); + + enum class unit { + minutes, + seconds, + milliseconds, + microseconds, + }; + + auto get_unit = [](uint64_t micros) { + if (micros > 900 * 1E6) { + return unit::minutes; + } + else if (micros > 1 * 1E6) { + return unit::seconds; + } else if (micros > 10E3) { + return unit::milliseconds; + } else { + return unit::microseconds; + } + }; + + auto unit_name = [](unit unit) { + switch (unit) { + case unit::minutes: return "minutes"; + case unit::seconds: return "seconds"; + case unit::milliseconds: return "milliseconds"; + case unit::microseconds: return "microseconds"; + } + }; + + auto convert = [](uint64_t micros, unit unit) { + switch (unit) { + case unit::minutes: return micros / 1.0E6 / 60.0; + case unit::seconds: return micros / 1.0E6; + case unit::milliseconds: return micros / 1.0E3; + case unit::microseconds: return micros / 1.0; + } + }; + + auto wall_unit = get_unit(net_wall_micros); + auto cpu_unit = get_unit((net_sys_micros + net_usr_micros) / 2); + auto wall_time = convert(net_wall_micros, wall_unit); + auto usr_time = convert(net_usr_micros, cpu_unit); + auto sys_time = convert(net_sys_micros, cpu_unit); streams.out.append_format( L"\n__________________________________" \ - L"\nExecution completed in %f seconds" \ - L"\nuser time %f seconds" \ - L"\nsystem time %f seconds" \ + L"\nExecuted in %6.2F %s" \ + L"\n usr time %6.2F %s" \ + L"\n sys time %6.2F %s" \ L"\n\n", - wall_micros / 1.0E6, - net_usr_micros / 1.0E6, - net_sys_micros / 1.0E6 + wall_time, unit_name(wall_unit), + usr_time, unit_name(cpu_unit), + sys_time, unit_name(cpu_unit) ); } From be376560671896636b735dd5b8b915b09044c617 Mon Sep 17 00:00:00 2001 From: Mahmoud Al-Qudsi Date: Wed, 18 Dec 2019 20:09:08 -0600 Subject: [PATCH 3/5] Support `time -v` for detailed `time` output This breaks down the usage into fish vs external processes. --- src/builtin_time.cpp | 101 +++++++++++++++++++++++++++++++++---------- 1 file changed, 77 insertions(+), 24 deletions(-) diff --git a/src/builtin_time.cpp b/src/builtin_time.cpp index 790c558d3..09215fc4f 100644 --- a/src/builtin_time.cpp +++ b/src/builtin_time.cpp @@ -16,6 +16,8 @@ #include "wgetopt.h" #include "wutil.h" // IWYU pragma: keep +#include +#include #include #include #include @@ -44,6 +46,14 @@ static uint64_t micros(struct timespec t) { return (static_cast(t.tv_nsec) / 1E3 + static_cast(t.tv_sec * 1E6)); }; +// Linux makes available CLOCK_MONOTONIC_RAW, which is monotonic even in the presence of NTP +// adjustments. +#ifdef CLOCK_MONOTONIC_RAW + #define CLOCK_SRC CLOCK_MONOTONIC_RAW +#else + #define CLOCK_SRC CLOCK_MONOTONIC +#endif + /// Implementation of time builtin. int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { int argc = builtin_count_args(argv); @@ -78,7 +88,7 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { // Start counters getrusage(RUSAGE_SELF, &fish_usage[0]); getrusage(RUSAGE_CHILDREN, &child_usage[0]); - clock_gettime(CLOCK_MONOTONIC, &wall[0]); + clock_gettime(CLOCK_SRC, &wall[0]); if (parser.eval(std::move(new_cmd), *streams.io_chain, block_type_t::TOP) != eval_result_t::ok) { @@ -90,17 +100,25 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { // Stop counters getrusage(RUSAGE_SELF, &fish_usage[1]); getrusage(RUSAGE_CHILDREN, &child_usage[1]); - clock_gettime(CLOCK_MONOTONIC, &wall[1]); + clock_gettime(CLOCK_SRC, &wall[1]); + int64_t fish_sys_micros = micros(fish_usage[1].ru_stime) - micros(fish_usage[0].ru_stime); + int64_t fish_usr_micros = micros(fish_usage[1].ru_utime) - micros(fish_usage[0].ru_utime); + int64_t child_sys_micros = micros(child_usage[1].ru_stime) - micros(child_usage[0].ru_stime); + int64_t child_usr_micros = micros(child_usage[1].ru_utime) - micros(child_usage[0].ru_utime); - uint64_t fish_sys_micros = micros(fish_usage[1].ru_stime) - micros(fish_usage[0].ru_stime); - uint64_t fish_usr_micros = micros(fish_usage[1].ru_utime) - micros(fish_usage[0].ru_utime); - uint64_t child_sys_micros = micros(child_usage[1].ru_stime) - micros(child_usage[0].ru_stime); - uint64_t child_usr_micros = micros(child_usage[1].ru_utime) - micros(child_usage[0].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); - uint64_t net_sys_micros = fish_sys_micros + child_sys_micros; - uint64_t net_usr_micros = fish_usr_micros + child_usr_micros; - uint64_t net_wall_micros = micros(wall[1]) - micros(wall[0]); + 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(wall[1]) - micros(wall[0]); enum class unit { minutes, @@ -109,13 +127,12 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { microseconds, }; - auto get_unit = [](uint64_t micros) { + auto get_unit = [](int64_t micros) { if (micros > 900 * 1E6) { return unit::minutes; - } - else if (micros > 1 * 1E6) { + } else if (micros > 1 * 1E6) { return unit::seconds; - } else if (micros > 10E3) { + } else if (micros > 1E3) { return unit::milliseconds; } else { return unit::microseconds; @@ -131,7 +148,16 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { } }; - auto convert = [](uint64_t micros, unit unit) { + auto unit_short_name = [](unit unit) { + switch (unit) { + case unit::minutes: return "mins"; + case unit::seconds: return "secs"; + case unit::milliseconds: return "millis"; + case unit::microseconds: return "micros"; + } + }; + + auto convert = [](int64_t micros, unit unit) { switch (unit) { case unit::minutes: return micros / 1.0E6 / 60.0; case unit::seconds: return micros / 1.0E6; @@ -146,16 +172,43 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { auto usr_time = convert(net_usr_micros, cpu_unit); auto sys_time = convert(net_sys_micros, cpu_unit); - streams.out.append_format( - L"\n__________________________________" \ - L"\nExecuted in %6.2F %s" \ - L"\n usr time %6.2F %s" \ - L"\n sys time %6.2F %s" \ - L"\n\n", - wall_time, unit_name(wall_unit), - usr_time, unit_name(cpu_unit), - sys_time, unit_name(cpu_unit) - ); + if (!verbose) { + streams.err.append_format( + L"\n_______________________________" \ + L"\nExecuted in %6.2F %s" \ + L"\n usr time %6.2F %s" \ + L"\n sys time %6.2F %s" \ + L"\n\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((fish_sys_micros + fish_usr_micros) / 2); + auto child_unit = get_unit((child_sys_micros + child_usr_micros) / 2); + auto fish_usr_time = convert(fish_usr_micros, fish_unit); + auto fish_sys_time = convert(fish_sys_micros, fish_unit); + auto child_usr_time = convert(child_usr_micros, child_unit); + auto child_sys_time = convert(child_sys_micros, child_unit); + + streams.err.append_format( + 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\n", + wall_time, unit_short_name(wall_unit), + strlen(unit_short_name(wall_unit)) - 1, "fish", + strlen(unit_short_name(fish_unit)) - 1, "external", + usr_time, unit_short_name(cpu_unit), + fish_usr_time, unit_short_name(fish_unit), + child_usr_time, unit_short_name(child_unit), + sys_time, unit_short_name(cpu_unit), + fish_sys_time, unit_short_name(fish_unit), + child_sys_time, unit_short_name(child_unit) + ); + + } } From 704a90deec9b26f7e5074b4f1953f6fc8127c7f6 Mon Sep 17 00:00:00 2001 From: Mahmoud Al-Qudsi Date: Wed, 18 Dec 2019 20:48:02 -0600 Subject: [PATCH 4/5] Rename time `unit` enum to please gcc --- src/builtin_time.cpp | 40 ++++++++++++++++++++-------------------- 1 file changed, 20 insertions(+), 20 deletions(-) diff --git a/src/builtin_time.cpp b/src/builtin_time.cpp index 09215fc4f..2eb56ae3f 100644 --- a/src/builtin_time.cpp +++ b/src/builtin_time.cpp @@ -120,7 +120,7 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { int64_t net_usr_micros = fish_usr_micros + child_usr_micros; int64_t net_wall_micros = micros(wall[1]) - micros(wall[0]); - enum class unit { + enum class tunit { minutes, seconds, milliseconds, @@ -129,40 +129,40 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { auto get_unit = [](int64_t micros) { if (micros > 900 * 1E6) { - return unit::minutes; + return tunit::minutes; } else if (micros > 1 * 1E6) { - return unit::seconds; + return tunit::seconds; } else if (micros > 1E3) { - return unit::milliseconds; + return tunit::milliseconds; } else { - return unit::microseconds; + return tunit::microseconds; } }; - auto unit_name = [](unit unit) { + auto unit_name = [](tunit unit) { switch (unit) { - case unit::minutes: return "minutes"; - case unit::seconds: return "seconds"; - case unit::milliseconds: return "milliseconds"; - case unit::microseconds: return "microseconds"; + case tunit::minutes: return "minutes"; + case tunit::seconds: return "seconds"; + case tunit::milliseconds: return "milliseconds"; + case tunit::microseconds: return "microseconds"; } }; - auto unit_short_name = [](unit unit) { + auto unit_short_name = [](tunit unit) { switch (unit) { - case unit::minutes: return "mins"; - case unit::seconds: return "secs"; - case unit::milliseconds: return "millis"; - case unit::microseconds: return "micros"; + case tunit::minutes: return "mins"; + case tunit::seconds: return "secs"; + case tunit::milliseconds: return "millis"; + case tunit::microseconds: return "micros"; } }; - auto convert = [](int64_t micros, unit unit) { + auto convert = [](int64_t micros, tunit unit) { switch (unit) { - case unit::minutes: return micros / 1.0E6 / 60.0; - case unit::seconds: return micros / 1.0E6; - case unit::milliseconds: return micros / 1.0E3; - case unit::microseconds: return micros / 1.0; + 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; } }; From 103726767c001476b413949ce65ba9aa364ab8ad Mon Sep 17 00:00:00 2001 From: Mahmoud Al-Qudsi Date: Wed, 18 Dec 2019 20:53:38 -0600 Subject: [PATCH 5/5] [time] Convince GCC control flow does not reach end of function --- src/builtin_time.cpp | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/builtin_time.cpp b/src/builtin_time.cpp index 2eb56ae3f..0f161be57 100644 --- a/src/builtin_time.cpp +++ b/src/builtin_time.cpp @@ -146,6 +146,8 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { 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) { @@ -155,6 +157,8 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { 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) { @@ -164,6 +168,8 @@ int builtin_time(parser_t &parser, io_streams_t &streams, wchar_t **argv) { 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);