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