Gitiles
Code Review Sign In
gerrit-public.fairphone.software / platform / external / bcc / refs/heads/int/11/fp3 / . / tools / hardirqs_example.txt
blob: d7dcc9cb8d09f89d255bd0a7587656bbd12612d9 [file] [log] [blame]
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]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
Alexei Starovoitovbdf07732016-01-14 10:09:20 -0800[diff] [blame]7# ./hardirqs
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]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
Brendan Greggc32b8452017-11-26 23:38:32 -0800[diff] [blame]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
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]650USAGE message:
651
652# ./hardirqs -h
Brendan Greggc32b8452017-11-26 23:38:32 -0800[diff] [blame]653usage: hardirqs [-h] [-T] [-N] [-C] [-d] [interval] [outputs]
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]654
655Summarize hard irq event time as histograms
656
657positional arguments:
658 interval output interval, in seconds
Brendan Greggc32b8452017-11-26 23:38:32 -0800[diff] [blame]659 outputs number of outputs
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]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
Brendan Greggc32b8452017-11-26 23:38:32 -0800[diff] [blame]665 -C, --count show event counts instead of timing
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]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