Demonstrations of runqlat, the Linux eBPF/bcc version.


This program summarizes scheduler run queue latency as a histogram, showing
how long tasks spent waiting their turn to run on-CPU.

Here is a heavily loaded system:

# ./runqlat 
Tracing run queue latency... Hit Ctrl-C to end.
^C
     usecs               : count     distribution
         0 -> 1          : 233      |***********                             |
         2 -> 3          : 742      |************************************    |
         4 -> 7          : 203      |**********                              |
         8 -> 15         : 173      |********                                |
        16 -> 31         : 24       |*                                       |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 30       |*                                       |
       128 -> 255        : 6        |                                        |
       256 -> 511        : 3        |                                        |
       512 -> 1023       : 5        |                                        |
      1024 -> 2047       : 27       |*                                       |
      2048 -> 4095       : 30       |*                                       |
      4096 -> 8191       : 20       |                                        |
      8192 -> 16383      : 29       |*                                       |
     16384 -> 32767      : 809      |****************************************|
     32768 -> 65535      : 64       |***                                     |

The distribution is bimodal, with one mode between 0 and 15 microseconds,
and another between 16 and 65 milliseconds. These modes are visible as the
spikes in the ASCII distribution (which is merely a visual representation
of the "count" column). As an example of reading one line: 809 events fell
into the 16384 to 32767 microsecond range (16 to 32 ms) while tracing.

I would expect the two modes to be due the workload: 16 hot CPU-bound threads,
and many other mostly idle threads doing occasional work. I suspect the mostly
idle threads will run with a higher priority when they wake up, and are
the reason for the low latency mode. The high latency mode will be the
CPU-bound threads. More analysis with this and other tools can confirm.


A -m option can be used to show milliseconds instead, as well as an interval
and a count. For example, showing three x five second summary in milliseconds:

# ./runqlat -m 5 3
Tracing run queue latency... Hit Ctrl-C to end.

     msecs               : count     distribution
         0 -> 1          : 3818     |****************************************|
         2 -> 3          : 39       |                                        |
         4 -> 7          : 39       |                                        |
         8 -> 15         : 62       |                                        |
        16 -> 31         : 2214     |***********************                 |
        32 -> 63         : 226      |**                                      |

     msecs               : count     distribution
         0 -> 1          : 3775     |****************************************|
         2 -> 3          : 52       |                                        |
         4 -> 7          : 37       |                                        |
         8 -> 15         : 65       |                                        |
        16 -> 31         : 2230     |***********************                 |
        32 -> 63         : 212      |**                                      |

     msecs               : count     distribution
         0 -> 1          : 3816     |****************************************|
         2 -> 3          : 49       |                                        |
         4 -> 7          : 40       |                                        |
         8 -> 15         : 53       |                                        |
        16 -> 31         : 2228     |***********************                 |
        32 -> 63         : 221      |**                                      |

This shows a similar distribution across the three summaries.


A -p option can be used to show one PID only, which is filtered in kernel for
efficiency. For example, PID 4505, and one second summaries:

# ./runqlat -mp 4505 1
Tracing run queue latency... Hit Ctrl-C to end.

     msecs               : count     distribution
         0 -> 1          : 1        |*                                       |
         2 -> 3          : 2        |***                                     |
         4 -> 7          : 1        |*                                       |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 25       |****************************************|
        32 -> 63         : 3        |****                                    |

     msecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 2        |**                                      |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |*                                       |
        16 -> 31         : 30       |****************************************|
        32 -> 63         : 1        |*                                       |

     msecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 28       |****************************************|
        32 -> 63         : 2        |**                                      |

     msecs               : count     distribution
         0 -> 1          : 1        |*                                       |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 27       |****************************************|
        32 -> 63         : 4        |*****                                   |
[...]

For comparison, here is pidstat(1) for that process:

# pidstat -p 4505 1
Linux 4.4.0-virtual (bgregg-xxxxxxxx) 	02/08/2016 	_x86_64_	(8 CPU)

08:56:11 AM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
08:56:12 AM     0      4505    9.00    3.00    0.00   12.00     0  bash
08:56:13 AM     0      4505    7.00    5.00    0.00   12.00     0  bash
08:56:14 AM     0      4505   10.00    2.00    0.00   12.00     0  bash
08:56:15 AM     0      4505   11.00    2.00    0.00   13.00     0  bash
08:56:16 AM     0      4505    9.00    3.00    0.00   12.00     0  bash
[...]

