From f864bd83ad4cb7cf4ea2c330bf14d3660b4f00c3 Mon Sep 17 00:00:00 2001 From: afg Date: Tue, 10 Mar 2020 01:22:19 +0800 Subject: [PATCH] time builtin: align output columns on rare cases 1. When the wall time and cpu time rows has different units e.x. running multiple cores 2. When duration is around 1E3 or 1E6 microseconds printf("%6.2F", 999.995) gives 1000.00 which is 7 digits --- src/fish_tests.cpp | 33 +++++++++++++++++++++++++++++++++ src/timer.cpp | 24 +++++++++++++----------- 2 files changed, 46 insertions(+), 11 deletions(-) diff --git a/src/fish_tests.cpp b/src/fish_tests.cpp index 73ce0616b..581195ff9 100644 --- a/src/fish_tests.cpp +++ b/src/fish_tests.cpp @@ -28,6 +28,7 @@ #include #include #include +#include #include #include #include @@ -72,6 +73,7 @@ #include "redirection.h" #include "screen.h" #include "signal.h" +#include "timer.h" #include "tnode.h" #include "tokenizer.h" #include "topic_monitor.h" @@ -5641,6 +5643,36 @@ static void test_topic_monitor_torture() { for (auto &t : threads) t.join(); } +static void test_timer_format() { + say(L"Testing timer format"); + 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\n\Expected: %ls\nActual:%ls\n", expected, + actual.c_str()); + } +} + /// Main test. int main(int argc, char **argv) { UNUSED(argc); @@ -5770,6 +5802,7 @@ int main(int argc, char **argv) { if (should_test_function("normalize")) test_normalize_path(); if (should_test_function("topics")) test_topic_monitor(); if (should_test_function("topics")) test_topic_monitor_torture(); + if (should_test_function("timer_format")) test_timer_format(); // history_tests_t::test_history_speed(); say(L"Encountered %d errors in low-level tests", err_count); diff --git a/src/timer.cpp b/src/timer.cpp index 53e0d996a..250bf79e3 100644 --- a/src/timer.cpp +++ b/src/timer.cpp @@ -101,9 +101,9 @@ wcstring timer_snapshot_t::print_delta(timer_snapshot_t t1, timer_snapshot_t t2, auto get_unit = [](int64_t micros) { if (micros > 900 * 1E6) { return tunit::minutes; - } else if (micros > 1 * 1E6) { + } else if (micros >= 999995) { return tunit::seconds; - } else if (micros > 1E3) { + } else if (micros >= 1000) { return tunit::milliseconds; } else { return tunit::microseconds; @@ -179,18 +179,20 @@ wcstring timer_snapshot_t::print_delta(timer_snapshot_t t1, timer_snapshot_t t2, auto child_usr_time = convert(child_usr_micros, child_unit); auto child_sys_time = convert(child_sys_micros, child_unit); + auto 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"\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, 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)); + wall_time, column2_unit_len, unit_short_name(wall_unit), + 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;