Demonstrations of cpudist. This program summarizes task on-CPU time as a histogram, showing how long tasks spent on the CPU before being descheduled. This provides valuable information that can indicate oversubscription (too many tasks for too few processors), overhead due to excessive context switching (e.g. a common shared lock for multiple threads), uneven workload distribution, too-granular tasks, and more. Alternatively, the same options are available for summarizing task off-CPU time, which helps understand how often threads are being descheduled and how long they spend waiting for I/O, locks, timers, and other causes of suspension. # ./cpudist.py Tracing on-CPU time... Hit Ctrl-C to end. ^C usecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 1 | | 4 -> 7 : 1 | | 8 -> 15 : 13 |** | 16 -> 31 : 187 |****************************************| 32 -> 63 : 89 |******************* | 64 -> 127 : 26 |***** | 128 -> 255 : 0 | | 256 -> 511 : 1 | | This is from a mostly idle system. Tasks wake up occasionally and run for only a few dozen microseconds, and then get descheduled. Here's some output from a system that is heavily loaded by threads that perform computation but also compete for a lock: # ./cpudist.py Tracing on-CPU time... Hit Ctrl-C to end. ^C usecs : count distribution 0 -> 1 : 51 |* | 2 -> 3 : 395 |*********** | 4 -> 7 : 259 |******* | 8 -> 15 : 61 |* | 16 -> 31 : 75 |** | 32 -> 63 : 31 | | 64 -> 127 : 7 | | 128 -> 255 : 5 | | 256 -> 511 : 3 | | 512 -> 1023 : 5 | | 1024 -> 2047 : 6 | | 2048 -> 4095 : 4 | | 4096 -> 8191 : 1361 |****************************************| 8192 -> 16383 : 523 |*************** | 16384 -> 32767 : 3 | | A bimodal distribution is now clearly visible. Most of the time, tasks were able to run for 4-16ms before being descheduled (this is likely the quantum length). Occasionally, tasks had to be descheduled a lot earlier -- possibly because they competed for a shared lock. If necessary, you can restrict the output to include only threads from a particular process -- this helps reduce noise: # ./cpudist.py -p $(pidof parprimes) Tracing on-CPU time... Hit Ctrl-C to end. ^C usecs : count distribution 0 -> 1 : 3 | | 2 -> 3 : 17 | | 4 -> 7 : 39 | | 8 -> 15 : 52 |* | 16 -> 31 : 43 | | 32 -> 63 : 12 | | 64 -> 127 : 13 | | 128 -> 255 : 0 | | 256 -> 511 : 1 | | 512 -> 1023 : 11 | | 1024 -> 2047 : 15 | | 2048 -> 4095 : 41 | | 4096 -> 8191 : 1134 |************************ | 8192 -> 16383 : 1883 |****************************************| 16384 -> 32767 : 65 |* | You can also ask for output at predefined intervals, and include timestamps for easier interpretation. While we're at it, the -P switch will print a histogram separately for each process: # ./cpudist.py -TP 5 3 Tracing on-CPU time... Hit Ctrl-C to end. 03:46:51 pid = 0 usecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 1 |** | 4 -> 7 : 17 |********************************** | 8 -> 15 : 11 |********************** | 16 -> 31 : 20 |****************************************| 32 -> 63 : 15 |****************************** | 64 -> 127 : 9 |****************** | 128 -> 255 : 6 |************ | 256 -> 511 : 0 | | 512 -> 1023 : 0 | | 1024 -> 2047 : 0 | | 2048 -> 4095 : 1 |** | pid = 5068 usecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 1 |************* | 4 -> 7 : 3 |****************************************| 8 -> 15 : 0 | | 16 -> 31 : 0 | | 32 -> 63 : 1 |************* | 03:46:56 pid = 0 usecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 1 |** | 4 -> 7 : 19 |****************************************| 8 -> 15 : 11 |*********************** | 16 -> 31 : 9 |****************** | 32 -> 63 : 3 |****** | 64 -> 127 : 1 |** | 128 -> 255 : 3 |****** | 256 -> 511 : 0 | | 512 -> 1023 : 1 |** | pid = 5068 usecs : count distribution 0 -> 1 : 1 |******************** | 2 -> 3 : 0 | | 4 -> 7 : 2 |****************************************| 03:47:01 pid = 0 usecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | 4 -> 7 : 12 |******************************** | 8 -> 15 : 15 |****************************************| 16 -> 31 : 15 |****************************************| 32 -> 63 : 0 | | 64 -> 127 : 3 |******** | 128 -> 255 : 1 |** | 256 -> 511 : 0 | | 512 -> 1023 : 1 |** | pid = 5068 usecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 1 |****** | 4 -> 7 : 6 |****************************************| 8 -> 15 : 0 | | 16 -> 31 : 0 | | 32 -> 63 : 2 |************* | This histogram was obtained while executing `dd if=/dev/zero of=/dev/null` with fairly large block sizes. You could also ask for an off-CPU report using the -O switch. Here's a histogram of task block times while the system is heavily loaded: # ./cpudist -O -p $(parprimes) Tracing off-CPU time... Hit Ctrl-C to end. ^C usecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 1 | | 4 -> 7 : 0 | | 8 -> 15 : 0 | | 16 -> 31 : 0 | | 32 -> 63 : 3 | | 64 -> 127 : 1 | | 128 -> 255 : 1 | | 256 -> 511 : 0 | | 512 -> 1023 : 2 | | 1024 -> 2047 : 4 | | 2048 -> 4095 : 3 | | 4096 -> 8191 : 70 |*** | 8192 -> 16383 : 867 |****************************************| 16384 -> 32767 : 141 |****** | 32768 -> 65535 : 8 | | 65536 -> 131071 : 0 | | 131072 -> 262143 : 1 | | 262144 -> 524287 : 2 | | 524288 -> 1048575 : 3 | | As you can see, threads are switching out for relatively long intervals, even though we know the workload doesn't have any significant blocking. This can be a result of over-subscription -- too many threads contending over too few CPUs. Indeed, there are four available CPUs and more than four runnable threads: # nproc 4 # cat /proc/loadavg 0.04 0.11 0.06 9/147 7494 (This shows we have 9 threads runnable out of 147 total. This is more than 4, the number of available CPUs.) Finally, let's ask for a per-thread report and values in milliseconds instead of microseconds: # ./cpudist.py -p $(pidof parprimes) -mL Tracing on-CPU time... Hit Ctrl-C to end. tid = 5092 msecs : count distribution 0 -> 1 : 3 | | 2 -> 3 : 4 | | 4 -> 7 : 4 | | 8 -> 15 : 535 |****************************************| 16 -> 31 : 14 |* | tid = 5093 msecs : count distribution 0 -> 1 : 8 | | 2 -> 3 : 6 | | 4 -> 7 : 4 | | 8 -> 15 : 534 |****************************************| 16 -> 31 : 12 | | tid = 5094 msecs : count distribution 0 -> 1 : 38 |*** | 2 -> 3 : 5 | | 4 -> 7 : 5 | | 8 -> 15 : 476 |****************************************| 16 -> 31 : 25 |** | tid = 5095 msecs : count distribution 0 -> 1 : 31 |** | 2 -> 3 : 6 | | 4 -> 7 : 10 | | 8 -> 15 : 478 |****************************************| 16 -> 31 : 20 |* | tid = 5096 msecs : count distribution 0 -> 1 : 21 |* | 2 -> 3 : 5 | | 4 -> 7 : 4 | | 8 -> 15 : 523 |****************************************| 16 -> 31 : 16 |* | tid = 5097 msecs : count distribution 0 -> 1 : 11 | | 2 -> 3 : 7 | | 4 -> 7 : 7 | | 8 -> 15 : 502 |****************************************| 16 -> 31 : 23 |* | tid = 5098 msecs : count distribution 0 -> 1 : 21 |* | 2 -> 3 : 5 | | 4 -> 7 : 3 | | 8 -> 15 : 494 |****************************************| 16 -> 31 : 28 |** | tid = 5099 msecs : count distribution 0 -> 1 : 15 |* | 2 -> 3 : 4 | | 4 -> 7 : 6 | | 8 -> 15 : 521 |****************************************| 16 -> 31 : 12 | | It looks like all threads are more-or-less equally busy, and are typically switched out after running for 8-15 milliseconds (again, this is the typical quantum length). USAGE message: # ./cpudist.py -h usage: cpudist.py [-h] [-O] [-T] [-m] [-P] [-L] [-p PID] [interval] [count] Summarize on-CPU time per task as a histogram. positional arguments: interval output interval, in seconds count number of outputs optional arguments: -h, --help show this help message and exit -O, --offcpu measure off-CPU time -T, --timestamp include timestamp on output -m, --milliseconds millisecond histogram -P, --pids print a histogram per process ID -L, --tids print a histogram per thread ID -p PID, --pid PID trace this PID only examples: cpudist # summarize on-CPU time as a histogram cpudist -O # summarize off-CPU time as a histogram cpudist 1 10 # print 1 second summaries, 10 times cpudist -mT 1 # 1s summaries, milliseconds, and timestamps cpudist -P # show each PID separately cpudist -p 185 # trace PID 185 only