| Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 1 | Demonstrations of runqlat, the Linux eBPF/bcc version. |
| 2 | |
| 3 | |
| 4 | This program summarizes scheduler run queue latency as a histogram, showing |
| 5 | how long tasks spent waiting their turn to run on-CPU. |
| 6 | |
| 7 | Here is a heavily loaded system: |
| 8 | |
| 9 | # ./runqlat |
| 10 | Tracing run queue latency... Hit Ctrl-C to end. |
| 11 | ^C |
| 12 | usecs : count distribution |
| 13 | 0 -> 1 : 233 |*********** | |
| 14 | 2 -> 3 : 742 |************************************ | |
| 15 | 4 -> 7 : 203 |********** | |
| 16 | 8 -> 15 : 173 |******** | |
| 17 | 16 -> 31 : 24 |* | |
| 18 | 32 -> 63 : 0 | | |
| 19 | 64 -> 127 : 30 |* | |
| 20 | 128 -> 255 : 6 | | |
| 21 | 256 -> 511 : 3 | | |
| 22 | 512 -> 1023 : 5 | | |
| 23 | 1024 -> 2047 : 27 |* | |
| 24 | 2048 -> 4095 : 30 |* | |
| 25 | 4096 -> 8191 : 20 | | |
| 26 | 8192 -> 16383 : 29 |* | |
| 27 | 16384 -> 32767 : 809 |****************************************| |
| 28 | 32768 -> 65535 : 64 |*** | |
| 29 | |
| 30 | The distribution is bimodal, with one mode between 0 and 15 microseconds, |
| 31 | and another between 16 and 65 milliseconds. These modes are visible as the |
| 32 | spikes in the ASCII distribution (which is merely a visual representation |
| 33 | of the "count" column). As an example of reading one line: 809 events fell |
| 34 | into the 16384 to 32767 microsecond range (16 to 32 ms) while tracing. |
| 35 | |
| 36 | I would expect the two modes to be due the workload: 16 hot CPU-bound threads, |
| 37 | and many other mostly idle threads doing occasional work. I suspect the mostly |
| 38 | idle threads will run with a higher priority when they wake up, and are |
| 39 | the reason for the low latency mode. The high latency mode will be the |
| 40 | CPU-bound threads. More analysis with this and other tools can confirm. |
| 41 | |
| 42 | |
| 43 | A -m option can be used to show milliseconds instead, as well as an interval |
| 44 | and a count. For example, showing three x five second summary in milliseconds: |
| 45 | |
| 46 | # ./runqlat -m 5 3 |
| 47 | Tracing run queue latency... Hit Ctrl-C to end. |
| 48 | |
| 49 | msecs : count distribution |
| 50 | 0 -> 1 : 3818 |****************************************| |
| 51 | 2 -> 3 : 39 | | |
| 52 | 4 -> 7 : 39 | | |
| 53 | 8 -> 15 : 62 | | |
| 54 | 16 -> 31 : 2214 |*********************** | |
| 55 | 32 -> 63 : 226 |** | |
| 56 | |
| 57 | msecs : count distribution |
| 58 | 0 -> 1 : 3775 |****************************************| |
| 59 | 2 -> 3 : 52 | | |
| 60 | 4 -> 7 : 37 | | |
| 61 | 8 -> 15 : 65 | | |
| 62 | 16 -> 31 : 2230 |*********************** | |
| 63 | 32 -> 63 : 212 |** | |
| 64 | |
| 65 | msecs : count distribution |
| 66 | 0 -> 1 : 3816 |****************************************| |
| 67 | 2 -> 3 : 49 | | |
| 68 | 4 -> 7 : 40 | | |
| 69 | 8 -> 15 : 53 | | |
| 70 | 16 -> 31 : 2228 |*********************** | |
| 71 | 32 -> 63 : 221 |** | |
| 72 | |
| 73 | This shows a similar distribution across the three summaries. |
| 74 | |
| 75 | |
| 76 | A -p option can be used to show one PID only, which is filtered in kernel for |
| 77 | efficiency. For example, PID 4505, and one second summaries: |
| 78 | |
| 79 | # ./runqlat -mp 4505 1 |
| 80 | Tracing run queue latency... Hit Ctrl-C to end. |
| 81 | |
| 82 | msecs : count distribution |
| 83 | 0 -> 1 : 1 |* | |
| 84 | 2 -> 3 : 2 |*** | |
| 85 | 4 -> 7 : 1 |* | |
| 86 | 8 -> 15 : 0 | | |
| 87 | 16 -> 31 : 25 |****************************************| |
| 88 | 32 -> 63 : 3 |**** | |
| 89 | |
| 90 | msecs : count distribution |
| 91 | 0 -> 1 : 0 | | |
| 92 | 2 -> 3 : 2 |** | |
| 93 | 4 -> 7 : 0 | | |
| 94 | 8 -> 15 : 1 |* | |
| 95 | 16 -> 31 : 30 |****************************************| |
| 96 | 32 -> 63 : 1 |* | |
| 97 | |
| 98 | msecs : count distribution |
| 99 | 0 -> 1 : 0 | | |
| 100 | 2 -> 3 : 0 | | |
| 101 | 4 -> 7 : 0 | | |
| 102 | 8 -> 15 : 0 | | |
| 103 | 16 -> 31 : 28 |****************************************| |
| 104 | 32 -> 63 : 2 |** | |
| 105 | |
| 106 | msecs : count distribution |
| 107 | 0 -> 1 : 1 |* | |
| 108 | 2 -> 3 : 0 | | |
| 109 | 4 -> 7 : 0 | | |
| 110 | 8 -> 15 : 0 | | |
| 111 | 16 -> 31 : 27 |****************************************| |
| 112 | 32 -> 63 : 4 |***** | |
| 113 | [...] |
| 114 | |
| 115 | For comparison, here is pidstat(1) for that process: |
| 116 | |
| 117 | # pidstat -p 4505 1 |
| 118 | Linux 4.4.0-virtual (bgregg-xxxxxxxx) 02/08/2016 _x86_64_ (8 CPU) |
| 119 | |
| 120 | 08:56:11 AM UID PID %usr %system %guest %CPU CPU Command |
| 121 | 08:56:12 AM 0 4505 9.00 3.00 0.00 12.00 0 bash |
| 122 | 08:56:13 AM 0 4505 7.00 5.00 0.00 12.00 0 bash |
| 123 | 08:56:14 AM 0 4505 10.00 2.00 0.00 12.00 0 bash |
| 124 | 08:56:15 AM 0 4505 11.00 2.00 0.00 13.00 0 bash |
| 125 | 08:56:16 AM 0 4505 9.00 3.00 0.00 12.00 0 bash |
| 126 | [...] |
| 127 | |
| 128 | This is a synthetic workload that is CPU bound. It's only spending 12% on-CPU |
| 129 | each second because of high CPU demand on this server: the remaining time |
| 130 | is spent waiting on a run queue, as visualized by runqlat. |
| 131 | |
| 132 | |
| 133 | Here is the same system, but when it is CPU idle: |
| 134 | |
| 135 | # ./runqlat 5 1 |
| 136 | Tracing run queue latency... Hit Ctrl-C to end. |
| 137 | |
| 138 | usecs : count distribution |
| 139 | 0 -> 1 : 2250 |******************************** | |
| 140 | 2 -> 3 : 2340 |********************************** | |
| 141 | 4 -> 7 : 2746 |****************************************| |
| 142 | 8 -> 15 : 418 |****** | |
| 143 | 16 -> 31 : 93 |* | |
| 144 | 32 -> 63 : 28 | | |
| 145 | 64 -> 127 : 119 |* | |
| 146 | 128 -> 255 : 9 | | |
| 147 | 256 -> 511 : 4 | | |
| 148 | 512 -> 1023 : 20 | | |
| 149 | 1024 -> 2047 : 22 | | |
| 150 | 2048 -> 4095 : 5 | | |
| 151 | 4096 -> 8191 : 2 | | |
| 152 | |
| 153 | Back to a microsecond scale, this time there is little run queue latency past 1 |
| 154 | millisecond, as would be expected. |
| 155 | |
| 156 | |
| 157 | Now 16 threads are performing heavy disk I/O: |
| 158 | |
| 159 | # ./runqlat 5 1 |
| 160 | Tracing run queue latency... Hit Ctrl-C to end. |
| 161 | |
| 162 | usecs : count distribution |
| 163 | 0 -> 1 : 204 | | |
| 164 | 2 -> 3 : 944 |* | |
| 165 | 4 -> 7 : 16315 |********************* | |
| 166 | 8 -> 15 : 29897 |****************************************| |
| 167 | 16 -> 31 : 1044 |* | |
| 168 | 32 -> 63 : 23 | | |
| 169 | 64 -> 127 : 128 | | |
| 170 | 128 -> 255 : 24 | | |
| 171 | 256 -> 511 : 5 | | |
| 172 | 512 -> 1023 : 13 | | |
| 173 | 1024 -> 2047 : 15 | | |
| 174 | 2048 -> 4095 : 13 | | |
| 175 | 4096 -> 8191 : 10 | | |
| 176 | |
| 177 | The distribution hasn't changed too much. While the disks are 100% busy, there |
| 178 | is still plenty of CPU headroom, and threads still don't spend much time |
| 179 | waiting their turn. |
| 180 | |
| 181 | |
| 182 | A -P option will print a distribution for each PID: |
| 183 | |
| 184 | # ./runqlat -P |
| 185 | Tracing run queue latency... Hit Ctrl-C to end. |
| 186 | ^C |
| 187 | |
| 188 | pid = 0 |
| 189 | usecs : count distribution |
| 190 | 0 -> 1 : 351 |******************************** | |
| 191 | 2 -> 3 : 96 |******** | |
| 192 | 4 -> 7 : 437 |****************************************| |
| 193 | 8 -> 15 : 12 |* | |
| 194 | 16 -> 31 : 10 | | |
| 195 | 32 -> 63 : 0 | | |
| 196 | 64 -> 127 : 16 |* | |
| 197 | 128 -> 255 : 0 | | |
| 198 | 256 -> 511 : 0 | | |
| 199 | 512 -> 1023 : 0 | | |
| 200 | 1024 -> 2047 : 0 | | |
| 201 | 2048 -> 4095 : 0 | | |
| 202 | 4096 -> 8191 : 0 | | |
| 203 | 8192 -> 16383 : 1 | | |
| 204 | |
| 205 | pid = 12929 |
| 206 | usecs : count distribution |
| 207 | 0 -> 1 : 1 |****************************************| |
| 208 | 2 -> 3 : 0 | | |
| 209 | 4 -> 7 : 1 |****************************************| |
| 210 | |
| 211 | pid = 12930 |
| 212 | usecs : count distribution |
| 213 | 0 -> 1 : 0 | | |
| 214 | 2 -> 3 : 0 | | |
| 215 | 4 -> 7 : 0 | | |
| 216 | 8 -> 15 : 0 | | |
| 217 | 16 -> 31 : 1 |****************************************| |
| 218 | 32 -> 63 : 0 | | |
| 219 | 64 -> 127 : 1 |****************************************| |
| 220 | |
| 221 | pid = 12931 |
| 222 | usecs : count distribution |
| 223 | 0 -> 1 : 0 | | |
| 224 | 2 -> 3 : 0 | | |
| 225 | 4 -> 7 : 1 |******************** | |
| 226 | 8 -> 15 : 0 | | |
| 227 | 16 -> 31 : 0 | | |
| 228 | 32 -> 63 : 0 | | |
| 229 | 64 -> 127 : 0 | | |
| 230 | 128 -> 255 : 0 | | |
| 231 | 256 -> 511 : 0 | | |
| 232 | 512 -> 1023 : 2 |****************************************| |
| 233 | |
| 234 | pid = 12932 |
| 235 | usecs : count distribution |
| 236 | 0 -> 1 : 0 | | |
| 237 | 2 -> 3 : 0 | | |
| 238 | 4 -> 7 : 0 | | |
| 239 | 8 -> 15 : 0 | | |
| 240 | 16 -> 31 : 0 | | |
| 241 | 32 -> 63 : 0 | | |
| 242 | 64 -> 127 : 0 | | |
| 243 | 128 -> 255 : 1 |****************************************| |
| 244 | 256 -> 511 : 0 | | |
| 245 | 512 -> 1023 : 1 |****************************************| |
| 246 | |
| 247 | pid = 7 |
| 248 | usecs : count distribution |
| 249 | 0 -> 1 : 0 | | |
| 250 | 2 -> 3 : 426 |************************************* | |
| 251 | 4 -> 7 : 457 |****************************************| |
| 252 | 8 -> 15 : 16 |* | |
| 253 | |
| 254 | pid = 9 |
| 255 | usecs : count distribution |
| 256 | 0 -> 1 : 0 | | |
| 257 | 2 -> 3 : 0 | | |
| 258 | 4 -> 7 : 425 |****************************************| |
| 259 | 8 -> 15 : 16 |* | |
| 260 | |
| 261 | pid = 11 |
| 262 | usecs : count distribution |
| 263 | 0 -> 1 : 0 | | |
| 264 | 2 -> 3 : 10 |****************************************| |
| 265 | |
| 266 | pid = 14 |
| 267 | usecs : count distribution |
| 268 | 0 -> 1 : 0 | | |
| 269 | 2 -> 3 : 8 |****************************************| |
| 270 | 4 -> 7 : 2 |********** | |
| 271 | |
| 272 | pid = 18 |
| 273 | usecs : count distribution |
| 274 | 0 -> 1 : 414 |****************************************| |
| 275 | 2 -> 3 : 0 | | |
| 276 | 4 -> 7 : 20 |* | |
| 277 | 8 -> 15 : 8 | | |
| 278 | |
| 279 | pid = 12928 |
| 280 | usecs : count distribution |
| 281 | 0 -> 1 : 0 | | |
| 282 | 2 -> 3 : 0 | | |
| 283 | 4 -> 7 : 1 |****************************************| |
| 284 | 8 -> 15 : 0 | | |
| 285 | 16 -> 31 : 0 | | |
| 286 | 32 -> 63 : 0 | | |
| 287 | 64 -> 127 : 1 |****************************************| |
| 288 | |
| 289 | pid = 1867 |
| 290 | usecs : count distribution |
| 291 | 0 -> 1 : 0 | | |
| 292 | 2 -> 3 : 0 | | |
| 293 | 4 -> 7 : 0 | | |
| 294 | 8 -> 15 : 15 |****************************************| |
| 295 | 16 -> 31 : 1 |** | |
| 296 | 32 -> 63 : 0 | | |
| 297 | 64 -> 127 : 0 | | |
| 298 | 128 -> 255 : 4 |********** | |
| 299 | |
| 300 | pid = 1871 |
| 301 | usecs : count distribution |
| 302 | 0 -> 1 : 0 | | |
| 303 | 2 -> 3 : 0 | | |
| 304 | 4 -> 7 : 0 | | |
| 305 | 8 -> 15 : 2 |****************************************| |
| 306 | 16 -> 31 : 0 | | |
| 307 | 32 -> 63 : 0 | | |
| 308 | 64 -> 127 : 0 | | |
| 309 | 128 -> 255 : 0 | | |
| 310 | 256 -> 511 : 0 | | |
| 311 | 512 -> 1023 : 1 |******************** | |
| 312 | |
| 313 | pid = 1876 |
| 314 | usecs : count distribution |
| 315 | 0 -> 1 : 0 | | |
| 316 | 2 -> 3 : 0 | | |
| 317 | 4 -> 7 : 0 | | |
| 318 | 8 -> 15 : 1 |****************************************| |
| 319 | 16 -> 31 : 0 | | |
| 320 | 32 -> 63 : 0 | | |
| 321 | 64 -> 127 : 0 | | |
| 322 | 128 -> 255 : 0 | | |
| 323 | 256 -> 511 : 1 |****************************************| |
| 324 | |
| 325 | pid = 1878 |
| 326 | usecs : count distribution |
| 327 | 0 -> 1 : 0 | | |
| 328 | 2 -> 3 : 0 | | |
| 329 | 4 -> 7 : 0 | | |
| 330 | 8 -> 15 : 0 | | |
| 331 | 16 -> 31 : 3 |****************************************| |
| 332 | |
| 333 | pid = 1880 |
| 334 | usecs : count distribution |
| 335 | 0 -> 1 : 0 | | |
| 336 | 2 -> 3 : 0 | | |
| 337 | 4 -> 7 : 0 | | |
| 338 | 8 -> 15 : 3 |****************************************| |
| 339 | |
| 340 | pid = 9307 |
| 341 | usecs : count distribution |
| 342 | 0 -> 1 : 0 | | |
| 343 | 2 -> 3 : 0 | | |
| 344 | 4 -> 7 : 0 | | |
| 345 | 8 -> 15 : 1 |****************************************| |
| 346 | |
| 347 | pid = 1886 |
| 348 | usecs : count distribution |
| 349 | 0 -> 1 : 0 | | |
| 350 | 2 -> 3 : 0 | | |
| 351 | 4 -> 7 : 1 |******************** | |
| 352 | 8 -> 15 : 2 |****************************************| |
| 353 | |
| 354 | pid = 1888 |
| 355 | usecs : count distribution |
| 356 | 0 -> 1 : 0 | | |
| 357 | 2 -> 3 : 0 | | |
| 358 | 4 -> 7 : 0 | | |
| 359 | 8 -> 15 : 3 |****************************************| |
| 360 | |
| 361 | pid = 3297 |
| 362 | usecs : count distribution |
| 363 | 0 -> 1 : 0 | | |
| 364 | 2 -> 3 : 0 | | |
| 365 | 4 -> 7 : 0 | | |
| 366 | 8 -> 15 : 1 |****************************************| |
| 367 | |
| 368 | pid = 1892 |
| 369 | usecs : count distribution |
| 370 | 0 -> 1 : 0 | | |
| 371 | 2 -> 3 : 0 | | |
| 372 | 4 -> 7 : 0 | | |
| 373 | 8 -> 15 : 0 | | |
| 374 | 16 -> 31 : 1 |******************** | |
| 375 | 32 -> 63 : 0 | | |
| 376 | 64 -> 127 : 0 | | |
| 377 | 128 -> 255 : 0 | | |
| 378 | 256 -> 511 : 0 | | |
| 379 | 512 -> 1023 : 2 |****************************************| |
| 380 | |
| 381 | pid = 7024 |
| 382 | usecs : count distribution |
| 383 | 0 -> 1 : 0 | | |
| 384 | 2 -> 3 : 0 | | |
| 385 | 4 -> 7 : 0 | | |
| 386 | 8 -> 15 : 4 |****************************************| |
| 387 | |
| 388 | pid = 16468 |
| 389 | usecs : count distribution |
| 390 | 0 -> 1 : 0 | | |
| 391 | 2 -> 3 : 0 | | |
| 392 | 4 -> 7 : 0 | | |
| 393 | 8 -> 15 : 3 |****************************************| |
| 394 | |
| 395 | pid = 12922 |
| 396 | usecs : count distribution |
| 397 | 0 -> 1 : 1 |****************************************| |
| 398 | 2 -> 3 : 0 | | |
| 399 | 4 -> 7 : 0 | | |
| 400 | 8 -> 15 : 1 |****************************************| |
| 401 | 16 -> 31 : 1 |****************************************| |
| 402 | 32 -> 63 : 0 | | |
| 403 | 64 -> 127 : 1 |****************************************| |
| 404 | |
| 405 | pid = 12923 |
| 406 | usecs : count distribution |
| 407 | 0 -> 1 : 0 | | |
| 408 | 2 -> 3 : 0 | | |
| 409 | 4 -> 7 : 1 |******************** | |
| 410 | 8 -> 15 : 0 | | |
| 411 | 16 -> 31 : 0 | | |
| 412 | 32 -> 63 : 0 | | |
| 413 | 64 -> 127 : 2 |****************************************| |
| 414 | 128 -> 255 : 0 | | |
| 415 | 256 -> 511 : 0 | | |
| 416 | 512 -> 1023 : 1 |******************** | |
| 417 | 1024 -> 2047 : 1 |******************** | |
| 418 | |
| 419 | pid = 12924 |
| 420 | usecs : count distribution |
| 421 | 0 -> 1 : 0 | | |
| 422 | 2 -> 3 : 0 | | |
| 423 | 4 -> 7 : 2 |******************** | |
| 424 | 8 -> 15 : 4 |****************************************| |
| 425 | 16 -> 31 : 1 |********** | |
| 426 | 32 -> 63 : 0 | | |
| 427 | 64 -> 127 : 0 | | |
| 428 | 128 -> 255 : 0 | | |
| 429 | 256 -> 511 : 0 | | |
| 430 | 512 -> 1023 : 0 | | |
| 431 | 1024 -> 2047 : 1 |********** | |
| 432 | |
| 433 | pid = 12925 |
| 434 | usecs : count distribution |
| 435 | 0 -> 1 : 0 | | |
| 436 | 2 -> 3 : 0 | | |
| 437 | 4 -> 7 : 0 | | |
| 438 | 8 -> 15 : 0 | | |
| 439 | 16 -> 31 : 0 | | |
| 440 | 32 -> 63 : 0 | | |
| 441 | 64 -> 127 : 1 |****************************************| |
| 442 | |
| 443 | pid = 12926 |
| 444 | usecs : count distribution |
| 445 | 0 -> 1 : 0 | | |
| 446 | 2 -> 3 : 1 |****************************************| |
| 447 | 4 -> 7 : 0 | | |
| 448 | 8 -> 15 : 1 |****************************************| |
| 449 | 16 -> 31 : 0 | | |
| 450 | 32 -> 63 : 0 | | |
| 451 | 64 -> 127 : 0 | | |
| 452 | 128 -> 255 : 0 | | |
| 453 | 256 -> 511 : 0 | | |
| 454 | 512 -> 1023 : 1 |****************************************| |
| 455 | |
| 456 | pid = 12927 |
| 457 | usecs : count distribution |
| 458 | 0 -> 1 : 1 |****************************************| |
| 459 | 2 -> 3 : 0 | | |
| 460 | 4 -> 7 : 1 |****************************************| |
| 461 | |
| 462 | |
| Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 463 | A -L option will print a distribution for each TID: |
| 464 | |
| 465 | # ./runqlat -L |
| 466 | Tracing run queue latency... Hit Ctrl-C to end. |
| 467 | ^C |
| 468 | |
| 469 | tid = 0 |
| 470 | usecs : count distribution |
| 471 | 0 -> 1 : 593 |**************************** | |
| 472 | 2 -> 3 : 829 |****************************************| |
| 473 | 4 -> 7 : 300 |************** | |
| 474 | 8 -> 15 : 321 |*************** | |
| 475 | 16 -> 31 : 132 |****** | |
| 476 | 32 -> 63 : 58 |** | |
| 477 | 64 -> 127 : 0 | | |
| 478 | 128 -> 255 : 0 | | |
| 479 | 256 -> 511 : 13 | | |
| 480 | |
| 481 | tid = 7 |
| 482 | usecs : count distribution |
| 483 | 0 -> 1 : 8 |******** | |
| 484 | 2 -> 3 : 19 |******************** | |
| 485 | 4 -> 7 : 37 |****************************************| |
| 486 | [...] |
| 487 | |
| 488 | |
| Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 489 | And a --pidnss option (short for PID namespaces) will print for each PID |
| 490 | namespace, for analyzing container performance: |
| 491 | |
| 492 | # ./runqlat --pidnss -m |
| 493 | Tracing run queue latency... Hit Ctrl-C to end. |
| 494 | ^C |
| 495 | |
| 496 | pidns = 4026532870 |
| 497 | msecs : count distribution |
| 498 | 0 -> 1 : 40 |****************************************| |
| 499 | 2 -> 3 : 1 |* | |
| 500 | 4 -> 7 : 0 | | |
| 501 | 8 -> 15 : 0 | | |
| 502 | 16 -> 31 : 0 | | |
| 503 | 32 -> 63 : 2 |** | |
| 504 | 64 -> 127 : 5 |***** | |
| 505 | |
| 506 | pidns = 4026532809 |
| 507 | msecs : count distribution |
| 508 | 0 -> 1 : 67 |****************************************| |
| 509 | |
| 510 | pidns = 4026532748 |
| 511 | msecs : count distribution |
| 512 | 0 -> 1 : 63 |****************************************| |
| 513 | |
| 514 | pidns = 4026532687 |
| 515 | msecs : count distribution |
| 516 | 0 -> 1 : 7 |****************************************| |
| 517 | |
| 518 | pidns = 4026532626 |
| 519 | msecs : count distribution |
| 520 | 0 -> 1 : 45 |****************************************| |
| 521 | 2 -> 3 : 0 | | |
| 522 | 4 -> 7 : 0 | | |
| 523 | 8 -> 15 : 0 | | |
| 524 | 16 -> 31 : 0 | | |
| 525 | 32 -> 63 : 0 | | |
| 526 | 64 -> 127 : 3 |** | |
| 527 | |
| 528 | pidns = 4026531836 |
| 529 | msecs : count distribution |
| 530 | 0 -> 1 : 314 |****************************************| |
| 531 | 2 -> 3 : 1 | | |
| 532 | 4 -> 7 : 11 |* | |
| 533 | 8 -> 15 : 28 |*** | |
| 534 | 16 -> 31 : 137 |***************** | |
| 535 | 32 -> 63 : 86 |********** | |
| 536 | 64 -> 127 : 1 | | |
| 537 | |
| 538 | pidns = 4026532382 |
| 539 | msecs : count distribution |
| 540 | 0 -> 1 : 285 |****************************************| |
| 541 | 2 -> 3 : 5 | | |
| 542 | 4 -> 7 : 16 |** | |
| 543 | 8 -> 15 : 9 |* | |
| 544 | 16 -> 31 : 69 |********* | |
| 545 | 32 -> 63 : 25 |*** | |
| 546 | |
| 547 | Many of these distributions have two modes: the second, in this case, is |
| 548 | caused by capping CPU usage via CPU shares. |
| 549 | |
| 550 | |
| Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 551 | USAGE message: |
| 552 | |
| 553 | # ./runqlat -h |
| Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 554 | usage: runqlat.py [-h] [-T] [-m] [-P] [--pidnss] [-L] [-p PID] |
| 555 | [interval] [count] |
| Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 556 | |
| Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 557 | Summarize run queue (scheduler) latency as a histogram |
| Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 558 | |
| 559 | positional arguments: |
| 560 | interval output interval, in seconds |
| 561 | count number of outputs |
| 562 | |
| 563 | optional arguments: |
| 564 | -h, --help show this help message and exit |
| 565 | -T, --timestamp include timestamp on output |
| 566 | -m, --milliseconds millisecond histogram |
| 567 | -P, --pids print a histogram per process ID |
| Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 568 | --pidnss print a histogram per PID namespace |
| Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 569 | -L, --tids print a histogram per thread ID |
| Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 570 | -p PID, --pid PID trace this PID only |
| 571 | |
| 572 | examples: |
| 573 | ./runqlat # summarize run queue latency as a histogram |
| 574 | ./runqlat 1 10 # print 1 second summaries, 10 times |
| 575 | ./runqlat -mT 1 # 1s summaries, milliseconds, and timestamps |
| 576 | ./runqlat -P # show each PID separately |
| 577 | ./runqlat -p 185 # trace PID 185 only |