Add profiler

lib/core/dsl.sh

@@ -57,10 +57,12 @@ shellspec_example() {
       shellspec_output EXAMPLE
       shellspec_output SUCCEEDED
     else
+      shellspec_profile_start
       # This {} is workaround for zsh 5.4.2
       # I think this bug is related to #12 in contrib/bugs.sh
       # But I do not know why this works well.
       { shellspec_invoke_example; }
+      shellspec_profile_end
     fi
   fi
 }
@@ -224,3 +226,15 @@ shellspec_abort() {
   [ "${3:-}" ] && shellspec_putsn "${3:-}" >&2
   exit "${1:-1}"
 }
+
+if [ "$SHELLSPEC_PROFILER" ]; then
+  shellspec_profile_start() {
+    kill -USR1 "$SHELLSPEC_PROFILER_PID"
+  }
+  shellspec_profile_end() {
+    kill -USR1 "$SHELLSPEC_PROFILER_PID"
+  }
+else
+  shellspec_profile_start() { :; }
+  shellspec_profile_end() { :; }
+fi

lib/core/output.sh

@@ -13,7 +13,9 @@ shellspec_output_raw() {
     begin)
       set -- "type:$@" "example_count:" ;;
     example)
-      set -- "type:$@" "evaluation:" "pending:" ;;
+      set -- "type:$@" "evaluation:" "pending:" \
+        "lineno_begin:$SHELLSPEC_LINENO_BEGIN" \
+        "lineno_end:$SHELLSPEC_LINENO_END";;
     statement)
       set -- "type:$@" "lineno:${SHELLSPEC_LINENO:-$SHELLSPEC_LINENO_BEGIN}" ;;
     *)

lib/libexec/reporter/documentation_formatter.sh

@@ -6,7 +6,7 @@
 documentation_last_id=''
 create_buffers documentation
 
