Profiler redesign

.travis.yml

@@ -55,7 +55,7 @@ before_script:
         make -j4 install
         cd ..
       fi
-  - ./shellspec --task fixture:stat:prepare
+  - ./shellspec --shell sh --task fixture:stat:prepare
 script:
   - contrib/all.sh contrib/various_test.sh
   - if [ "$COVERAGE" ]; then ./shellspec --kcov --kcov-options "--coveralls-id=${TRAVIS_JOB_ID}"; fi

contrib/various_test.sh

@@ -4,13 +4,19 @@ set -eu
 
 : "${SH:=sh}"
 
-$SH shellspec --banner
-$SH shellspec --no-banner --skip-message quiet -j 3
-$SH shellspec --no-banner --skip-message quiet $($SH shellspec --list specfiles | head -n 5)
-$SH shellspec --no-banner --skip-message quiet $($SH shellspec --list examples:lineno | head -n 5)
-$SH shellspec --no-banner --skip-message quiet spec/general_spec.sh:40:60:80:100
-$SH shellspec --no-banner --skip-message quiet --profile
-$SH shellspec --syntax-check
-$SH shellspec --count
-$SH shellspec --task
-$SH shellspec --task hello:shellspec
+shellspec() {
+  set -- $SH shellspec --shell "$SH" "$@"
+  echo "\$ $@" >&2
+  "$@"
+}
+
+shellspec --banner
+shellspec --no-banner --skip-message quiet -j 3
+shellspec --no-banner --skip-message quiet $(shellspec --list specfiles | head -n 5)
+shellspec --no-banner --skip-message quiet $(shellspec --list examples:lineno | head -n 5)
+shellspec --no-banner --skip-message quiet spec/general_spec.sh:40:60:80:100
+shellspec --no-banner --skip-message quiet --profile
+shellspec --syntax-check
+shellspec --count
+shellspec --task
+shellspec --task hello:shellspec

lib/bootstrap.sh

@@ -57,3 +57,15 @@ shellspec_call_configure() {
   done
 }
 shellspec_call_configure "$SHELLSPEC_REQUIRES"
+
+if [ "$SHELLSPEC_PROFILER" ]; then
+  shellspec_profile_start() { shellspec_profile_wait; }
+  shellspec_profile_end() { shellspec_profile_wait; }
+  shellspec_profile_wait() {
+    echo = > "$SHELLSPEC_PROFILER_SIGNAL"
+    while [ -s "$SHELLSPEC_PROFILER_SIGNAL" ]; do :; done
+  }
+else
+  shellspec_profile_start() { :; }
+  shellspec_profile_end() { :; }
+fi

lib/core/dsl.sh

@@ -238,15 +238,3 @@ shellspec_abort() {
   [ "${3:-}" ] && shellspec_putsn "${3:-}" >&2
   exit "${1:-1}"
 }
-
-if [ "$SHELLSPEC_PROFILER" ]; then
-  shellspec_profile_start() {
-    shellspec_signal -USR1 "$SHELLSPEC_PROFILER_PID"
-  }
-  shellspec_profile_end() {
-    shellspec_signal -USR1 "$SHELLSPEC_PROFILER_PID"
-  }
-else
-  shellspec_profile_start() { :; }
-  shellspec_profile_end() { :; }
-fi

lib/general.sh

@@ -240,6 +240,13 @@ shellspec_sequence_() {
   shellspec_sequence_ "$1" $(($2 + $4)) "$3" "$4" "$5"
 }
 
+shellspec_loop() {
+  if [ "$2" -gt 0 ]; then
+    "$1"
+    shellspec_loop "$1" $(($2 - 1))
+  fi
+}
+
 shellspec_escape_quote() {
   SHELLSPEC_EVAL="
     shellspec_reset_params '\$$1' \"'\"; \
@@ -411,13 +418,3 @@ shellspec_chomp() {
   "
   eval "$SHELLSPEC_EVAL"
 }