This is a synthetic workload that is CPU bound. It's only spending 12% on-CPU
each second because of high CPU demand on this server: the remaining time
is spent waiting on a run queue, as visualized by runqlat.


Here is the same system, but when it is CPU idle:

# ./runqlat 5 1
Tracing run queue latency... Hit Ctrl-C to end.

     usecs               : count     distribution
         0 -> 1          : 2250     |********************************        |
         2 -> 3          : 2340     |**********************************      |
         4 -> 7          : 2746     |****************************************|
         8 -> 15         : 418      |******                                  |
        16 -> 31         : 93       |*                                       |
        32 -> 63         : 28       |                                        |
        64 -> 127        : 119      |*                                       |
       128 -> 255        : 9        |                                        |
       256 -> 511        : 4        |                                        |
       512 -> 1023       : 20       |                                        |
      1024 -> 2047       : 22       |                                        |
      2048 -> 4095       : 5        |                                        |
      4096 -> 8191       : 2        |                                        |

Back to a microsecond scale, this time there is little run queue latency past 1
millisecond, as would be expected.


Now 16 threads are performing heavy disk I/O:

# ./runqlat 5 1
Tracing run queue latency... Hit Ctrl-C to end.

     usecs               : count     distribution
         0 -> 1          : 204      |                                        |
         2 -> 3          : 944      |*                                       |
         4 -> 7          : 16315    |*********************                   |
         8 -> 15         : 29897    |****************************************|
        16 -> 31         : 1044     |*                                       |
        32 -> 63         : 23       |                                        |
        64 -> 127        : 128      |                                        |
       128 -> 255        : 24       |                                        |
       256 -> 511        : 5        |                                        |
       512 -> 1023       : 13       |                                        |
      1024 -> 2047       : 15       |                                        |
      2048 -> 4095       : 13       |                                        |
      4096 -> 8191       : 10       |                                        |

The distribution hasn't changed too much. While the disks are 100% busy, there
is still plenty of CPU headroom, and threads still don't spend much time
waiting their turn.


A -P option will print a distribution for each PID:

# ./runqlat -P
Tracing run queue latency... Hit Ctrl-C to end.
^C

pid = 0
     usecs               : count     distribution
         0 -> 1          : 351      |********************************        |
         2 -> 3          : 96       |********                                |
         4 -> 7          : 437      |****************************************|
         8 -> 15         : 12       |*                                       |
        16 -> 31         : 10       |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 16       |*                                       |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 0        |                                        |
      1024 -> 2047       : 0        |                                        |
      2048 -> 4095       : 0        |                                        |
      4096 -> 8191       : 0        |                                        |
      8192 -> 16383      : 1        |                                        |

pid = 12929
     usecs               : count     distribution
         0 -> 1          : 1        |****************************************|
         2 -> 3          : 0        |                                        |
         4 -> 7          : 1        |****************************************|

pid = 12930
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 1        |****************************************|
        32 -> 63         : 0        |                                        |
        64 -> 127        : 1        |****************************************|

pid = 12931
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 1        |********************                    |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 2        |****************************************|

pid = 12932
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 1        |****************************************|
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 1        |****************************************|

pid = 7
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 426      |*************************************   |
         4 -> 7          : 457      |****************************************|
         8 -> 15         : 16       |*                                       |

pid = 9
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 425      |****************************************|
         8 -> 15         : 16       |*                                       |

pid = 11
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 10       |****************************************|

pid = 14
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 8        |****************************************|
         4 -> 7          : 2        |**********                              |

pid = 18
     usecs               : count     distribution
         0 -> 1          : 414      |****************************************|
         2 -> 3          : 0        |                                        |
         4 -> 7          : 20       |*                                       |
         8 -> 15         : 8        |                                        |

pid = 12928
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 1        |****************************************|
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 1        |****************************************|

pid = 1867
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 15       |****************************************|
        16 -> 31         : 1        |**                                      |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 4        |**********                              |

pid = 1871
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 2        |****************************************|
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 1        |********************                    |

pid = 1876
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |****************************************|
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 1        |****************************************|

pid = 1878
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 3        |****************************************|

pid = 1880
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 3        |****************************************|

pid = 9307
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |****************************************|

pid = 1886
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 1        |********************                    |
         8 -> 15         : 2        |****************************************|

pid = 1888
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 3        |****************************************|

pid = 3297
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |****************************************|

