← source index

sched-diag.sh

149 lines  ·  5.4 K  ·  bash
#!/usr/bin/env bash
# sched-diag.sh -- scheduling and syscall diagnostics for a long-running process.
#
#   ./sched-diag.sh                 # auto-detect via MATCH below
#   ./sched-diag.sh -p 1583494      # explicit pid
#   ./sched-diag.sh -m bin/app -d 20
#   ./sched-diag.sh -w              # live watch of ctxt switch counters, then exit
#
# Everything except the perf/strace sections works unprivileged.

set -uo pipefail

MATCH="bin/app"          # substring matched against the full command line
DURATION=10              # seconds per sampling window
WATCH_ONLY=0
PID=""

while getopts "p:m:d:wh" o; do
  case "$o" in
    p) PID="$OPTARG" ;;
    m) MATCH="$OPTARG" ;;
    d) DURATION="$OPTARG" ;;
    w) WATCH_ONLY=1 ;;
    h) sed -n '2,12p' "$0"; exit 0 ;;
    *) exit 2 ;;
  esac
done

hr() { printf '\n\033[1m== %s\033[0m\n' "$*"; }
have() { command -v "$1" >/dev/null 2>&1; }

# ---------------------------------------------------------------- find the pid
if [[ -z "$PID" ]]; then
  mapfile -t hits < <(pgrep -f -- "$MATCH")
  case "${#hits[@]}" in
    0) echo "no process matching '$MATCH' -- is it running?" >&2; exit 1 ;;
    1) PID="${hits[0]}" ;;
    *) echo "'$MATCH' matched ${#hits[@]} processes:" >&2
       for p in "${hits[@]}"; do
         printf '  %-8s %s\n' "$p" "$(tr '\0' ' ' < /proc/$p/cmdline)" >&2
       done
       echo "re-run with -p PID" >&2; exit 1 ;;
  esac
fi
[[ -d /proc/$PID ]] || { echo "pid $PID is not alive" >&2; exit 1; }

CMD=$(tr '\0' ' ' < /proc/$PID/cmdline)
NTHREADS=$(awk '/^Threads:/{print $2}' /proc/$PID/status)
echo "pid=$PID  threads=$NTHREADS"
echo "cmd=$CMD"

# ------------------------------------------------- optional: live counter watch
if (( WATCH_ONLY )); then
  exec watch -n1 -d "grep -E 'ctxt_switches|Threads' /proc/$PID/status"
fi

# ------------------------------------------------ per-thread switch rate deltas
# voluntary   = the thread called something that blocked (read, futex, poll...)
# nonvoluntary = the scheduler took the CPU away while it was still runnable
snapshot() {
  local t
  for t in /proc/$PID/task/*; do
    [[ -r "$t/status" ]] || continue
    printf '%s %s %s %s\n' \
      "${t##*/}" \
      "$(tr -d ' ' < "$t/comm")" \
      "$(awk '/^voluntary_ctxt_switches/{print $2}'    "$t/status")" \
      "$(awk '/^nonvoluntary_ctxt_switches/{print $2}' "$t/status")"
  done
}

hr "per-thread context switches over ${DURATION}s"
before=$(snapshot)
sleep "$DURATION"
after=$(snapshot)

awk -v dur="$DURATION" '
  NR==FNR { bv[$1]=$3; bn[$1]=$4; next }          # first pass: the "before" snapshot
  ($1 in bv) {
    rows[++k] = sprintf("%-8s %-18s %10.1f %10.1f %12s",
                        $1, $2, ($3-bv[$1])/dur, ($4-bn[$1])/dur, $3)
    key[k]  = ($3-bv[$1])/dur
  }
  END {
    printf "%-8s %-18s %10s %10s %12s\n", "TID", "COMM", "VOL/s", "NONVOL/s", "VOL_TOT"
    for (i=1; i<=k; i++)                           # insertion sort, descending by VOL/s
      for (j=i+1; j<=k; j++)
        if (key[j] > key[i]) {
          t=key[i]; key[i]=key[j]; key[j]=t
          s=rows[i]; rows[i]=rows[j]; rows[j]=s
        }
    for (i=1; i<=k; i++) print rows[i]
  }
' <(printf '%s\n' "$before") <(printf '%s\n' "$after")

cat <<'EOF'

  Reading it: high VOL/s means the thread blocks a lot -- each wakeup costs
  ~3-25us, so multiply to get the tax. High NONVOL/s means the scheduler is
  evicting you; that is a core-contention problem, not a code problem.
EOF

# ---------------------------------------------------------- coarse perf counters
if have perf; then
  hr "perf counters (${DURATION}s)"
  perf stat -e context-switches,cpu-migrations,page-faults,minor-faults,major-faults \
       -p "$PID" -- sleep "$DURATION" 2>&1 | sed '/^$/d'
  echo "  page-faults should be ~0 in steady state; anything else means allocation."
fi

# ----------------------------------------------------------- who preempted you?
if have perf && [[ $EUID -eq 0 || -n "${SUDO_OK:-}" ]]; then
  hr "scheduler delay by task (5s, system-wide)"
  tmp=$(mktemp -d); trap 'rm -rf "$tmp"' EXIT
  ( cd "$tmp" && perf sched record -- sleep 5 >/dev/null 2>&1 \
      && perf sched latency --sort max 2>/dev/null | head -25 )
  echo "  'Max delay' = runnable-to-running latency. Find your threads in the list."
else
  hr "scheduler delay"
  echo "  needs root: sudo $0 -p $PID"
fi

# --------------------------------------------------------------- syscall profile
hr "syscall profile (${DURATION}s)"
if have strace; then
  sudo -n true 2>/dev/null && SUDO=sudo || SUDO=
  $SUDO timeout "$DURATION" strace -c -f -p "$PID" 2>&1 | tail -30
  echo
  echo "  full trace with timings:"
  $SUDO timeout 5 strace -T -tt -f -p "$PID" -o /tmp/strace.$PID.txt 2>/dev/null
  [[ -s /tmp/strace.$PID.txt ]] && head -20 /tmp/strace.$PID.txt \
    && echo "  ... full trace in /tmp/strace.$PID.txt"
elif have perf; then
  echo "  strace not installed -- using perf trace (much lower overhead anyway)"
  sudo -n perf trace -p "$PID" -- sleep 5 2>&1 | tail -30
else
  echo "  install strace:  sudo dnf install strace   (or apt install strace)"
fi

cat <<EOF

--------------------------------------------------------------------
Follow-ups worth running once:
  cyclictest -m -p 95 -d 0 -l 100000     # the machine's own jitter floor
  grep nr_throttled /sys/fs/cgroup/cpu.stat    # container quota stalls
  taskset -cp \$PID                       # what cores is it allowed on
--------------------------------------------------------------------
EOF