-
-if $SHELLSPEC_KILL -0 $$ 2>/dev/null; then
-  shellspec_signal() {
-    "$SHELLSPEC_KILL" "$1" "$2"
-  }
-else
-  shellspec_signal() {
-    "$SHELLSPEC_KILL" -s "${1#-}" "$2"
-  }
-fi

lib/libexec.sh

@@ -1,4 +1,4 @@
-#shellcheck shell=sh
+#shellcheck shell=sh disable=SC2004
 
 [ "${ZSH_VERSION:-}" ] && setopt shwordsplit
 
@@ -96,4 +96,30 @@ abort() {
   exit 1
 }
 
+sleep_wait() {
+  case $1 in
+    *[!0-9]*) while "$@"; do sleep 0; done; return 0 ;;
+  esac
+
+  sleep_wait_eval="
+    shift; \
+    while \"\$@\"; do \
+      [ \"\$(( \$(date +%s) - $(date +%s) ))\" -ge $1 ] && return 1; \
+      sleep 0; \
+    done
+  "
+  eval "$sleep_wait_eval"
+}
+
+
+if $SHELLSPEC_KILL -0 $$ 2>/dev/null; then
+  signal() {
+    "$SHELLSPEC_KILL" "$1" "$2"
+  }
+else
+  signal() {
+    "$SHELLSPEC_KILL" -s "${1#-}" "$2"
+  }
+fi
+
 use puts putsn

lib/libexec/reporter.sh

