1Demonstrations of hardirqs, the Linux eBPF/bcc version. 2 3 4This program traces hard interrupts (irqs), and stores timing statistics 5in-kernel for efficiency. For example: 6 7# ./hardirqs 8Tracing hard irq event time... Hit Ctrl-C to end. 9^C 10HARDIRQ TOTAL_usecs 11callfuncsingle0 2 12callfuncsingle5 5 13callfuncsingle6 5 14callfuncsingle7 21 15blkif 66 16timer7 84 17resched5 94 18resched0 97 19resched3 102 20resched7 111 21resched6 255 22timer3 362 23resched4 367 24timer5 474 25timer1 529 26timer6 679 27timer2 746 28timer4 943 29resched1 1048 30timer0 1558 31resched2 1750 32eth0 11441 33 34The HARDIRQ column prints the interrupt action name. While tracing, the eth0 35hard irq action ran for 11441 microseconds (11 milliseconds) in total. 36 37Many other interrupts are visible in the output: this is an 8 CPU system, and 38some of these interrupts have a separate action per-CPU (eg, "timer", 39"resched"). 40 41 42An interval can be provided, and also optionally a count. Eg, printing output 43every 1 second, and including timestamps (-T): 44 45# ./hardirqs -T 1 3 46Tracing hard irq event time... Hit Ctrl-C to end. 47 4822:16:14 49HARDIRQ TOTAL_usecs 50callfuncsingle0 2 51callfuncsingle7 5 52callfuncsingle3 5 53callfuncsingle2 5 54callfuncsingle6 6 55callfuncsingle1 11 56resched0 32 57blkif 51 58resched5 71 59resched7 71 60resched4 72 61resched6 82 62timer7 172 63resched1 187 64resched2 236 65timer3 252 66resched3 282 67timer1 320 68timer2 374 69timer6 396 70timer5 427 71timer4 470 72timer0 1430 73eth0 7498 74 7522:16:15 76HARDIRQ TOTAL_usecs 77callfuncsingle7 6 78callfuncsingle5 11 79callfuncsingle4 13 80timer2 17 81callfuncsingle6 18 82resched0 21 83blkif 33 84resched3 40 85resched5 60 86resched4 69 87resched6 70 88resched7 74 89timer7 86 90resched2 91 91timer3 134 92resched1 293 93timer5 354 94timer1 433 95timer6 497 96timer4 1112 97timer0 1768 98eth0 6972 99 10022:16:16 101HARDIRQ TOTAL_usecs 102callfuncsingle7 5 103callfuncsingle3 5 104callfuncsingle2 6 105timer3 10 106resched0 18 107callfuncsingle4 22 108resched5 27 109resched6 44 110blkif 45 111resched7 65 112resched4 69 113timer4 77 114resched2 97 115timer7 98 116resched3 103 117timer2 169 118resched1 226 119timer5 525 120timer1 691 121timer6 697 122timer0 1415 123eth0 7152 124 125This can be useful for quantifying where CPU cycles are spent among the hard 126interrupts (summarized as the %irq column from mpstat(1)). The output above 127shows that most time was spent processing for eth0 (network interface), which 128was around 7 milliseconds per second (total across all CPUs). 129 130Note that the time spent among the "timer" interrupts was low, and usually less 131than one microsecond per second. Here's the hardirq per-second output when the 132perf tool is performing a 999 Hertz CPU profile ("perf record -F 999 -a ..."): 133 13422:13:59 135HARDIRQ TOTAL_usecs 136callfuncsingle7 5 137callfuncsingle5 5 138callfuncsingle3 6 139callfuncsingle4 7 140callfuncsingle6 19 141blkif 66 142resched0 66 143resched2 82 144resched7 87 145resched3 96 146resched4 118 147resched5 120 148resched6 130 149resched1 230 150timer3 946 151timer1 1981 152timer7 2618 153timer5 3063 154timer6 3141 155timer4 3511 156timer2 3554 157timer0 5044 158eth0 16015 159 160This sheds some light into the CPU overhead of the perf profiler, which cost 161around 3 milliseconds per second. Note that I'm usually profiling at a much 162lower rate, 99 Hertz, which looks like this: 163 16422:22:12 165HARDIRQ TOTAL_usecs 166callfuncsingle3 5 167callfuncsingle6 5 168callfuncsingle5 22 169blkif 46 170resched6 47 171resched5 57 172resched4 66 173resched7 78 174resched2 97 175resched0 214 176timer2 326 177timer0 498 178timer5 536 179timer6 576 180timer1 600 181timer4 982 182resched1 1315 183timer7 1364 184timer3 1825 185resched3 5708 186eth0 9743 187 188Much lower (and remember to compare this to the baseline). Note that perf has 189other overheads (non-irq CPU cycles, file system storage). 190 191 192The distribution of interrupt run time can be printed as a histogram with the -d 193option. Eg: 194 195# ./hardirqs -d 196Tracing hard irq event time... Hit Ctrl-C to end. 197^C 198 199hardirq = 'callfuncsingle1' 200 usecs : count distribution 201 0 -> 1 : 0 | | 202 2 -> 3 : 0 | | 203 4 -> 7 : 0 | | 204 8 -> 15 : 0 | | 205 16 -> 31 : 0 | | 206 32 -> 63 : 0 | | 207 64 -> 127 : 0 | | 208 128 -> 255 : 0 | | 209 256 -> 511 : 0 | | 210 512 -> 1023 : 0 | | 211 1024 -> 2047 : 0 | | 212 2048 -> 4095 : 0 | | 213 4096 -> 8191 : 0 | | 214 8192 -> 16383 : 1 |****************************************| 215 216hardirq = 'callfuncsingle0' 217 usecs : count distribution 218 0 -> 1 : 0 | | 219 2 -> 3 : 0 | | 220 4 -> 7 : 0 | | 221 8 -> 15 : 0 | | 222 16 -> 31 : 0 | | 223 32 -> 63 : 0 | | 224 64 -> 127 : 0 | | 225 128 -> 255 : 0 | | 226 256 -> 511 : 0 | | 227 512 -> 1023 : 0 | | 228 1024 -> 2047 : 0 | | 229 2048 -> 4095 : 1 |****************************************| 230 231hardirq = 'callfuncsingle3' 232 usecs : count distribution 233 0 -> 1 : 0 | | 234 2 -> 3 : 0 | | 235 4 -> 7 : 0 | | 236 8 -> 15 : 0 | | 237 16 -> 31 : 0 | | 238 32 -> 63 : 0 | | 239 64 -> 127 : 0 | | 240 128 -> 255 : 0 | | 241 256 -> 511 : 0 | | 242 512 -> 1023 : 0 | | 243 1024 -> 2047 : 0 | | 244 2048 -> 4095 : 0 | | 245 4096 -> 8191 : 3 |****************************************| 246 247hardirq = 'callfuncsingle2' 248 usecs : count distribution 249 0 -> 1 : 0 | | 250 2 -> 3 : 0 | | 251 4 -> 7 : 0 | | 252 8 -> 15 : 0 | | 253 16 -> 31 : 0 | | 254 32 -> 63 : 0 | | 255 64 -> 127 : 0 | | 256 128 -> 255 : 0 | | 257 256 -> 511 : 0 | | 258 512 -> 1023 : 0 | | 259 1024 -> 2047 : 0 | | 260 2048 -> 4095 : 0 | | 261 4096 -> 8191 : 2 |****************************************| 262 263hardirq = 'callfuncsingle5' 264 usecs : count distribution 265 0 -> 1 : 0 | | 266 2 -> 3 : 0 | | 267 4 -> 7 : 0 | | 268 8 -> 15 : 0 | | 269 16 -> 31 : 0 | | 270 32 -> 63 : 0 | | 271 64 -> 127 : 0 | | 272 128 -> 255 : 0 | | 273 256 -> 511 : 0 | | 274 512 -> 1023 : 0 | | 275 1024 -> 2047 : 0 | | 276 2048 -> 4095 : 0 | | 277 4096 -> 8191 : 5 |****************************************| 278 279hardirq = 'callfuncsingle4' 280 usecs : count distribution 281 0 -> 1 : 0 | | 282 2 -> 3 : 0 | | 283 4 -> 7 : 0 | | 284 8 -> 15 : 0 | | 285 16 -> 31 : 0 | | 286 32 -> 63 : 0 | | 287 64 -> 127 : 0 | | 288 128 -> 255 : 0 | | 289 256 -> 511 : 0 | | 290 512 -> 1023 : 0 | | 291 1024 -> 2047 : 0 | | 292 2048 -> 4095 : 0 | | 293 4096 -> 8191 : 6 |****************************************| 294 295hardirq = 'callfuncsingle7' 296 usecs : count distribution 297 0 -> 1 : 0 | | 298 2 -> 3 : 0 | | 299 4 -> 7 : 0 | | 300 8 -> 15 : 0 | | 301 16 -> 31 : 0 | | 302 32 -> 63 : 0 | | 303 64 -> 127 : 0 | | 304 128 -> 255 : 0 | | 305 256 -> 511 : 0 | | 306 512 -> 1023 : 0 | | 307 1024 -> 2047 : 0 | | 308 2048 -> 4095 : 0 | | 309 4096 -> 8191 : 4 |****************************************| 310 311hardirq = 'callfuncsingle6' 312 usecs : count distribution 313 0 -> 1 : 0 | | 314 2 -> 3 : 0 | | 315 4 -> 7 : 0 | | 316 8 -> 15 : 0 | | 317 16 -> 31 : 0 | | 318 32 -> 63 : 0 | | 319 64 -> 127 : 0 | | 320 128 -> 255 : 0 | | 321 256 -> 511 : 0 | | 322 512 -> 1023 : 0 | | 323 1024 -> 2047 : 0 | | 324 2048 -> 4095 : 0 | | 325 4096 -> 8191 : 4 |****************************************| 326 327hardirq = 'eth0' 328 usecs : count distribution 329 0 -> 1 : 0 | | 330 2 -> 3 : 0 | | 331 4 -> 7 : 0 | | 332 8 -> 15 : 0 | | 333 16 -> 31 : 0 | | 334 32 -> 63 : 0 | | 335 64 -> 127 : 0 | | 336 128 -> 255 : 0 | | 337 256 -> 511 : 0 | | 338 512 -> 1023 : 5102 |********* | 339 1024 -> 2047 : 20617 |****************************************| 340 2048 -> 4095 : 4832 |********* | 341 4096 -> 8191 : 12 | | 342 343hardirq = 'timer7' 344 usecs : count distribution 345 0 -> 1 : 0 | | 346 2 -> 3 : 0 | | 347 4 -> 7 : 0 | | 348 8 -> 15 : 0 | | 349 16 -> 31 : 0 | | 350 32 -> 63 : 0 | | 351 64 -> 127 : 0 | | 352 128 -> 255 : 0 | | 353 256 -> 511 : 0 | | 354 512 -> 1023 : 0 | | 355 1024 -> 2047 : 9 |*** | 356 2048 -> 4095 : 70 |***************************** | 357 4096 -> 8191 : 94 |****************************************| 358 359hardirq = 'timer6' 360 usecs : count distribution 361 0 -> 1 : 0 | | 362 2 -> 3 : 0 | | 363 4 -> 7 : 0 | | 364 8 -> 15 : 0 | | 365 16 -> 31 : 0 | | 366 32 -> 63 : 0 | | 367 64 -> 127 : 0 | | 368 128 -> 255 : 0 | | 369 256 -> 511 : 0 | | 370 512 -> 1023 : 0 | | 371 1024 -> 2047 : 1 | | 372 2048 -> 4095 : 86 |*********** | 373 4096 -> 8191 : 295 |****************************************| 374 8192 -> 16383 : 28 |*** | 375 376hardirq = 'timer5' 377 usecs : count distribution 378 0 -> 1 : 0 | | 379 2 -> 3 : 0 | | 380 4 -> 7 : 0 | | 381 8 -> 15 : 0 | | 382 16 -> 31 : 0 | | 383 32 -> 63 : 0 | | 384 64 -> 127 : 0 | | 385 128 -> 255 : 0 | | 386 256 -> 511 : 0 | | 387 512 -> 1023 : 1 | | 388 1024 -> 2047 : 0 | | 389 2048 -> 4095 : 137 |****************************************| 390 4096 -> 8191 : 123 |*********************************** | 391 8192 -> 16383 : 8 |** | 392 393hardirq = 'timer4' 394 usecs : count distribution 395 0 -> 1 : 0 | | 396 2 -> 3 : 0 | | 397 4 -> 7 : 0 | | 398 8 -> 15 : 0 | | 399 16 -> 31 : 0 | | 400 32 -> 63 : 0 | | 401 64 -> 127 : 0 | | 402 128 -> 255 : 0 | | 403 256 -> 511 : 0 | | 404 512 -> 1023 : 0 | | 405 1024 -> 2047 : 0 | | 406 2048 -> 4095 : 46 |********* | 407 4096 -> 8191 : 198 |****************************************| 408 8192 -> 16383 : 49 |********* | 409 410hardirq = 'timer3' 411 usecs : count distribution 412 0 -> 1 : 0 | | 413 2 -> 3 : 0 | | 414 4 -> 7 : 0 | | 415 8 -> 15 : 0 | | 416 16 -> 31 : 0 | | 417 32 -> 63 : 0 | | 418 64 -> 127 : 0 | | 419 128 -> 255 : 0 | | 420 256 -> 511 : 0 | | 421 512 -> 1023 : 0 | | 422 1024 -> 2047 : 4 | | 423 2048 -> 4095 : 210 |****************************************| 424 4096 -> 8191 : 186 |*********************************** | 425 426hardirq = 'timer2' 427 usecs : count distribution 428 0 -> 1 : 0 | | 429 2 -> 3 : 0 | | 430 4 -> 7 : 0 | | 431 8 -> 15 : 0 | | 432 16 -> 31 : 0 | | 433 32 -> 63 : 0 | | 434 64 -> 127 : 0 | | 435 128 -> 255 : 0 | | 436 256 -> 511 : 0 | | 437 512 -> 1023 : 0 | | 438 1024 -> 2047 : 0 | | 439 2048 -> 4095 : 245 |****************************************| 440 4096 -> 8191 : 227 |************************************* | 441 8192 -> 16383 : 6 | | 442 443hardirq = 'timer1' 444 usecs : count distribution 445 0 -> 1 : 0 | | 446 2 -> 3 : 0 | | 447 4 -> 7 : 0 | | 448 8 -> 15 : 0 | | 449 16 -> 31 : 0 | | 450 32 -> 63 : 0 | | 451 64 -> 127 : 0 | | 452 128 -> 255 : 0 | | 453 256 -> 511 : 0 | | 454 512 -> 1023 : 0 | | 455 1024 -> 2047 : 6 |* | 456 2048 -> 4095 : 112 |************************ | 457 4096 -> 8191 : 181 |****************************************| 458 8192 -> 16383 : 7 |* | 459 460hardirq = 'timer0' 461 usecs : count distribution 462 0 -> 1 : 0 | | 463 2 -> 3 : 0 | | 464 4 -> 7 : 0 | | 465 8 -> 15 : 0 | | 466 16 -> 31 : 0 | | 467 32 -> 63 : 0 | | 468 64 -> 127 : 0 | | 469 128 -> 255 : 0 | | 470 256 -> 511 : 0 | | 471 512 -> 1023 : 0 | | 472 1024 -> 2047 : 0 | | 473 2048 -> 4095 : 0 | | 474 4096 -> 8191 : 887 |****************************************| 475 8192 -> 16383 : 92 |**** | 476 477hardirq = 'blkif' 478 usecs : count distribution 479 0 -> 1 : 0 | | 480 2 -> 3 : 0 | | 481 4 -> 7 : 0 | | 482 8 -> 15 : 0 | | 483 16 -> 31 : 0 | | 484 32 -> 63 : 0 | | 485 64 -> 127 : 0 | | 486 128 -> 255 : 0 | | 487 256 -> 511 : 0 | | 488 512 -> 1023 : 0 | | 489 1024 -> 2047 : 0 | | 490 2048 -> 4095 : 0 | | 491 4096 -> 8191 : 9 |****************************************| 492 8192 -> 16383 : 7 |******************************* | 493 16384 -> 32767 : 2 |******** | 494 495hardirq = 'resched4' 496 usecs : count distribution 497 0 -> 1 : 0 | | 498 2 -> 3 : 0 | | 499 4 -> 7 : 0 | | 500 8 -> 15 : 0 | | 501 16 -> 31 : 0 | | 502 32 -> 63 : 0 | | 503 64 -> 127 : 0 | | 504 128 -> 255 : 0 | | 505 256 -> 511 : 0 | | 506 512 -> 1023 : 0 | | 507 1024 -> 2047 : 104 |****************************************| 508 2048 -> 4095 : 80 |****************************** | 509 510hardirq = 'resched5' 511 usecs : count distribution 512 0 -> 1 : 0 | | 513 2 -> 3 : 0 | | 514 4 -> 7 : 0 | | 515 8 -> 15 : 0 | | 516 16 -> 31 : 0 | | 517 32 -> 63 : 0 | | 518 64 -> 127 : 0 | | 519 128 -> 255 : 0 | | 520 256 -> 511 : 0 | | 521 512 -> 1023 : 27 |***** | 522 1024 -> 2047 : 216 |****************************************| 523 2048 -> 4095 : 27 |***** | 524 4096 -> 8191 : 1 | | 525 526hardirq = 'resched6' 527 usecs : count distribution 528 0 -> 1 : 0 | | 529 2 -> 3 : 0 | | 530 4 -> 7 : 0 | | 531 8 -> 15 : 0 | | 532 16 -> 31 : 0 | | 533 32 -> 63 : 0 | | 534 64 -> 127 : 0 | | 535 128 -> 255 : 0 | | 536 256 -> 511 : 0 | | 537 512 -> 1023 : 480 |******************* | 538 1024 -> 2047 : 1003 |****************************************| 539 2048 -> 4095 : 64 |** | 540 541hardirq = 'resched7' 542 usecs : count distribution 543 0 -> 1 : 0 | | 544 2 -> 3 : 0 | | 545 4 -> 7 : 0 | | 546 8 -> 15 : 0 | | 547 16 -> 31 : 0 | | 548 32 -> 63 : 0 | | 549 64 -> 127 : 0 | | 550 128 -> 255 : 0 | | 551 256 -> 511 : 0 | | 552 512 -> 1023 : 46 |********* | 553 1024 -> 2047 : 190 |****************************************| 554 2048 -> 4095 : 42 |******** | 555 556hardirq = 'resched0' 557 usecs : count distribution 558 0 -> 1 : 0 | | 559 2 -> 3 : 0 | | 560 4 -> 7 : 0 | | 561 8 -> 15 : 0 | | 562 16 -> 31 : 0 | | 563 32 -> 63 : 0 | | 564 64 -> 127 : 0 | | 565 128 -> 255 : 0 | | 566 256 -> 511 : 0 | | 567 512 -> 1023 : 11 |**** | 568 1024 -> 2047 : 100 |****************************************| 569 2048 -> 4095 : 23 |********* | 570 571hardirq = 'resched1' 572 usecs : count distribution 573 0 -> 1 : 0 | | 574 2 -> 3 : 0 | | 575 4 -> 7 : 0 | | 576 8 -> 15 : 0 | | 577 16 -> 31 : 0 | | 578 32 -> 63 : 0 | | 579 64 -> 127 : 0 | | 580 128 -> 255 : 0 | | 581 256 -> 511 : 0 | | 582 512 -> 1023 : 96 |******** | 583 1024 -> 2047 : 462 |****************************************| 584 2048 -> 4095 : 36 |*** | 585 586hardirq = 'resched2' 587 usecs : count distribution 588 0 -> 1 : 0 | | 589 2 -> 3 : 0 | | 590 4 -> 7 : 0 | | 591 8 -> 15 : 0 | | 592 16 -> 31 : 0 | | 593 32 -> 63 : 0 | | 594 64 -> 127 : 0 | | 595 128 -> 255 : 0 | | 596 256 -> 511 : 0 | | 597 512 -> 1023 : 120 |************************** | 598 1024 -> 2047 : 183 |****************************************| 599 2048 -> 4095 : 41 |******** | 600 601hardirq = 'resched3' 602 usecs : count distribution 603 0 -> 1 : 0 | | 604 2 -> 3 : 0 | | 605 4 -> 7 : 0 | | 606 8 -> 15 : 0 | | 607 16 -> 31 : 0 | | 608 32 -> 63 : 0 | | 609 64 -> 127 : 0 | | 610 128 -> 255 : 0 | | 611 256 -> 511 : 0 | | 612 512 -> 1023 : 0 | | 613 1024 -> 2047 : 789 |****************************************| 614 2048 -> 4095 : 39 |* | 615 616 617Sometimes you just want counts of events, and don't need the distribution 618of times. You can use the -C or --count option: 619 620# ./hardirqs.py -C 621Tracing hard irq events... Hit Ctrl-C to end. 622^C 623HARDIRQ TOTAL_count 624blkif 2 625callfuncsingle3 8 626callfuncsingle2 10 627callfuncsingle1 18 628resched7 25 629callfuncsingle6 25 630callfuncsingle5 27 631callfuncsingle0 27 632eth0 34 633resched2 40 634resched1 66 635timer7 70 636resched6 71 637resched0 73 638resched5 79 639resched4 90 640timer6 95 641timer4 100 642timer1 109 643timer2 115 644timer0 117 645timer3 123 646resched3 140 647timer5 288 648 649 650USAGE message: 651 652# ./hardirqs -h 653usage: hardirqs [-h] [-T] [-N] [-C] [-d] [interval] [outputs] 654 655Summarize hard irq event time as histograms 656 657positional arguments: 658 interval output interval, in seconds 659 outputs number of outputs 660 661optional arguments: 662 -h, --help show this help message and exit 663 -T, --timestamp include timestamp on output 664 -N, --nanoseconds output in nanoseconds 665 -C, --count show event counts instead of timing 666 -d, --dist show distributions as histograms 667 668examples: 669 ./hardirqs # sum hard irq event time 670 ./hardirqs -d # show hard irq event time as histograms 671 ./hardirqs 1 10 # print 1 second summaries, 10 times 672 ./hardirqs -NT 1 # 1s summaries, nanoseconds, and timestamps 673