1 Demonstrations of hardirqs, the Linux eBPF/bcc version. 2 3 4 This program traces hard interrupts (irqs), and stores timing statistics 5 in-kernel for efficiency. For example: 6 7 # ./hardirqs 8 Tracing hard irq event time... Hit Ctrl-C to end. 9 ^C 10 HARDIRQ TOTAL_usecs 11 callfuncsingle0 2 12 callfuncsingle5 5 13 callfuncsingle6 5 14 callfuncsingle7 21 15 blkif 66 16 timer7 84 17 resched5 94 18 resched0 97 19 resched3 102 20 resched7 111 21 resched6 255 22 timer3 362 23 resched4 367 24 timer5 474 25 timer1 529 26 timer6 679 27 timer2 746 28 timer4 943 29 resched1 1048 30 timer0 1558 31 resched2 1750 32 eth0 11441 33 34 The HARDIRQ column prints the interrupt action name. While tracing, the eth0 35 hard irq action ran for 11441 microseconds (11 milliseconds) in total. 36 37 Many other interrupts are visible in the output: this is an 8 CPU system, and 38 some of these interrupts have a separate action per-CPU (eg, "timer", 39 "resched"). 40 41 42 An interval can be provided, and also optionally a count. Eg, printing output 43 every 1 second, and including timestamps (-T): 44 45 # ./hardirqs -T 1 3 46 Tracing hard irq event time... Hit Ctrl-C to end. 47 48 22:16:14 49 HARDIRQ TOTAL_usecs 50 callfuncsingle0 2 51 callfuncsingle7 5 52 callfuncsingle3 5 53 callfuncsingle2 5 54 callfuncsingle6 6 55 callfuncsingle1 11 56 resched0 32 57 blkif 51 58 resched5 71 59 resched7 71 60 resched4 72 61 resched6 82 62 timer7 172 63 resched1 187 64 resched2 236 65 timer3 252 66 resched3 282 67 timer1 320 68 timer2 374 69 timer6 396 70 timer5 427 71 timer4 470 72 timer0 1430 73 eth0 7498 74 75 22:16:15 76 HARDIRQ TOTAL_usecs 77 callfuncsingle7 6 78 callfuncsingle5 11 79 callfuncsingle4 13 80 timer2 17 81 callfuncsingle6 18 82 resched0 21 83 blkif 33 84 resched3 40 85 resched5 60 86 resched4 69 87 resched6 70 88 resched7 74 89 timer7 86 90 resched2 91 91 timer3 134 92 resched1 293 93 timer5 354 94 timer1 433 95 timer6 497 96 timer4 1112 97 timer0 1768 98 eth0 6972 99 100 22:16:16 101 HARDIRQ TOTAL_usecs 102 callfuncsingle7 5 103 callfuncsingle3 5 104 callfuncsingle2 6 105 timer3 10 106 resched0 18 107 callfuncsingle4 22 108 resched5 27 109 resched6 44 110 blkif 45 111 resched7 65 112 resched4 69 113 timer4 77 114 resched2 97 115 timer7 98 116 resched3 103 117 timer2 169 118 resched1 226 119 timer5 525 120 timer1 691 121 timer6 697 122 timer0 1415 123 eth0 7152 124 125 This can be useful for quantifying where CPU cycles are spent among the hard 126 interrupts (summarized as the %irq column from mpstat(1)). The output above 127 shows that most time was spent processing for eth0 (network interface), which 128 was around 7 milliseconds per second (total across all CPUs). 129 130 Note that the time spent among the "timer" interrupts was low, and usually less 131 than one microsecond per second. Here's the hardirq per-second output when the 132 perf tool is performing a 999 Hertz CPU profile ("perf record -F 999 -a ..."): 133 134 22:13:59 135 HARDIRQ TOTAL_usecs 136 callfuncsingle7 5 137 callfuncsingle5 5 138 callfuncsingle3 6 139 callfuncsingle4 7 140 callfuncsingle6 19 141 blkif 66 142 resched0 66 143 resched2 82 144 resched7 87 145 resched3 96 146 resched4 118 147 resched5 120 148 resched6 130 149 resched1 230 150 timer3 946 151 timer1 1981 152 timer7 2618 153 timer5 3063 154 timer6 3141 155 timer4 3511 156 timer2 3554 157 timer0 5044 158 eth0 16015 159 160 This sheds some light into the CPU overhead of the perf profiler, which cost 161 around 3 milliseconds per second. Note that I'm usually profiling at a much 162 lower rate, 99 Hertz, which looks like this: 163 164 22:22:12 165 HARDIRQ TOTAL_usecs 166 callfuncsingle3 5 167 callfuncsingle6 5 168 callfuncsingle5 22 169 blkif 46 170 resched6 47 171 resched5 57 172 resched4 66 173 resched7 78 174 resched2 97 175 resched0 214 176 timer2 326 177 timer0 498 178 timer5 536 179 timer6 576 180 timer1 600 181 timer4 982 182 resched1 1315 183 timer7 1364 184 timer3 1825 185 resched3 5708 186 eth0 9743 187 188 Much lower (and remember to compare this to the baseline). Note that perf has 189 other overheads (non-irq CPU cycles, file system storage). 190 191 192 The distribution of interrupt run time can be printed as a histogram with the -d 193 option. Eg: 194 195 # ./hardirqs -d 196 Tracing hard irq event time... Hit Ctrl-C to end. 197 ^C 198 199 hardirq = '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 216 hardirq = '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 231 hardirq = '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 247 hardirq = '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 263 hardirq = '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 279 hardirq = '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 295 hardirq = '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 311 hardirq = '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 327 hardirq = '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 343 hardirq = '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 359 hardirq = '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 376 hardirq = '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 393 hardirq = '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 410 hardirq = '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 426 hardirq = '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 443 hardirq = '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 460 hardirq = '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 477 hardirq = '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 495 hardirq = '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 510 hardirq = '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 526 hardirq = '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 541 hardirq = '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 556 hardirq = '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 571 hardirq = '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 586 hardirq = '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 601 hardirq = '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 617 Sometimes you just want counts of events, and don't need the distribution 618 of times. You can use the -C or --count option: 619 620 # ./hardirqs.py -C 621 Tracing hard irq events... Hit Ctrl-C to end. 622 ^C 623 HARDIRQ TOTAL_count 624 blkif 2 625 callfuncsingle3 8 626 callfuncsingle2 10 627 callfuncsingle1 18 628 resched7 25 629 callfuncsingle6 25 630 callfuncsingle5 27 631 callfuncsingle0 27 632 eth0 34 633 resched2 40 634 resched1 66 635 timer7 70 636 resched6 71 637 resched0 73 638 resched5 79 639 resched4 90 640 timer6 95 641 timer4 100 642 timer1 109 643 timer2 115 644 timer0 117 645 timer3 123 646 resched3 140 647 timer5 288 648 649 650 USAGE message: 651 652 # ./hardirqs -h 653 usage: hardirqs [-h] [-T] [-N] [-C] [-d] [interval] [outputs] 654 655 Summarize hard irq event time as histograms 656 657 positional arguments: 658 interval output interval, in seconds 659 outputs number of outputs 660 661 optional 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 668 examples: 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