@@ -98,16 +98,14 @@ inc() {
 
 read_profiler() {
   tick_total=0 time_real_nano=0
-  while IFS=" " read -r tick; do
-    tick_total=$(($tick_total + $tick))
-  done < "$2"
+  read -r tick_total < "$2.total"
 
-  shellspec_shift10 time_real_nano "$3" 6
+  shellspec_shift10 time_real_nano "$3" 4
 
   i=0
   while IFS=" " read -r tick; do
     duration=$(($time_real_nano * $tick / $tick_total))
-    shellspec_shift10 duration "$duration" -6
+    shellspec_shift10 duration "$duration" -4
     $1 "$i" "$tick" "$duration"
     i=$(($i + 1))
   done < "$2"

lib/libexec/reporter/profiler_formatter.sh

@@ -1,11 +1,22 @@
 #shellcheck shell=sh disable=SC2004
 
-: "${profiler_count:-}"
+: "${profiler_count:-} ${example_count:-}"
 
 profiler_output() {
-  [ "$profiler_count" -eq 0 ] && return 0
+  [ "$SHELLSPEC_PROFILER" ] || return 0
   case $1 in (end)
-    _i=0
+    _i=0 _slowest=$SHELLSPEC_PROFILER_LIMIT
+    [ "$profiler_count" -le "$_slowest" ] && _slowest=$profiler_count
+    puts "${BOLD}${BLACK}"
+    putsn "Top $_slowest slowest examples of the $profiler_count examples"
+
+    if [ "$example_count" -gt 0 ] && [ "$profiler_count" -eq 0 ]; then
+      putsn "(Warning, An error has occurred in the profiler)"
+    elif [ "$example_count" -ne "$profiler_count" ]; then
+      putsn "(Warning, A drop or an error has occurred in the profiler)"
+    fi
+    puts "${RESET}"
+
     while [ $_i -lt "$profiler_count" ]; do
       eval "putsn \$profiler_tick$_i \$profiler_time$_i \"\$profiler_line$_i\""
       _i=$(($_i + 1))
@@ -15,7 +26,10 @@ profiler_output() {
       while IFS=" " read -r _tick _duration _line; do
         [ "$_i" -ge "$SHELLSPEC_PROFILER_LIMIT" ] && break
         _i=$(($_i + 1))
-        putsn "${BOLD}${BLACK}$_i $_duration $_line${RESET}"
+        while [ "${#_i}" -lt "${#SHELLSPEC_PROFILER_LIMIT}" ]; do
+          _i=" $_i"
+        done
+        putsn "${BOLD}${BLACK} $_i $_duration $_line${RESET}"
       done
     }
     putsn

lib/libexec/runner.sh

@@ -2,7 +2,6 @@
 
 # shellcheck source=lib/libexec.sh
 . "${SHELLSPEC_LIB:-./lib}/libexec.sh"
-use signal
 
 mktempdir() {
   (umask 0077; mkdir "$1"; chmod 0700 "$1")
@@ -23,15 +22,3 @@ read_pid_file() {
     eval "read -r $1 < \"$2\""
   fi
 }
-
-sleep_wait() {
-  case $1 in
-    *[!0-9]*) timeout=999999999 ;;
-    *) timeout=$1; shift
-  esac
-  while "$@"; do
-    [ "$timeout" -gt 0 ] || return 1
-    sleep 0
-    timeout=$(($timeout - 1))
-  done
-}

libexec/shellspec-profiler.sh

@@ -3,35 +3,26 @@
 
 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
-  rm "$SHELLSPEC_TMPBASE/profiler.pid"
-  exit
-}
-
 : > "$SHELLSPEC_PROFILER_LOG"
 
-pid=''
-if ( trap - USR1 && trap - TERM ) 2>/dev/null; then
-  trap handler USR1
-  trap terminate TERM
-  pid=$$
-fi
-echo "$pid" > "$SHELLSPEC_TMPBASE/profiler.pid"
-[ "$pid" ] || exit 1
-
 index=0 counter=0
-while :; do
+
+: > "$SHELLSPEC_PROFILER_SIGNAL"
+
+while [ -e "$SHELLSPEC_PROFILER_SIGNAL" ]; do
+  if [ -s "$SHELLSPEC_PROFILER_SIGNAL" ]; then
+    eval "counter${index}=$counter index=$(($index + 1))"
+    : > "$SHELLSPEC_PROFILER_SIGNAL"
+  fi
   counter=$(($counter + 1))
 done
+
+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
+echo "$counter" > "$SHELLSPEC_PROFILER_LOG.total"
+: > "$SHELLSPEC_TMPBASE/profiler.done"

libexec/shellspec-reporter.sh

@@ -148,9 +148,7 @@ read_time_log "time" "$SHELLSPEC_TIME_LOG"
 
 if [ "$SHELLSPEC_PROFILER" ] && [ "$SHELLSPEC_PROFILER_LOG" ]; then
   mkdir -p "$SHELLSPEC_REPORTDIR"
-  while shellspec_signal -0 "$SHELLSPEC_PROFILER_PID" 2>/dev/null; do
-    sleep 0
-  done
+  sleep_wait [ ! -e "$SHELLSPEC_TMPBASE/profiler.done" ] ||:
   callback() {
     eval "profiler_tick$1=\$2 profiler_time$1=\$3" \
       "profiler_line=\$profiler_line$1 profiler_count=$(($1 + 1))"

libexec/shellspec-runner.sh

@@ -3,31 +3,26 @@
 
 set -eu
 
-export SHELLSPEC_PROFILER_PID=''
+export SHELLSPEC_PROFILER_SIGNAL="$SHELLSPEC_TMPBASE/profiler.signal"
 
 # shellcheck source=lib/libexec/runner.sh
 . "${SHELLSPEC_LIB:-./lib}/libexec/runner.sh"
 
 start_profiler() {
   [ "$SHELLSPEC_PROFILER" ] || return 0
   $SHELLSPEC_SHELL "$SHELLSPEC_LIBEXEC/shellspec-profiler.sh" &
-  read_pid_file SHELLSPEC_PROFILER_PID "$SHELLSPEC_TMPBASE/profiler.pid" 1000
-  [ "$SHELLSPEC_PROFILER_PID" ] && return 0
-  warn "Failed to activate profiler (trap not supported?)"
-  SHELLSPEC_PROFILER=''
-}
+} 2>/dev/null
 
 stop_profiler() {
-  [ "$SHELLSPEC_PROFILER_PID" ] || return 0
-  signal -TERM "$SHELLSPEC_PROFILER_PID" 2>/dev/null ||:
-  sleep_wait 1000 [ -e "$SHELLSPEC_TMPBASE/profiler.pid" ] ||:
-  SHELLSPEC_PROFILER_PID=''
+  [ "$SHELLSPEC_PROFILER" ] || return 0
+  if [ -e "$SHELLSPEC_PROFILER_SIGNAL" ]; then
+    rm "$SHELLSPEC_PROFILER_SIGNAL"
+  fi
 }
 
 cleanup() {
   if (trap - INT) 2>/dev/null; then trap '' INT; fi
   [ "$SHELLSPEC_TMPBASE" ] || return 0
-  stop_profiler
   tmpbase="$SHELLSPEC_TMPBASE" && SHELLSPEC_TMPBASE=''
   [ -f "$SHELLSPEC_KCOV_IN_FILE" ] && rm "$SHELLSPEC_KCOV_IN_FILE"
   [ "$SHELLSPEC_KEEP_TEMPDIR" ] || rmtempdir "$tmpbase"
@@ -45,6 +40,7 @@ interrupt() {
 }
 
 executor() {
+  start_profiler
   executor="$SHELLSPEC_LIBEXEC/shellspec-executor.sh"
   # shellcheck disable=SC2086
   $SHELLSPEC_TIME $SHELLSPEC_SHELL "$executor" "$@" 3>&2 2>"$SHELLSPEC_TIME_LOG"
@@ -95,8 +91,6 @@ 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
@@ -122,6 +116,11 @@ start_profiler
 ) 3>&1 4>&2 &&:
 exit_status=$?
 
+if [ -e "$SHELLSPEC_TMPBASE/profiler.timeout" ]; then
+  warn "Forced terminate the profiler due to a timed out" \
+    "(Occasionally occurs with zsh)."
+fi
+
 case $exit_status in
   0) ;; # Running specs exit with successfully.
   $SHELLSPEC_SPEC_FAILURE_CODE) ;; # Running specs exit with failure.

