1# -*- tab-width: 4 -*- ;; Emacs 2# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM 3############################################################ IDENT(1) 4# 5# $Title: dwatch(8) module for long sleeps and hung threads $ 6# $Copyright: 2026 Devin Teske. All rights reserved. $ 7# 8############################################################ DESCRIPTION 9# 10# Print threads that were asleep for a long time, as they wake, naming 11# the sleeper, how long it slept, and (in the standard event tag) the 12# process that woke it. Sleeps shorter than a threshold are suppressed 13# (default 1000 ms; tunable via DWATCH_HANG_MS in the environment, 0 to 14# show everything). Answers "what was my process stuck on?" -- the 15# blocking that the slow profile cannot see, because a syscall that 16# never returns never reports its latency. NB: the report fires at 17# wakeup with the full duration; a thread still asleep has not yet 18# been reported. 19# The hang-top profile maintains a running catalog, updated every 20# 3 seconds, of long sleeps by process. Combine with `-O cmd' to 21# capture state as each event occurs. 22# 23############################################################ PRAGMAS 24 25case "$PROFILE" in 26hang-top) 27 DTRACE_PRAGMA=" 28 option quiet 29 option aggsortrev 30 " # END-QUOTE 31 ;; 32esac 33 34############################################################ PROBE 35 36case "$PROFILE" in 37hang-top) 38 : ${PROBE:=profile:::tick-3s} ;; 39*) 40 : ${PROBE:=sched:::wakeup} 41esac 42 43############################################################ EVENT ACTION 44 45: ${DWATCH_HANG_MS:=1000} 46 47case "$DWATCH_HANG_MS" in 48""|*[!0-9]*) die "DWATCH_HANG_MS must be a number" ;; # NOTREACHED 49esac 50 51[ "$CUSTOM_TEST" ] || case "$PROFILE" in 52hang-top) ;; 53*) EVENT_TEST="this->hang_ns >= (int64_t)$DWATCH_HANG_MS * 1000000" 54esac 55 56############################################################ ACTIONS 57 58if [ "$PROFILE" = "hang-top" ]; then 59exec 9<<EOF 60this int64_t hang_ns; 61int64_t hang_ts[int]; 62 63BEGIN { printf("Cataloging long sleeps ...") } /* probe ID $ID */ 64 65sched:::sleep /* probe ID $(( $ID + 1 )) */ 66{ 67 hang_ts[curthread->td_tid] = timestamp; 68} 69 70sched:::wakeup /* probe ID $(( $ID + 2 )) */ 71{ 72 /* NB: -1 if we did not see the sleep (enabled mid-sleep) */ 73 this->hang_ns = 74 hang_ts[((struct thread *)args[0])->td_tid] ? timestamp - 75 hang_ts[((struct thread *)args[0])->td_tid] : -1; 76 hang_ts[((struct thread *)args[0])->td_tid] = 0; 77} 78 79sched:::wakeup /this->hang_ns >= 80 (int64_t)$DWATCH_HANG_MS * 1000000/ /* probe ID $(( $ID + 3 )) */ 81{ 82 @hang_cnt[stringof(((struct proc *)args[1])->p_comm)] = count(); 83 @hang_max[stringof(((struct proc *)args[1])->p_comm)] = 84 max(this->hang_ns / 1000000); 85} 86EOF 87ACTIONS=$( cat <&9 ) 88ID=$(( $ID + 4 )) 89else 90exec 9<<EOF 91this int64_t hang_ns; 92int64_t hang_ts[int]; 93 94sched:::sleep /* probe ID $ID */ 95{${TRACE:+ 96 printf("<$ID>"); 97} 98 hang_ts[curthread->td_tid] = timestamp; 99} 100 101$PROBE /* probe ID $(( $ID + 1 )) */ 102{${TRACE:+ 103 printf("<$(( $ID + 1 ))>"); 104} 105 /* NB: -1 if we did not see the sleep (enabled mid-sleep) */ 106 this->hang_ns = 107 hang_ts[((struct thread *)args[0])->td_tid] ? timestamp - 108 hang_ts[((struct thread *)args[0])->td_tid] : -1; 109 hang_ts[((struct thread *)args[0])->td_tid] = 0; 110 111 $( pproc -P _hang "(struct proc *)args[1]" ) 112} 113EOF 114ACTIONS=$( cat <&9 ) 115ID=$(( $ID + 2 )) 116fi 117 118############################################################ EVENT TAG 119 120# For the running catalog, override the default `UID.GID CMD[PID]: ' tag 121# with ANSI cursor-homing and screen-clearing codes plus column headers. 122 123if [ "$PROFILE" = "hang-top" ]; then 124size=$( stty size 2> /dev/null ) 125rows="${size%% *}" 126cols="${size#* }" 127 128exec 9<<EOF 129 printf("\033[H"); /* Position the cursor at top-left */ 130 printf("\033[J"); /* Clear display from cursor to end */ 131 132 /* Header line containing probe (left) and date (right) */ 133 printf("%-*s%s%Y%s\n", 134 $(( ${cols:-80} - 20 )), "$PROBE", 135 console ? "\033[32m" : "", 136 walltimestamp, 137 console ? "\033[39m" : ""); 138 139 /* Column headers */ 140 printf("%s%8s %10s %s%s\n", 141 console ? "\033[1m" : "", 142 "COUNT", 143 "MAX(ms)", 144 "EXECNAME", 145 console ? "\033[22m" : ""); 146EOF 147EVENT_TAG=$( cat <&9 ) 148fi 149 150############################################################ EVENT DETAILS 151 152if [ "$PROFILE" = "hang-top" ]; then 153exec 9<<EOF 154 /* NB: Cumulative; not truncated between updates */ 155 printa("%@8u %@10d %s\n", @hang_cnt, @hang_max); 156EOF 157EVENT_DETAILS=$( cat <&9 ) 158elif [ ! "$CUSTOM_DETAILS" ]; then 159exec 9<<EOF 160 /* 161 * Print long sleep details (tag shows the waker) 162 */ 163 printf("pid %d slept %d.%03d ms -- %s", 164 this->pid_hang, 165 this->hang_ns / 1000000, 166 (this->hang_ns % 1000000) / 1000, 167 this->args_hang); 168EOF 169EVENT_DETAILS=$( cat <&9 ) 170fi 171 172################################################################################ 173# END 174################################################################################ 175