headless-browser: Add an option to log per-test durations

This adds a verbosity option to log the start and end of each test, with
the duration taken for the test. To be able to use this option with our
exisiting verbosity flag, without cluttering stdout with other data, we
add verbosity levels to headless-browser. The level is increased by
providing the -v flag on the command line multiple times.

UI/Headless/Application.cpp

@@ -45,9 +45,23 @@ void Application::create_platform_arguments(Core::ArgsParser& args_parser)
     args_parser.add_option(is_layout_test_mode, "Enable layout test mode", "layout-test-mode");
     args_parser.add_option(rebaseline, "Rebaseline any executed layout or text tests", "rebaseline");
     args_parser.add_option(per_test_timeout_in_seconds, "Per-test timeout (default: 30)", "per-test-timeout", 't', "seconds");
-    args_parser.add_option(verbose, "Log extra information about test results", "verbose", 'v');
     args_parser.add_option(width, "Set viewport width in pixels (default: 800)", "width", 'W', "pixels");
     args_parser.add_option(height, "Set viewport height in pixels (default: 600)", "height", 'H', "pixels");
+
+    args_parser.add_option(Core::ArgsParser::Option {
+        .argument_mode = Core::ArgsParser::OptionArgumentMode::Optional,
+        .help_string = "Log extra information about test results (use multiple times for more information)",
+        .long_name = "verbose",
+        .short_name = 'v',
+        .accept_value = [&](StringView value) -> ErrorOr<bool> {
+            if (value.is_empty() && verbosity < NumericLimits<u8>::max()) {
+                ++verbosity;
+                return true;
+            }
+
+            return false;
+        },
+    });
 }
 
 void Application::create_platform_options(WebView::ChromeOptions& chrome_options, WebView::WebContentOptions& web_content_options)

UI/Headless/Application.h

@@ -44,6 +44,10 @@ public:
             callback(*web_view);
     }
 
+    static constexpr u8 VERBOSITY_LEVEL_LOG_TEST_DURATION = 1;
+    static constexpr u8 VERBOSITY_LEVEL_LOG_SLOWEST_TESTS = 2;
+    static constexpr u8 VERBOSITY_LEVEL_LOG_SKIPPED_TESTS = 3;
+
     int screenshot_timeout { 1 };
     ByteString resources_folder;
     bool dump_failed_ref_tests { false };
@@ -57,7 +61,7 @@ public:
     ByteString test_glob;
     bool test_dry_run { false };
     bool rebaseline { false };
-    bool verbose { false };
+    u8 verbosity { 0 };
     int per_test_timeout_in_seconds { 30 };
     int width { 800 };
     int height { 600 };

UI/Headless/Test.cpp

@@ -443,7 +443,8 @@ ErrorOr<void> run_tests(Core::AnonymousBuffer const& theme, Web::DevicePixelSize
     size_t skipped_count = 0;
     bool all_tests_ok = true;
 
-    bool is_tty = isatty(STDOUT_FILENO);
+    // Keep clearing and reusing the same line if stdout is a TTY.
+    bool log_on_one_line = app.verbosity < Application::VERBOSITY_LEVEL_LOG_TEST_DURATION && isatty(STDOUT_FILENO) == 1;
     outln("Running {} tests...", tests.size());
 
     auto all_tests_complete = Core::Promise<Empty>::construct();
@@ -462,19 +463,15 @@ ErrorOr<void> run_tests(Core::AnonymousBuffer const& theme, Web::DevicePixelSize
 
             auto& test = tests[index];
             test.start_time = UnixDateTime::now();
+            test.index = index + 1;
 
-            if (is_tty) {
-                // Keep clearing and reusing the same line if stdout is a TTY.
-                out("\33[2K\r");
+            if (log_on_one_line) {
+                out("\33[2K\r{}/{}: {}", test.index, tests.size(), test.relative_path);
+                (void)fflush(stdout);
+            } else {
+                outln("{}/{}:  Start {}", test.index, tests.size(), test.relative_path);
             }
 
-            out("{}/{}: {}", index + 1, tests.size(), test.relative_path);
-
-            if (is_tty)
-                fflush(stdout);
-            else
-                outln("");
-
             Core::deferred_invoke([&]() mutable {
                 if (s_skipped_tests.contains_slow(test.input_path))
                     view.on_test_complete({ test, TestResult::Skipped });
@@ -486,6 +483,11 @@ ErrorOr<void> run_tests(Core::AnonymousBuffer const& theme, Web::DevicePixelSize
         view.test_promise().when_resolved([&, run_next_test](auto result) {
             result.test.end_time = UnixDateTime::now();
 
+            if (app.verbosity >= Application::VERBOSITY_LEVEL_LOG_TEST_DURATION) {
+                auto duration = result.test.end_time - result.test.start_time;
+                outln("{}/{}: Finish {}: {}ms", result.test.index, tests.size(), result.test.relative_path, duration.to_milliseconds());
+            }
+
             switch (result.result) {
             case TestResult::Pass:
                 ++pass_count;
@@ -523,7 +525,7 @@ ErrorOr<void> run_tests(Core::AnonymousBuffer const& theme, Web::DevicePixelSize
 
     MUST(all_tests_complete->await());
 
-    if (is_tty)
+    if (log_on_one_line)
         outln("\33[2K\rDone!");
 
     outln("==========================================================");
@@ -531,13 +533,13 @@ ErrorOr<void> run_tests(Core::AnonymousBuffer const& theme, Web::DevicePixelSize
     outln("==========================================================");
 
     for (auto const& non_passing_test : non_passing_tests) {
-        if (non_passing_test.result == TestResult::Skipped && !app.verbose)
+        if (non_passing_test.result == TestResult::Skipped && app.verbosity < Application::VERBOSITY_LEVEL_LOG_SKIPPED_TESTS)
             continue;
 
         outln("{}: {}", test_result_to_string(non_passing_test.result), non_passing_test.test.relative_path);
     }
 
-    if (app.verbose) {
+    if (app.verbosity >= Application::VERBOSITY_LEVEL_LOG_SLOWEST_TESTS) {
         auto tests_to_print = min(10uz, tests.size());
         outln("\nSlowest {} tests:", tests_to_print);
 

UI/Headless/Test.h

@@ -63,6 +63,7 @@ struct Test {
 
     UnixDateTime start_time {};
     UnixDateTime end_time {};
+    size_t index { 0 };
 
     String text {};
     bool did_finish_test { false };