1*c29d5175SchristosThe following is an example of the shortlived.d program. 2*c29d5175SchristosIt can measure time spent processing short lived processes, 3*c29d5175Schristosthat may be responsible for heavy load on the system but 4*c29d5175Schristosare usually difficult to see with sampling tools like prstat. 5*c29d5175Schristos 6*c29d5175Schristos 7*c29d5175Schristos 8*c29d5175SchristosHere we run in for a few seconds on a server, 9*c29d5175Schristos 10*c29d5175Schristos # shortlived.d 11*c29d5175Schristos Tracing... Hit Ctrl-C to stop. 12*c29d5175Schristos ^C 13*c29d5175Schristos short lived processes: 0.456 secs 14*c29d5175Schristos total sample duration: 9.352 secs 15*c29d5175Schristos 16*c29d5175Schristos Total time by process name, 17*c29d5175Schristos date 12 ms 18*c29d5175Schristos df 20 ms 19*c29d5175Schristos ls 40 ms 20*c29d5175Schristos perl 380 ms 21*c29d5175Schristos 22*c29d5175Schristos Total time by PPID, 23*c29d5175Schristos 3279 452 ms 24*c29d5175Schristos 25*c29d5175SchristosIn the above output, around 5% of the CPU was lost to short 26*c29d5175Schristoslived processes - mostly perl. This may be many perl processes, 27*c29d5175Schristoshere we are aggregating on the process name not the instance. 28*c29d5175Schristos 29*c29d5175Schristos 30*c29d5175Schristos 31*c29d5175SchristosNow shortlived.d is run on a server with a performance problem, 32*c29d5175Schristos 33*c29d5175Schristos # uptime 34*c29d5175Schristos 10:58pm up 5 day(s), 1:28, 1 user, load average: 2.20, 1.81, 1.04 35*c29d5175Schristos # 36*c29d5175Schristos # shortlived.d 37*c29d5175Schristos Tracing... Hit Ctrl-C to stop. 38*c29d5175Schristos ^C 39*c29d5175Schristos short lived processes: 4.546 secs 40*c29d5175Schristos total sample duration: 9.858 secs 41*c29d5175Schristos 42*c29d5175Schristos Total time by process name, 43*c29d5175Schristos expr 4122 ms 44*c29d5175Schristos 45*c29d5175Schristos Total time by PPID, 46*c29d5175Schristos 3279 4122 ms 47*c29d5175Schristos # 48*c29d5175Schristos # ps -p 3279 49*c29d5175Schristos PID TTY TIME CMD 50*c29d5175Schristos 3279 pts/10 0:45 report.sh 51*c29d5175Schristos 52*c29d5175Schristosshortlived.d showed that 50% of the CPU was consumed by short lived 53*c29d5175Schristosprocesses, all of them the "expr" command, and all having the 54*c29d5175Schristosparent proccess-ID 3279. We finished by checking PID 3279 to find 55*c29d5175Schristosit is a Bourne shell script called "report.sh". 56*c29d5175Schristos 57*c29d5175Schristos 58