| Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 1 | Demonstrations of stacksnoop, the Linux eBPF/bcc version. |
| 2 | |
| 3 | |
| 4 | This program traces the given kernel function and prints the kernel stack trace |
| 5 | for every call. This tool is useful for studying low frequency kernel functions, |
| 6 | to see how they were invoked. For exmaple, tracing the ext4_sync_fs() call: |
| 7 | |
| 8 | # ./stacksnoop ext4_sync_fs |
| 9 | TIME(s) STACK |
| 10 | 42005194.132250004 |
| 11 | 42005194.132253997 ip: ffffffff81280461 ext4_sync_fs |
| 12 | 42005194.132256001 r0: ffffffff811ed7f9 iterate_supers |
| 13 | 42005194.132257000 r1: ffffffff8121ba25 sys_sync |
| 14 | 42005194.132257000 r2: ffffffff81775cb6 entry_SYSCALL_64_fastpath |
| 15 | 42005194.132275000 |
| 16 | 42005194.132275999 ip: ffffffff81280461 ext4_sync_fs |
| 17 | 42005194.132275999 r0: ffffffff811ed7f9 iterate_supers |
| 18 | 42005194.132276997 r1: ffffffff8121ba35 sys_sync |
| 19 | 42005194.132276997 r2: ffffffff81775cb6 entry_SYSCALL_64_fastpath |
| 20 | |
| 21 | This shows that ext4_sync_fs() was called by iterate_supers(), which was called |
| 22 | by sys_sync(), and so on. (It tells me that this was a syscall invoked sync, |
| 23 | so an application has requested it.) |
| 24 | |
| 25 | The "ip" refers to the instruction pointer, and the "r#" refers to the return |
| 26 | address for each stack frame. |
| 27 | |
| 28 | For high frequency functions, see stackcount, which summarizes in-kernel for |
| 29 | efficiency. If you don't know if your function is low or high frequency, try |
| 30 | funccount. |
| 31 | |
| 32 | |
| 33 | The -v option includes more fields, including the on-CPU process (COMM and PID): |
| 34 | |
| 35 | # ./stacksnoop -v ext4_sync_fs |
| 36 | TIME(s) COMM PID CPU STACK |
| 37 | 42005557.056332998 sync 22352 1 |
| 38 | 42005557.056336999 sync 22352 1 ip: ffffffff81280461 ext4_sync_fs |
| 39 | 42005557.056339003 sync 22352 1 r0: ffffffff811ed7f9 iterate_supers |
| 40 | 42005557.056340002 sync 22352 1 r1: ffffffff8121ba25 sys_sync |
| 41 | 42005557.056340002 sync 22352 1 r2: ffffffff81775cb6 entry_SYSCALL_64_fastpath |
| 42 | 42005557.056358002 sync 22352 1 |
| 43 | 42005557.056358002 sync 22352 1 ip: ffffffff81280461 ext4_sync_fs |
| 44 | 42005557.056359001 sync 22352 1 r0: ffffffff811ed7f9 iterate_supers |
| 45 | 42005557.056359999 sync 22352 1 r1: ffffffff8121ba35 sys_sync |
| 46 | 42005557.056359999 sync 22352 1 r2: ffffffff81775cb6 entry_SYSCALL_64_fastpath |
| 47 | |
| 48 | This identifies the application issuing the sync syscall: the sync(1) command |
| 49 | (COMM column). |
| 50 | |
| 51 | |
| 52 | Here's another example, showing the path to second_overflow() and on-CPU |
| 53 | process: |
| 54 | |
| 55 | # ./stacksnoop -v second_overflow |
| 56 | TIME(s) COMM PID CPU STACK |
| 57 | 42005696.529449999 <idle> 0 0 |
| 58 | 42005696.529457003 <idle> 0 0 ip: ffffffff810e5701 second_overflow |
| 59 | 42005696.529459000 <idle> 0 0 r0: ffffffff810ecb1b tick_do_update_jiffies64 |
| 60 | 42005696.529459998 <idle> 0 0 r1: ffffffff810ed6e0 tick_irq_enter |
| 61 | 42005696.529459998 <idle> 0 0 r2: ffffffff8107a195 irq_enter |
| 62 | 42005696.529460996 <idle> 0 0 r3: ffffffff8146bb6f xen_evtchn_do_upcall |
| 63 | 42005696.529460996 <idle> 0 0 r4: ffffffff81777a2e xen_do_hypervisor_callback |
| 64 | 42005697.616295002 <idle> 0 0 |
| 65 | 42005697.616301000 <idle> 0 0 ip: ffffffff810e5701 second_overflow |
| 66 | 42005697.616302997 <idle> 0 0 r0: ffffffff810ecb1b tick_do_update_jiffies64 |
| 67 | 42005697.616304003 <idle> 0 0 r1: ffffffff810ed6e0 tick_irq_enter |
| 68 | 42005697.616304003 <idle> 0 0 r2: ffffffff8107a195 irq_enter |
| 69 | 42005697.616305001 <idle> 0 0 r3: ffffffff8146bb6f xen_evtchn_do_upcall |
| 70 | 42005697.616305001 <idle> 0 0 r4: ffffffff81777a2e xen_do_hypervisor_callback |
| 71 | 42005698.556240998 <idle> 0 1 |
| 72 | 42005698.556247003 <idle> 0 1 ip: ffffffff810e5701 second_overflow |
| 73 | 42005698.556249000 <idle> 0 1 r0: ffffffff810ecb1b tick_do_update_jiffies64 |
| 74 | 42005698.556249000 <idle> 0 1 r1: ffffffff810ed6e0 tick_irq_enter |
| 75 | 42005698.556249999 <idle> 0 1 r2: ffffffff8107a195 irq_enter |
| 76 | 42005698.556249999 <idle> 0 1 r3: ffffffff8146bb6f xen_evtchn_do_upcall |
| 77 | 42005698.556250997 <idle> 0 1 r4: ffffffff81777a2e xen_do_hypervisor_callback |
| 78 | [...] |
| 79 | |
| 80 | This fires every second (see TIME(s)), and is from tick_do_update_jiffies64(). |
| 81 | |
| 82 | |
| 83 | USAGE message: |
| 84 | |
| 85 | # ./stacksnoop -h |
| 86 | usage: stacksnoop [-h] [-p PID] [-s] [-v] function |
| 87 | |
| 88 | Trace and print kernel stack traces for a kernel function |
| 89 | |
| 90 | positional arguments: |
| 91 | function kernel function name |
| 92 | |
| 93 | optional arguments: |
| 94 | -h, --help show this help message and exit |
| 95 | -p PID, --pid PID trace this PID only |
| 96 | -s, --offset show address offsets |
| 97 | -v, --verbose print more fields |
| 98 | |
| 99 | examples: |
| 100 | ./stacksnoop ext4_sync_fs # print kernel stack traces for ext4_sync_fs |
| 101 | ./stacksnoop -s ext4_sync_fs # ... also show symbol offsets |
| 102 | ./stacksnoop -v ext4_sync_fs # ... show extra columns |
| 103 | ./stacksnoop -p 185 ext4_sync_fs # ... only when PID 185 is on-CPU |