shellspec

@@ -62,6 +62,7 @@ export SHELLSPEC_PROFILER_REPORT="profiler.log"
 export SHELLSPEC_DEFECT_READONLY=''
 export SHELLSPEC_DEFECT_REDEFINE=''
 export SHELLSPEC_KILL='kill'
+export SHELLSPEC_SLEEP='sleep'
 
 #shellcheck disable=SC2039
 export SHELLSPEC_HOSTNAME=${HOSTNAME:-localhost}
@@ -328,7 +329,7 @@ parse_options() {
         shift ;;
       -p | --profile) SHELLSPEC_PROFILER=1 ;;
       --no-profile) SHELLSPEC_PROFILER='' ;;
-      --profiler-limit) [ "${2:-}" ] || abort 'Require N.'
+      --profile-limit) [ "${2:-}" ] || abort 'Require N.'
         SHELLSPEC_PROFILER_LIMIT="$2"
         shift ;;
       --init | --task | --translate | --syntax-check) SHELLSPEC_MODE=${1#--} ;;
@@ -368,7 +369,6 @@ if [ -z "$SHELLSPEC_SHELL" ]; then
 fi
 
 #shellcheck disable=SC2123
-
 # posh 0.8.5 implements kill but not support any signals. meaningless.
 if [ ! "$(PATH=; kill -l 2>/dev/null)"  ]; then
   SHELLSPEC_KILL=$(command_path kill) ||:
@@ -411,8 +411,12 @@ if [ "$SHELLSPEC_KCOV" ]; then
   fi
 fi
 
-if [ "$SHELLSPEC_PROFILER" ] && [ "$SHELLSPEC_JOBS" -gt 0 ]; then
-  abort "Can not be specified profiler and paralell execution at the same time"
+if [ "$SHELLSPEC_PROFILER" ]; then
+  if [ "$SHELLSPEC_JOBS" -gt 0 ]; then
+    abort "Can not be specified profiler" \
+      "and paralell execution at the same time"
+  fi
+  SHELLSPEC_SLEEP=$(command_path sleep)
 fi
 
 case $SHELLSPEC_MODE in (init | task) ;; (*)