From 5e652e94a9203e0cfa27e93a89878439b7900001 Mon Sep 17 00:00:00 2001 From: Maxim Cournoyer Date: Tue, 2 Feb 2021 00:28:49 -0500 Subject: [PATCH] build: Add a --show-duration option to the SCM test-driver. * build-aux/test-driver.scm (script-version): Update. (show-help): Document it. (%options): Add the 'show-duration' option. (test-runner-gnu): Pass as a new argument. [test-cases-start-time]: New inner variable. [test-on-test-begin-gnu]: New hook, used to record the start time. [test-on-test-end-gnu]: Conditionally print elapsed time. Record it as the optional metadata in the test result file (.trs). * doc/guix.texi (Running the Test Suite): Document it. --- build-aux/test-driver.scm | 43 +++++++++++++++++++++++++++++++-------- doc/guix.texi | 10 ++++++++- 2 files changed, 43 insertions(+), 10 deletions(-) diff --git a/build-aux/test-driver.scm b/build-aux/test-driver.scm index ac21783d41..1cdd4ff8f7 100755 --- a/build-aux/test-driver.scm +++ b/build-aux/test-driver.scm @@ -3,7 +3,7 @@ exec guile --no-auto-compile -e main -s "$0" "$@" !# ;;;; test-driver.scm - Guile test driver for Automake testsuite harness -(define script-version "2021-01-26.20") ;UTC +(define script-version "2021-02-02.05") ;UTC ;;; Copyright © 2015, 2016 Mathieu Lirzin ;;; Copyright © 2021 Maxim Cournoyer @@ -28,10 +28,12 @@ exec guile --no-auto-compile -e main -s "$0" "$@" ;;; ;;;; Code: -(use-modules (ice-9 getopt-long) +(use-modules (ice-9 format) + (ice-9 getopt-long) (ice-9 pretty-print) (ice-9 regex) (srfi srfi-1) + (srfi srfi-19) (srfi srfi-26) (srfi srfi-64)) @@ -40,14 +42,16 @@ exec guile --no-auto-compile -e main -s "$0" "$@" test-driver --test-name=NAME --log-file=PATH --trs-file=PATH [--expect-failure={yes|no}] [--color-tests={yes|no}] [--select=REGEXP] [--exclude=REGEXP] [--errors-only={yes|no}] - [--enable-hard-errors={yes|no}] [--brief={yes|no}}] [--] + [--enable-hard-errors={yes|no}] [--brief={yes|no}}] + [--show-duration={yes|no}] [--] TEST-SCRIPT [TEST-SCRIPT-ARGUMENTS] The '--test-name' option is mandatory. The '--select' and '--exclude' options allow selecting or excluding individual test cases via a regexp, respectively. The '--errors-only' option can be set to \"yes\" to limit the logged test case metadata to only those test cases that failed. When set to \"yes\", the '--brief' option disables printing the individual test case result to the -console.\n")) +console. When '--show-duration' is set to \"yes\", the time elapsed per test +case is shown.\n")) (define %options '((test-name (value #t)) @@ -60,6 +64,7 @@ console.\n")) (expect-failure (value #t)) ;XXX: not implemented yet (enable-hard-errors (value #t)) ;not implemented in SRFI-64 (brief (value #t)) + (show-duration (value #t)) (help (single-char #\h) (value #f)) (version (single-char #\V) (value #f)))) @@ -96,6 +101,7 @@ console.\n")) ;;; (define* (test-runner-gnu test-name #:key color? brief? errors-only? + show-duration? (out-port (current-output-port)) (trs-port (%make-void-port "w")) select exclude) @@ -109,6 +115,15 @@ defaults to a void port, which means no TRS output is logged. SELECT and EXCLUDE may take a regular expression to select or exclude individual test cases based on their names." + (define test-cases-start-time (make-hash-table)) + + (define (test-on-test-begin-gnu runner) + ;; Procedure called at the start of an individual test case, before the + ;; test expression (and expected value) are evaluated. + (let ((test-case-name (test-runner-test-name runner)) + (start-time (current-time time-monotonic))) + (hash-set! test-cases-start-time test-case-name start-time))) + (define (test-skipped? runner) (eq? 'skip (test-result-kind runner))) @@ -121,12 +136,19 @@ cases based on their names." ;; of the test is available. (let* ((results (test-result-alist runner)) (result? (cut assq <> results)) - (result (cut assq-ref results <>))) + (result (cut assq-ref results <>)) + (test-case-name (test-runner-test-name runner)) + (start (hash-ref test-cases-start-time test-case-name)) + (end (current-time time-monotonic)) + (time-elapsed (time-difference end start)) + (time-elapsed-seconds (+ (time-second time-elapsed) + (* 1e-9 (time-nanosecond time-elapsed))))) (unless (or brief? (and errors-only? (test-skipped? runner))) ;; Display the result of each test case on the console. - (format out-port "~A: ~A - ~A~%" + (format out-port "~a: ~a - ~a ~@[[~,3fs]~]~%" (result->string (test-result-kind runner) #:colorize? color?) - test-name (test-runner-test-name runner))) + test-name test-case-name + (and show-duration? time-elapsed-seconds))) (unless (and errors-only? (not (test-failed? runner))) (format #t "test-name: ~A~%" (result 'test-name)) @@ -145,9 +167,9 @@ cases based on their names." (format #t "result: ~a~%" (result->string (result 'result-kind))) (newline)) - (format trs-port ":test-result: ~A ~A~%" + (format trs-port ":test-result: ~A ~A [~,3fs]~%" (result->string (test-result-kind runner)) - (test-runner-test-name runner)))) + (test-runner-test-name runner) time-elapsed-seconds))) (define (test-on-group-end-gnu runner) ;; Procedure called by a 'test-end', including at the end of a test-group. @@ -171,6 +193,7 @@ cases based on their names." #f)) (let ((runner (test-runner-null))) + (test-runner-on-test-begin! runner test-on-test-begin-gnu) (test-runner-on-test-end! runner test-on-test-end-gnu) (test-runner-on-group-end! runner test-on-group-end-gnu) (test-runner-on-bad-end-name! runner test-on-bad-end-name-simple) @@ -239,6 +262,8 @@ cases based on their names." #:color? color-tests #:brief? (option->boolean opts 'brief) #:errors-only? (option->boolean opts 'errors-only) + #:show-duration? (option->boolean + opts 'show-duration) #:out-port out #:trs-port trs) (test-apply test-specifier (lambda _ diff --git a/doc/guix.texi b/doc/guix.texi index beff276f9d..598d3d6773 100644 --- a/doc/guix.texi +++ b/doc/guix.texi @@ -48,7 +48,7 @@ Copyright @copyright{} 2017 humanitiesNerd@* Copyright @copyright{} 2017 Christopher Allan Webber@* Copyright @copyright{} 2017, 2018, 2019, 2020 Marius Bakke@* Copyright @copyright{} 2017, 2019, 2020 Hartmut Goebel@* -Copyright @copyright{} 2017, 2019, 2020 Maxim Cournoyer@* +Copyright @copyright{} 2017, 2019, 2020, 2021 Maxim Cournoyer@* Copyright @copyright{} 2017, 2018, 2019, 2020 Tobias Geerinckx-Rice@* Copyright @copyright{} 2017 George Clemmer@* Copyright @copyright{} 2017 Andy Wingo@* @@ -942,6 +942,14 @@ Automake makefile variable, as in: make check SCM_LOG_DRIVER_FLAGS="--brief=no --errors-only=yes" VERBOSE=1 @end example +The @option{--show-duration=yes} option can be used to print the +duration of the individual test cases, when used in combination with +@option{--brief=no}: + +@example +make check SCM_LOG_DRIVER_FLAGS="--brief=no --show-duration=yes" +@end example + @xref{Parallel Test Harness,,,automake,GNU Automake} for more information about the Automake Parallel Test Harness.