Add YAML-ish durations to TAP format

README.md

@@ -61,6 +61,19 @@ You can force TAP output from a terminal by invoking Bats with the
     ok 1 addition using bc
     ok 2 addition using dc
 
+Additionally, using the -d parameter, you can time your tests and output the test durations in a common TAP extension format: YAML-ish.  Use this in conjuction with the [Jenkins TAP Plugin](https://wiki.jenkins-ci.org/display/JENKINS/TAP+Plugin) to display your test times!
+
+    $ bats --tap -d addition.bats
+    1..2
+    ok 1 addition using bc
+      ---
+        duration_ms: 21
+      ...
+    ok 2 addition using dc
+      ---
+        duration_ms: 22
+      ...
+
 ### Test suites
 
 You can invoke the `bats` interpreter with multiple test file

libexec/bats

@@ -20,6 +20,7 @@ help() {
   echo "  -h, --help     Display this help message"
   echo "  -p, --pretty   Show results in pretty format (default for terminals)"
   echo "  -t, --tap      Show results in TAP format"
+  echo "  -d             Durations for TAP output with YAML format"
   echo "  -v, --version  Display the version number"
   echo
   echo "  For more information, see https://github.com/sstephenson/bats"
@@ -96,6 +97,9 @@ for option in "${options[@]}"; do
   "t" | "tap" )
     pretty=""
     ;;
+  "d" )
+    durations_flag="-d"
+    ;;
   "p" | "pretty" )
     pretty="1"
     ;;
@@ -139,4 +143,4 @@ else
 fi
 
 set -o pipefail execfail
-exec "$command" $count_flag $extended_syntax_flag "${filenames[@]}" | "$formatter"
+exec "$command" $count_flag $extended_syntax_flag $durations_flag "${filenames[@]}" | "$formatter"

libexec/bats-exec-suite

@@ -13,6 +13,12 @@ if [ "$1" = "-x" ]; then
   shift
 fi
 
+durations_flag=""
+if [ "$1" = "-d" ]; then
+  durations_flag="-d"
+  shift
+fi
+
 trap "kill 0; exit 1" int
 
 count=0
@@ -48,7 +54,7 @@ for filename in "$@"; do
         ;;
       esac
     done
-  } < <( bats-exec-test $extended_syntax_flag "$filename" )
+  } < <( bats-exec-test $extended_syntax_flag $durations_flag "$filename" )
   offset=$(($offset + $index))
 done
 

libexec/bats-exec-test

@@ -15,6 +15,12 @@ if [ "$1" = "-x" ]; then
   shift
 fi
 
+BATS_RECORD_DURATIONS=""
+if [ "$1" = "-d" ]; then
+  BATS_RECORD_DURATIONS=$1
+  shift
+fi
+
 BATS_TEST_FILENAME="$1"
 if [ -z "$BATS_TEST_FILENAME" ]; then
   echo "usage: bats-exec <filename>" >&2
@@ -224,6 +230,18 @@ bats_error_trap() {
   trap - debug
 }
 
+
+get_mills_since_epoch() {
+  local ms_since_epoch=$(date +%s%N)
+  if [[ "$ms_since_epoch" == *N ]]; then
+        ms_since_epoch=$(( $(date +%s) * 1000 ))
+  else
+        ms_since_epoch=$(( ms_since_epoch / 1000000 ))
+  fi
+
+  echo $ms_since_epoch
+}
+
 bats_teardown_trap() {
   trap "bats_exit_trap" exit
   local status=0
@@ -236,6 +254,8 @@ bats_teardown_trap() {
     BATS_ERROR_STACK_TRACE=( "${BATS_CURRENT_STACK_TRACE[@]}" )
   fi
 
+  BATS_TEST_DURATION=$(( $(get_mills_since_epoch) - BATS_TEST_START_TIME ))
+
   bats_exit_trap
 }
 
@@ -263,6 +283,12 @@ bats_exit_trap() {
     status=0
   fi
 
+  if [[ -z $BATS_EXTENDED_SYNTAX && -n $BATS_RECORD_DURATIONS && -n $BATS_TEST_DURATION ]]; then
+    echo "  ---" >&3
+    echo "    duration_ms: $BATS_TEST_DURATION" >&3
+    echo "  ..." >&3
+  fi
+
   rm -f "$BATS_OUT"
   exit "$status"
 }
@@ -272,7 +298,7 @@ bats_perform_tests() {
   test_number=1
   status=0
   for test_name in "$@"; do
-    "$0" $BATS_EXTENDED_SYNTAX "$BATS_TEST_FILENAME" "$test_name" "$test_number" || status=1
+    "$0" $BATS_EXTENDED_SYNTAX $BATS_RECORD_DURATIONS "$BATS_TEST_FILENAME" "$test_name" "$test_number" || status=1
     let test_number+=1
   done
   exit "$status"
@@ -288,10 +314,11 @@ bats_perform_test() {
     fi
 
     BATS_TEST_COMPLETED=""
+    BATS_TEST_START_TIME=$(get_mills_since_epoch)
     BATS_TEARDOWN_COMPLETED=""
     trap "bats_debug_trap \"\$BASH_SOURCE\"" debug
     trap "bats_error_trap" err
-    trap "bats_teardown_trap" exit
+    trap "bats_teardown_trap $BATS_RECORD_DURATIONS" exit
     "$BATS_TEST_NAME" >>"$BATS_OUT" 2>&1
     BATS_TEST_COMPLETED=1
 

test/bats.bats

@@ -262,3 +262,22 @@ fixtures bats
   [ $status -eq 0 ]
   [ "${lines[1]}" = "ok 1 loop_func" ]
 }
+
+@test "tests with durations" {
+  run bats -d $FIXTURE_ROOT/passing_failing_and_skipping.bats
+  [ "$status" -eq 1 ]
+
+  [ "${lines[1]}"       =  'ok 1 a passing test' ]
+  [ "${lines[2]}"       =  '  ---' ]
+  [ "${lines[3]:0:17}"  =  '    duration_ms: ' ]
+  [ "${lines[4]}"       =  '  ...' ]
+  [ "${lines[5]}"       =  'ok 2 # skip a skipping test' ]
+  [ "${lines[6]}"       =  '  ---' ]
+  [ "${lines[7]:0:17}"  =  '    duration_ms: ' ]
+  [ "${lines[8]}"       =  '  ...' ]
+  [ "${lines[9]}"       =  'not ok 3 a failing test' ]
+  [ "${lines[10]:0:15}"      =  '# (in test file' ]
+  [ "${lines[12]}"      =  '  ---' ]
+  [ "${lines[13]:0:17}" =  '    duration_ms: ' ]
+  [ "${lines[14]}"      =  '  ...' ]
+}