pid = 1892
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 1        |********************                    |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 2        |****************************************|

pid = 7024
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 4        |****************************************|

pid = 16468
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 3        |****************************************|

pid = 12922
     usecs               : count     distribution
         0 -> 1          : 1        |****************************************|
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |****************************************|
        16 -> 31         : 1        |****************************************|
        32 -> 63         : 0        |                                        |
        64 -> 127        : 1        |****************************************|

pid = 12923
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 1        |********************                    |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 2        |****************************************|
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 1        |********************                    |
      1024 -> 2047       : 1        |********************                    |

pid = 12924
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 2        |********************                    |
         8 -> 15         : 4        |****************************************|
        16 -> 31         : 1        |**********                              |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 0        |                                        |
      1024 -> 2047       : 1        |**********                              |

pid = 12925
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 1        |****************************************|

pid = 12926
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 1        |****************************************|
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |****************************************|
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 1        |****************************************|

pid = 12927
     usecs               : count     distribution
         0 -> 1          : 1        |****************************************|
         2 -> 3          : 0        |                                        |
         4 -> 7          : 1        |****************************************|


A -L option will print a distribution for each TID:

# ./runqlat -L
Tracing run queue latency... Hit Ctrl-C to end.
^C

tid = 0
     usecs               : count     distribution
         0 -> 1          : 593      |****************************            |
         2 -> 3          : 829      |****************************************|
         4 -> 7          : 300      |**************                          |
         8 -> 15         : 321      |***************                         |
        16 -> 31         : 132      |******                                  |
        32 -> 63         : 58       |**                                      |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 13       |                                        |

tid = 7
     usecs               : count     distribution
         0 -> 1          : 8        |********                                |
         2 -> 3          : 19       |********************                    |
         4 -> 7          : 37       |****************************************|
[...]


And a --pidnss option (short for PID namespaces)  will print for each PID
namespace, for analyzing container performance:

# ./runqlat --pidnss -m
Tracing run queue latency... Hit Ctrl-C to end.
^C

pidns = 4026532870
     msecs               : count     distribution
         0 -> 1          : 40       |****************************************|
         2 -> 3          : 1        |*                                       |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 2        |**                                      |
        64 -> 127        : 5        |*****                                   |

pidns = 4026532809
     msecs               : count     distribution
         0 -> 1          : 67       |****************************************|

pidns = 4026532748
     msecs               : count     distribution
         0 -> 1          : 63       |****************************************|

pidns = 4026532687
     msecs               : count     distribution
         0 -> 1          : 7        |****************************************|

pidns = 4026532626
     msecs               : count     distribution
         0 -> 1          : 45       |****************************************|
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 3        |**                                      |

pidns = 4026531836
     msecs               : count     distribution
         0 -> 1          : 314      |****************************************|
         2 -> 3          : 1        |                                        |
         4 -> 7          : 11       |*                                       |
         8 -> 15         : 28       |***                                     |
        16 -> 31         : 137      |*****************                       |
        32 -> 63         : 86       |**********                              |
        64 -> 127        : 1        |                                        |

pidns = 4026532382
     msecs               : count     distribution
         0 -> 1          : 285      |****************************************|
         2 -> 3          : 5        |                                        |
         4 -> 7          : 16       |**                                      |
         8 -> 15         : 9        |*                                       |
        16 -> 31         : 69       |*********                               |
        32 -> 63         : 25       |***                                     |

Many of these distributions have two modes: the second, in this case, is
caused by capping CPU usage via CPU shares.


USAGE message:

# ./runqlat -h
usage: runqlat.py [-h] [-T] [-m] [-P] [--pidnss] [-L] [-p PID]
                  [interval] [count]

Summarize run queue (scheduler) latency as a histogram

positional arguments:
  interval            output interval, in seconds
  count               number of outputs

optional arguments:
  -h, --help          show this help message and exit
  -T, --timestamp     include timestamp on output
  -m, --milliseconds  millisecond histogram
  -P, --pids          print a histogram per process ID
  --pidnss            print a histogram per PID namespace
  -L, --tids          print a histogram per thread ID
  -p PID, --pid PID   trace this PID only

examples:
    ./runqlat            # summarize run queue latency as a histogram
    ./runqlat 1 10       # print 1 second summaries, 10 times
    ./runqlat -mT 1      # 1s summaries, milliseconds, and timestamps
    ./runqlat -P         # show each PID separately
    ./runqlat -p 185     # trace PID 185 only