-require_formatters methods conclusion finished summary references
+require_formatters methods conclusion finished summary references profiler
 [ "$SHELLSPEC_KCOV" ] && require_formatters kcov
 
 documentation_each() {
@@ -39,7 +39,7 @@ documentation_each() {
 }
 
 documentation_output() {
-  output "$1" methods conclusion finished summary references
+  output "$1" methods conclusion finished summary references profiler
   if [ "$SHELLSPEC_KCOV" ]; then output "$1" kcov; fi
   documentation '>>>'
 }

lib/libexec/reporter/profiler_formatter.sh

@@ -0,0 +1,29 @@
+#shellcheck shell=sh disable=SC2004
+
+: "${field_type:-} ${profiler_count:-} ${example_count:-}"
+
+profiler_each() {
+  [ "$SHELLSPEC_PROFILER" ] || return 0
+  [ "$field_type" = example ] || return 0
+  eval "profiler_line$example_count=\$field_specfile:\$field_lineno_begin"
+}
+
+profiler_output() {
+  [ "$SHELLSPEC_PROFILER" ] || return 0
+  case $1 in (end)
+    _i=0
+    while [ $_i -lt "$profiler_count" ]; do
+      eval "putsn \$profiler_time$_i \"\$profiler_line$_i\""
+      _i=$(($_i + 1))
+    done | sort -k 1 -n -r | {
+      _i=0
+      #shellcheck disable=SC2034
+      while IFS=" " read -r _tick _duration _line; do
+        [ "$_i" -ge "$SHELLSPEC_PROFILER_LIMIT" ] && break
+        _i=$(($_i + 1))
+        putsn "${BOLD}${BLACK}$_i $_duration $_line${RESET}"
+      done
+    }
+    putsn
+  esac
+}

lib/libexec/reporter/progress_formatter.sh

@@ -2,7 +2,7 @@
 
 : "${field_type:-} ${field_tag:-} ${field_color:-}"
 
-require_formatters methods conclusion finished summary references
+require_formatters methods conclusion finished summary references profiler
 [ "$SHELLSPEC_KCOV" ] && require_formatters kcov
 
 create_buffers progress
@@ -26,6 +26,6 @@ progress_end() {
 
 progress_output() {
   progress '>>>'
-  output "$1" methods conclusion finished summary references
+  output "$1" methods conclusion finished summary references profiler
   if [ "$SHELLSPEC_KCOV" ]; then output "$1" kcov; fi
 }

libexec/shellspec-profiler.sh

@@ -0,0 +1,28 @@
+#!/bin/sh
+#shellcheck disable=SC2004
+
+set -eu
+
+handler() {
+  eval "counter${index}=$counter"
+  index=$(($index + 1))
+}
+
+terminate() {
+  i=0 start='' end=''
+  while [ $i -lt $index ]; do
+    eval "start=\$counter${i} end=\${counter$(($i + 1)):-}"
+    [ "$end" ] || break
+    echo "$(($end - $start))" >> "$SHELLSPEC_PROFILER_LOG"
+    i=$(($i + 2))
+  done
+  exit
+}
+
+trap handler USR1
+trap terminate TERM
+
+index=0 counter=0
+while :; do
+  counter=$(($counter + 1))
+done

libexec/shellspec-reporter.sh

@@ -139,8 +139,25 @@ parse_lines
 
 callback() { [ -e "$SHELLSPEC_TIME_LOG" ] || sleep 0; }
 sequence callback 1 10
+time_real='' time_real_nano=''
 read_time_log "time" "$SHELLSPEC_TIME_LOG"
 
+if [ "$SHELLSPEC_PROFILER" ] && [ "$SHELLSPEC_PROFILER_LOG" ]; then
+  profiler_tick_total=0
+  while IFS=" " read -r profiler_tick; do
+    profiler_tick_total=$(($profiler_tick_total + $profiler_tick))
+  done < "$SHELLSPEC_PROFILER_LOG"
+
+  shellspec_shift10 time_real_nano "$time_real" 6
+  profiler_count=0
+  while IFS=" " read -r profiler_tick; do
+    profiler_duration=$(($time_real_nano * $profiler_tick / $profiler_tick_total))
+    shellspec_shift10 profiler_duration "$profiler_duration" -6
+    eval "profiler_time$profiler_count=\"$profiler_tick $profiler_duration\""
+    profiler_count=$(($profiler_count + 1))
+  done < "$SHELLSPEC_PROFILER_LOG"
+fi
+
 output_formatters end
 
 generators cleanup "$@"

libexec/shellspec-runner.sh

@@ -14,10 +14,30 @@ wait_reporter_finished() {
   done
 }
 
+start_profiler() {
+  [ "$SHELLSPEC_PROFILER" ] || return 0
+  profiler="$SHELLSPEC_LIBEXEC/shellspec-profiler.sh"
+  $SHELLSPEC_SHELL "$profiler" &
+  SHELLSPEC_PROFILER_PID=$!
+}
+
+stop_profiler() {
+  [ "$SHELLSPEC_PROFILER_PID" ] || return 0
+  kill -TERM "$SHELLSPEC_PROFILER_PID"
+  while kill -0 "$SHELLSPEC_PROFILER_PID" 2>/dev/null; do
+    sleep 0
+  done
+  SHELLSPEC_PROFILER_PID=''
+}
+
 mktempdir "$SHELLSPEC_TMPBASE"
 cleanup() {
   if (trap - INT) 2>/dev/null; then trap '' INT; fi
   [ "$SHELLSPEC_TMPBASE" ] || return 0
+  if [ "$SHELLSPEC_PROFILER_PID" ]; then
+    kill -TERM "$SHELLSPEC_PROFILER_PID" 2>/dev/null ||:
+    SHELLSPEC_PROFILER_PID=''
+  fi
   tmpbase="$SHELLSPEC_TMPBASE"
   SHELLSPEC_TMPBASE=''
   rmtempdir "$tmpbase"
@@ -29,6 +49,7 @@ trap 'cleanup' EXIT
 
 interrupt() {
   trap '' TERM # posh: Prevent display 'Terminated'.
+  stop_profiler
   wait_reporter_finished "$SHELLSPEC_TMPBASE/reporter_pid"
   kill -TERM 0
   cleanup
@@ -43,6 +64,7 @@ executor() {
   # shellcheck disable=SC2086
   command $SHELLSPEC_TIME $SHELLSPEC_SHELL "$executor" "$@" \
     3>&2 2>"$SHELLSPEC_TIME_LOG"
+  stop_profiler
 }
 
 reporter() {
@@ -78,6 +100,8 @@ if [ "${SHELLSPEC_RANDOM:-}" ]; then
   set -- -
 fi
 
+start_profiler
+
 # I want to process with non-blocking output
 # and the stdout of runner streams to the reporter
 # and capture stderr both of the runner and the reporter

shellspec

@@ -54,6 +54,10 @@ export SHELLSPEC_KCOV_COMMON_OPTS=''
 export SHELLSPEC_KCOV_OPTS=''
 export SHELLSPEC_KCOV_FILENAME=''
 export SHELLSPEC_KCOV_IN_FILE=''
+export SHELLSPEC_PROFILER=''
+export SHELLSPEC_PROFILER_PID=''
+export SHELLSPEC_PROFILER_LOG=''
+export SHELLSPEC_PROFILER_LIMIT=10
 
 #shellcheck disable=SC2039
 export SHELLSPEC_HOSTNAME=${HOSTNAME:-localhost}
@@ -92,6 +96,7 @@ SHELLSPEC_UNIXTIME=$(date +%s)
 SHELLSPEC_TMPBASE="${SHELLSPEC_TMPDIR%/}/shellspec.$SHELLSPEC_UNIXTIME.$$"
 SHELLSPEC_TIME_LOG="$SHELLSPEC_TMPBASE/time.log"
 SHELLSPEC_EXAMPLES_LOG="$SHELLSPEC_TMPBASE/examples.log"
+SHELLSPEC_PROFILER_LOG="$SHELLSPEC_TMPBASE/profiler.log"
 SHELLSPEC_BANNER="$SHELLSPEC_SPECDIR/banner"
 
 SHELLSPEC_TIME="$SHELLSPEC_LIBEXEC/shellspec-time.sh"
@@ -154,6 +159,8 @@ Usage: shellspec [options] [files or directories]
                                         [verbose]  do not mute any messages [default]
                                         [moderate] mute repeated messages
                                         [quiet]    mute repeated messages and non-temporarily messages
+  -p  --[no-]profile                  Enable profiling of examples and list the slowest examples
+      --profile-limit N               List the top N slowest examples (default: 10)
 
   **** Ranges / Filters ****
 
@@ -299,6 +306,7 @@ parse_options() {
       --fail-low-coverage) SHELLSPEC_FAIL_LOW_COVERAGE=1 ;;
       --no-fail-low-coverage) SHELLSPEC_FAIL_LOW_COVERAGE='' ;;
       --kcov) SHELLSPEC_KCOV=1 ;;
+      --no-kcov) SHELLSPEC_KCOV='' ;;
       --kcov-path) [ "${2:-}" ] || abort 'Require PATH.'
         SHELLSPEC_KCOV_PATH="$2"
         shift ;;
@@ -308,7 +316,11 @@ parse_options() {
       --kcov-options) [ "${2:-}" ] || abort 'Require OPTIONS.'
         SHELLSPEC_KCOV_OPTS="${SHELLSPEC_KCOV_OPTS}${SHELLSPEC_KCOV_OPTS:+ }$2"
         shift ;;
-      --no-kcov) SHELLSPEC_KCOV='' ;;
+      -p | --profile) SHELLSPEC_PROFILER=1 ;;
+      --no-profile) SHELLSPEC_PROFILER='' ;;
+      --profiler-limit) [ "${2:-}" ] || abort 'Require N.'
+        SHELLSPEC_PROFILER_LIMIT="$2"
+        shift ;;
       --init | --task | --translate | --syntax-check) SHELLSPEC_MODE=${1#--} ;;
       --count) SHELLSPEC_MODE=list SHELLSPEC_LIST='' ;;
       --list) [ "${2:-}" ] || abort 'Require LIST.'