diff options
| author | Scott Rifenbark <scott.m.rifenbark@intel.com> | 2013-01-16 15:49:14 -0800 |
|---|---|---|
| committer | Richard Purdie <richard.purdie@linuxfoundation.org> | 2013-01-27 13:56:02 +0000 |
| commit | 82928e228bc438f7693097786e00cb26eb914758 (patch) | |
| tree | 4df15bcc735c7af2061dc8fff776fcdad3888044 /documentation/profile-manual | |
| parent | 41fe45977ce4bcecbd963176aea0637a86e3c224 (diff) | |
| download | ast2050-yocto-poky-82928e228bc438f7693097786e00cb26eb914758.zip ast2050-yocto-poky-82928e228bc438f7693097786e00cb26eb914758.tar.gz | |
profile-manual: Added ftrace section to the manual.
No re-writing, no clean up what-so-ever. It is simply in the
DocBook form.
(From yocto-docs rev: 3d2c17c076b67c3e2ab094d0562038e422b63d44)
Signed-off-by: Scott Rifenbark <scott.m.rifenbark@intel.com>
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
Diffstat (limited to 'documentation/profile-manual')
| -rw-r--r-- | documentation/profile-manual/profile-manual-usage.xml | 664 |
1 files changed, 664 insertions, 0 deletions
diff --git a/documentation/profile-manual/profile-manual-usage.xml b/documentation/profile-manual/profile-manual-usage.xml index 12323ed..a35a112 100644 --- a/documentation/profile-manual/profile-manual-usage.xml +++ b/documentation/profile-manual/profile-manual-usage.xml @@ -1340,6 +1340,670 @@ </para> </section> </section> + +<section id='profile-manual-ftrace'> + <title>ftrace</title> + + <para> + 'ftrace' literally refers to the 'ftrace function tracer' but in + reality this encompasses a number of related tracers along with + the infrastructure that they all make use of. + </para> + + <section id='ftrace-setup'> + <title>Setup</title> + + <para> + For this section, we'll assume you've already performed the basic + setup outlined in the General Setup section. + </para> + + <para> + ftrace, trace-cmd, and kernelshark run on the target system, + and are ready to go out-of-the-box - no additional setup is + necessary. For the rest of this section we assume you've ssh'ed + to the host and will be running ftrace on the target. kernelshark + is a GUI application and if you use the '-X' option to ssh you + can have the kernelshark GUI run on the target but display + remotely on the host if you want. + </para> + </section> + + <section id='basic-ftrace-usage'> + <title>Basic ftrace usage</title> + + <para> + 'ftrace' essentially refers to everything included in + the /tracing directory of the mounted debugfs filesystem + (Yocto follows the standard convention and mounts it + at /sys/kernel/debug). Here's a listing of all the files + found in /sys/kernel/debug/tracing on a Yocto system.: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing# ls + README kprobe_events trace + available_events kprobe_profile trace_clock + available_filter_functions options trace_marker + available_tracers per_cpu trace_options + buffer_size_kb printk_formats trace_pipe + buffer_total_size_kb saved_cmdlines tracing_cpumask + current_tracer set_event tracing_enabled + dyn_ftrace_total_info set_ftrace_filter tracing_on + enabled_functions set_ftrace_notrace tracing_thresh + events set_ftrace_pid + free_buffer set_graph_function + </literallayout> + The files listed above are used for various purposes - + some relate directly to the tracers themselves, others are + used to set tracing options, and yet others actually contain + the tracing output when a tracer is in effect. Some of the + functions can be guessed from their names, others need + explanation; in any case, we'll cover some of the files we + see here below but for an explanation of the others, please + see the ftrace documentation. + </para> + + <para> + We'll start by looking at some of the available built-in + tracers. + </para> + + <para> + cat'ing the 'available_tracers' file lists the set of + available tracers: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing# cat available_tracers + blk function_graph function nop + </literallayout> + The 'current_tracer' file contains the tracer currently in + effect: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer + nop + </literallayout> + The above listing of current_tracer shows that + the 'nop' tracer is in effect, which is just another + way of saying that there's actually no tracer + currently in effect. + </para> + + <para> + echo'ing one of the available_tracers into current_tracer + makes the specified tracer the current tracer: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing# echo function > current_tracer + root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer + function + </literallayout> + The above sets the current tracer to be the + 'function tracer'. This tracer traces every function + call in the kernel and makes it available as the + contents of the 'trace' file. Reading the 'trace' file + lists the currently buffered function calls that have been + traced by the function tracer: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing# cat trace | less + + # tracer: function + # + # entries-in-buffer/entries-written: 310629/766471 #P:8 + # + # _-----=> irqs-off + # / _----=> need-resched + # | / _---=> hardirq/softirq + # || / _--=> preempt-depth + # ||| / delay + # TASK-PID CPU# |||| TIMESTAMP FUNCTION + # | | | |||| | | + <idle>-0 [004] d..1 470.867169: ktime_get_real <-intel_idle + <idle>-0 [004] d..1 470.867170: getnstimeofday <-ktime_get_real + <idle>-0 [004] d..1 470.867171: ns_to_timeval <-intel_idle + <idle>-0 [004] d..1 470.867171: ns_to_timespec <-ns_to_timeval + <idle>-0 [004] d..1 470.867172: smp_apic_timer_interrupt <-apic_timer_interrupt + <idle>-0 [004] d..1 470.867172: native_apic_mem_write <-smp_apic_timer_interrupt + <idle>-0 [004] d..1 470.867172: irq_enter <-smp_apic_timer_interrupt + <idle>-0 [004] d..1 470.867172: rcu_irq_enter <-irq_enter + <idle>-0 [004] d..1 470.867173: rcu_idle_exit_common.isra.33 <-rcu_irq_enter + <idle>-0 [004] d..1 470.867173: local_bh_disable <-irq_enter + <idle>-0 [004] d..1 470.867173: add_preempt_count <-local_bh_disable + <idle>-0 [004] d.s1 470.867174: tick_check_idle <-irq_enter + <idle>-0 [004] d.s1 470.867174: tick_check_oneshot_broadcast <-tick_check_idle + <idle>-0 [004] d.s1 470.867174: ktime_get <-tick_check_idle + <idle>-0 [004] d.s1 470.867174: tick_nohz_stop_idle <-tick_check_idle + <idle>-0 [004] d.s1 470.867175: update_ts_time_stats <-tick_nohz_stop_idle + <idle>-0 [004] d.s1 470.867175: nr_iowait_cpu <-update_ts_time_stats + <idle>-0 [004] d.s1 470.867175: tick_do_update_jiffies64 <-tick_check_idle + <idle>-0 [004] d.s1 470.867175: _raw_spin_lock <-tick_do_update_jiffies64 + <idle>-0 [004] d.s1 470.867176: add_preempt_count <-_raw_spin_lock + <idle>-0 [004] d.s2 470.867176: do_timer <-tick_do_update_jiffies64 + <idle>-0 [004] d.s2 470.867176: _raw_spin_lock <-do_timer + <idle>-0 [004] d.s2 470.867176: add_preempt_count <-_raw_spin_lock + <idle>-0 [004] d.s3 470.867177: ntp_tick_length <-do_timer + <idle>-0 [004] d.s3 470.867177: _raw_spin_lock_irqsave <-ntp_tick_length + . + . + . + </literallayout> + Each line in the trace above shows what was happening in + the kernel on a given cpu, to the level of detail of + function calls. Each entry shows the function called, + followed by its caller (after the arrow). + </para> + + <para> + The function tracer gives you an extremely detailed idea + of what the kernel was doing at the point in time the trace + was taken, and is a great way to learn about how the kernel + code works in a dynamic sense. + </para> + + <note> + Tying It Together: The ftrace function tracer is also + available from within perf, as the ftrace:function tracepoint. + </note> + + <para> + It is a little more difficult to follow the call chains than + it needs to be - luckily there's a variant of the function + tracer that displays the callchains explicitly, called the + 'function_graph' tracer: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing# echo function_graph > current_tracer + root@sugarbay:/sys/kernel/debug/tracing# cat trace | less + + tracer: function_graph + + CPU DURATION FUNCTION CALLS + | | | | | | | + 7) 0.046 us | pick_next_task_fair(); + 7) 0.043 us | pick_next_task_stop(); + 7) 0.042 us | pick_next_task_rt(); + 7) 0.032 us | pick_next_task_fair(); + 7) 0.030 us | pick_next_task_idle(); + 7) | _raw_spin_unlock_irq() { + 7) 0.033 us | sub_preempt_count(); + 7) 0.258 us | } + 7) 0.032 us | sub_preempt_count(); + 7) + 13.341 us | } /* __schedule */ + 7) 0.095 us | } /* sub_preempt_count */ + 7) | schedule() { + 7) | __schedule() { + 7) 0.060 us | add_preempt_count(); + 7) 0.044 us | rcu_note_context_switch(); + 7) | _raw_spin_lock_irq() { + 7) 0.033 us | add_preempt_count(); + 7) 0.247 us | } + 7) | idle_balance() { + 7) | _raw_spin_unlock() { + 7) 0.031 us | sub_preempt_count(); + 7) 0.246 us | } + 7) | update_shares() { + 7) 0.030 us | __rcu_read_lock(); + 7) 0.029 us | __rcu_read_unlock(); + 7) 0.484 us | } + 7) 0.030 us | __rcu_read_lock(); + 7) | load_balance() { + 7) | find_busiest_group() { + 7) 0.031 us | idle_cpu(); + 7) 0.029 us | idle_cpu(); + 7) 0.035 us | idle_cpu(); + 7) 0.906 us | } + 7) 1.141 us | } + 7) 0.022 us | msecs_to_jiffies(); + 7) | load_balance() { + 7) | find_busiest_group() { + 7) 0.031 us | idle_cpu(); + . + . + . + 4) 0.062 us | msecs_to_jiffies(); + 4) 0.062 us | __rcu_read_unlock(); + 4) | _raw_spin_lock() { + 4) 0.073 us | add_preempt_count(); + 4) 0.562 us | } + 4) + 17.452 us | } + 4) 0.108 us | put_prev_task_fair(); + 4) 0.102 us | pick_next_task_fair(); + 4) 0.084 us | pick_next_task_stop(); + 4) 0.075 us | pick_next_task_rt(); + 4) 0.062 us | pick_next_task_fair(); + 4) 0.066 us | pick_next_task_idle(); + ------------------------------------------ + 4) kworker-74 => <idle>-0 + ------------------------------------------ + + 4) | finish_task_switch() { + 4) | _raw_spin_unlock_irq() { + 4) 0.100 us | sub_preempt_count(); + 4) 0.582 us | } + 4) 1.105 us | } + 4) 0.088 us | sub_preempt_count(); + 4) ! 100.066 us | } + . + . + . + 3) | sys_ioctl() { + 3) 0.083 us | fget_light(); + 3) | security_file_ioctl() { + 3) 0.066 us | cap_file_ioctl(); + 3) 0.562 us | } + 3) | do_vfs_ioctl() { + 3) | drm_ioctl() { + 3) 0.075 us | drm_ut_debug_printk(); + 3) | i915_gem_pwrite_ioctl() { + 3) | i915_mutex_lock_interruptible() { + 3) 0.070 us | mutex_lock_interruptible(); + 3) 0.570 us | } + 3) | drm_gem_object_lookup() { + 3) | _raw_spin_lock() { + 3) 0.080 us | add_preempt_count(); + 3) 0.620 us | } + 3) | _raw_spin_unlock() { + 3) 0.085 us | sub_preempt_count(); + 3) 0.562 us | } + 3) 2.149 us | } + 3) 0.133 us | i915_gem_object_pin(); + 3) | i915_gem_object_set_to_gtt_domain() { + 3) 0.065 us | i915_gem_object_flush_gpu_write_domain(); + 3) 0.065 us | i915_gem_object_wait_rendering(); + 3) 0.062 us | i915_gem_object_flush_cpu_write_domain(); + 3) 1.612 us | } + 3) | i915_gem_object_put_fence() { + 3) 0.097 us | i915_gem_object_flush_fence.constprop.36(); + 3) 0.645 us | } + 3) 0.070 us | add_preempt_count(); + 3) 0.070 us | sub_preempt_count(); + 3) 0.073 us | i915_gem_object_unpin(); + 3) 0.068 us | mutex_unlock(); + 3) 9.924 us | } + 3) + 11.236 us | } + 3) + 11.770 us | } + 3) + 13.784 us | } + 3) | sys_ioctl() { + </literallayout> + As you can see, the function_graph display is much easier to + follow. Also note that in addition to the function calls and + associated braces, other events such as scheduler events + are displayed in context. In fact, you can freely include + any tracepoint available in the trace events subsystem described + in the next section by simply enabling those events, and they'll + appear in context in the function graph display. Quite a + powerful tool for understanding kernel dynamics. + </para> + + <para> + Also notice that there are various annotations on the left + hand side of the display. For example if the total time it + took for a given function to execute is above a certain + threshold, and exclamation point or plus sign appears on the + left hand side. Please see the ftrace documentation for + details on all these fields. + </para> + </section> + + <section id='the-trace-events-subsystem'> + <title>The 'trace events' Subsystem</title> + + <para> + One especially important directory contained within + the /sys/kernel/debug/tracing directory is the 'events' + subdirectory, which contains representations of every + tracepoint in the system. Listing out the contents of + the 'events' subdirectory, we see mainly another set of + subdirectories: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing# cd events + root@sugarbay:/sys/kernel/debug/tracing/events# ls -al + drwxr-xr-x 38 root root 0 Nov 14 23:19 . + drwxr-xr-x 5 root root 0 Nov 14 23:19 .. + drwxr-xr-x 19 root root 0 Nov 14 23:19 block + drwxr-xr-x 32 root root 0 Nov 14 23:19 btrfs + drwxr-xr-x 5 root root 0 Nov 14 23:19 drm + -rw-r--r-- 1 root root 0 Nov 14 23:19 enable + drwxr-xr-x 40 root root 0 Nov 14 23:19 ext3 + drwxr-xr-x 79 root root 0 Nov 14 23:19 ext4 + drwxr-xr-x 14 root root 0 Nov 14 23:19 ftrace + drwxr-xr-x 8 root root 0 Nov 14 23:19 hda + -r--r--r-- 1 root root 0 Nov 14 23:19 header_event + -r--r--r-- 1 root root 0 Nov 14 23:19 header_page + drwxr-xr-x 25 root root 0 Nov 14 23:19 i915 + drwxr-xr-x 7 root root 0 Nov 14 23:19 irq + drwxr-xr-x 12 root root 0 Nov 14 23:19 jbd + drwxr-xr-x 14 root root 0 Nov 14 23:19 jbd2 + drwxr-xr-x 14 root root 0 Nov 14 23:19 kmem + drwxr-xr-x 7 root root 0 Nov 14 23:19 module + drwxr-xr-x 3 root root 0 Nov 14 23:19 napi + drwxr-xr-x 6 root root 0 Nov 14 23:19 net + drwxr-xr-x 3 root root 0 Nov 14 23:19 oom + drwxr-xr-x 12 root root 0 Nov 14 23:19 power + drwxr-xr-x 3 root root 0 Nov 14 23:19 printk + drwxr-xr-x 8 root root 0 Nov 14 23:19 random + drwxr-xr-x 4 root root 0 Nov 14 23:19 raw_syscalls + drwxr-xr-x 3 root root 0 Nov 14 23:19 rcu + drwxr-xr-x 6 root root 0 Nov 14 23:19 rpm + drwxr-xr-x 20 root root 0 Nov 14 23:19 sched + drwxr-xr-x 7 root root 0 Nov 14 23:19 scsi + drwxr-xr-x 4 root root 0 Nov 14 23:19 signal + drwxr-xr-x 5 root root 0 Nov 14 23:19 skb + drwxr-xr-x 4 root root 0 Nov 14 23:19 sock + drwxr-xr-x 10 root root 0 Nov 14 23:19 sunrpc + drwxr-xr-x 538 root root 0 Nov 14 23:19 syscalls + drwxr-xr-x 4 root root 0 Nov 14 23:19 task + drwxr-xr-x 14 root root 0 Nov 14 23:19 timer + drwxr-xr-x 3 root root 0 Nov 14 23:19 udp + drwxr-xr-x 21 root root 0 Nov 14 23:19 vmscan + drwxr-xr-x 3 root root 0 Nov 14 23:19 vsyscall + drwxr-xr-x 6 root root 0 Nov 14 23:19 workqueue + drwxr-xr-x 26 root root 0 Nov 14 23:19 writeback + </literallayout> + Each one of these subdirectories corresponds to a + 'subsystem' and contains yet again more subdirectories, + each one of those finally corresponding to a tracepoint. + For example, here are the contents of the 'kmem' subsystem: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing/events# cd kmem + root@sugarbay:/sys/kernel/debug/tracing/events/kmem# ls -al + drwxr-xr-x 14 root root 0 Nov 14 23:19 . + drwxr-xr-x 38 root root 0 Nov 14 23:19 .. + -rw-r--r-- 1 root root 0 Nov 14 23:19 enable + -rw-r--r-- 1 root root 0 Nov 14 23:19 filter + drwxr-xr-x 2 root root 0 Nov 14 23:19 kfree + drwxr-xr-x 2 root root 0 Nov 14 23:19 kmalloc + drwxr-xr-x 2 root root 0 Nov 14 23:19 kmalloc_node + drwxr-xr-x 2 root root 0 Nov 14 23:19 kmem_cache_alloc + drwxr-xr-x 2 root root 0 Nov 14 23:19 kmem_cache_alloc_node + drwxr-xr-x 2 root root 0 Nov 14 23:19 kmem_cache_free + drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_alloc + drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_alloc_extfrag + drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_alloc_zone_locked + drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_free + drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_free_batched + drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_pcpu_drain + </literallayout> + Let's see what's inside the subdirectory for a specific + tracepoint, in this case the one for kmalloc: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing/events/kmem# cd kmalloc + root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# ls -al + drwxr-xr-x 2 root root 0 Nov 14 23:19 . + drwxr-xr-x 14 root root 0 Nov 14 23:19 .. + -rw-r--r-- 1 root root 0 Nov 14 23:19 enable + -rw-r--r-- 1 root root 0 Nov 14 23:19 filter + -r--r--r-- 1 root root 0 Nov 14 23:19 format + -r--r--r-- 1 root root 0 Nov 14 23:19 id + </literallayout> + The 'format' file for the tracepoint describes the event + in memory, which is used by the various tracing tools + that now make use of these tracepoint to parse the event + and make sense of it, along with a 'print fmt' field that + allows tools like ftrace to display the event as text. + Here's what the format of the kmalloc event looks like: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# cat format + name: kmalloc + ID: 313 + format: + field:unsigned short common_type; offset:0; size:2; signed:0; + field:unsigned char common_flags; offset:2; size:1; signed:0; + field:unsigned char common_preempt_count; offset:3; size:1; signed:0; + field:int common_pid; offset:4; size:4; signed:1; + field:int common_padding; offset:8; size:4; signed:1; + + field:unsigned long call_site; offset:16; size:8; signed:0; + field:const void * ptr; offset:24; size:8; signed:0; + field:size_t bytes_req; offset:32; size:8; signed:0; + field:size_t bytes_alloc; offset:40; size:8; signed:0; + field:gfp_t gfp_flags; offset:48; size:4; signed:0; + + print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", REC->call_site, REC->ptr, REC->bytes_req, REC->bytes_alloc, + (REC->gfp_flags) ? __print_flags(REC->gfp_flags, "|", {(unsigned long)(((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( + gfp_t)0x20000u) | (( gfp_t)0x02u) | (( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) | (( gfp_t)0x1000u) | (( gfp_t)0x200u) | (( + gfp_t)0x400000u)), "GFP_TRANSHUGE"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u) | (( + gfp_t)0x02u) | (( gfp_t)0x08u)), "GFP_HIGHUSER_MOVABLE"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( + gfp_t)0x20000u) | (( gfp_t)0x02u)), "GFP_HIGHUSER"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( + gfp_t)0x20000u)), "GFP_USER"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x80000u)), GFP_TEMPORARY"}, + {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u)), "GFP_KERNEL"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u)), + "GFP_NOFS"}, {(unsigned long)((( gfp_t)0x20u)), "GFP_ATOMIC"}, {(unsigned long)((( gfp_t)0x10u)), "GFP_NOIO"}, {(unsigned long)(( + gfp_t)0x20u), "GFP_HIGH"}, {(unsigned long)(( gfp_t)0x10u), "GFP_WAIT"}, {(unsigned long)(( gfp_t)0x40u), "GFP_IO"}, {(unsigned long)(( + gfp_t)0x100u), "GFP_COLD"}, {(unsigned long)(( gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned long)(( gfp_t)0x400u), "GFP_REPEAT"}, {(unsigned + long)(( gfp_t)0x800u), "GFP_NOFAIL"}, {(unsigned long)(( gfp_t)0x1000u), "GFP_NORETRY"}, {(unsigned long)(( gfp_t)0x4000u), "GFP_COMP"}, + {(unsigned long)(( gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)(( gfp_t)0x10000u), "GFP_NOMEMALLOC"}, {(unsigned long)(( gfp_t)0x20000u), + "GFP_HARDWALL"}, {(unsigned long)(( gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)(( gfp_t)0x80000u), "GFP_RECLAIMABLE"}, {(unsigned + long)(( gfp_t)0x08u), "GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0), "GFP_NOTRACK"}, {(unsigned long)(( gfp_t)0x400000u), "GFP_NO_KSWAPD"}, + {(unsigned long)(( gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT" + </literallayout> + The 'enable' file in the tracepoint directory is what allows + the user (or tools such as trace-cmd) to actually turn the + tracepoint on and off. When enabled, the corresponding + tracepoint will start appearing in the ftrace 'trace' + file described previously. For example, this turns on the + kmalloc tracepoint: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 1 > enable + </literallayout> + At the moment, we're not interested in the function tracer or + some other tracer that might be in effect, so we first turn + it off, but if we do that, we still need to turn tracing on in + order to see the events in the output buffer: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing# echo nop > current_tracer + root@sugarbay:/sys/kernel/debug/tracing# echo 1 > tracing_on + </literallayout> + Now, if we look at the the 'trace' file, we see nothing + but the kmalloc events we just turned on: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing# cat trace | less + # tracer: nop + # + # entries-in-buffer/entries-written: 1897/1897 #P:8 + # + # _-----=> irqs-off + # / _----=> need-resched + # | / _---=> hardirq/softirq + # || / _--=> preempt-depth + # ||| / delay + # TASK-PID CPU# |||| TIMESTAMP FUNCTION + # | | | |||| | | + dropbear-1465 [000] ...1 18154.620753: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL + <idle>-0 [000] ..s3 18154.621640: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + <idle>-0 [000] ..s3 18154.621656: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + matchbox-termin-1361 [001] ...1 18154.755472: kmalloc: call_site=ffffffff81614050 ptr=ffff88006d5f0e00 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_KERNEL|GFP_REPEAT + Xorg-1264 [002] ...1 18154.755581: kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRY + Xorg-1264 [002] ...1 18154.755583: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO + Xorg-1264 [002] ...1 18154.755589: kmalloc: call_site=ffffffff81419edb ptr=ffff8800721a2f00 bytes_req=64 bytes_alloc=64 gfp_flags=GFP_KERNEL|GFP_ZERO + matchbox-termin-1361 [001] ...1 18155.354594: kmalloc: call_site=ffffffff81614050 ptr=ffff88006db35400 bytes_req=576 bytes_alloc=1024 gfp_flags=GFP_KERNEL|GFP_REPEAT + Xorg-1264 [002] ...1 18155.354703: kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRY + Xorg-1264 [002] ...1 18155.354705: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO + Xorg-1264 [002] ...1 18155.354711: kmalloc: call_site=ffffffff81419edb ptr=ffff8800721a2f00 bytes_req=64 bytes_alloc=64 gfp_flags=GFP_KERNEL|GFP_ZERO + <idle>-0 [000] ..s3 18155.673319: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + dropbear-1465 [000] ...1 18155.673525: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL + <idle>-0 [000] ..s3 18155.674821: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + <idle>-0 [000] ..s3 18155.793014: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + dropbear-1465 [000] ...1 18155.793219: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL + <idle>-0 [000] ..s3 18155.794147: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + <idle>-0 [000] ..s3 18155.936705: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + dropbear-1465 [000] ...1 18155.936910: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL + <idle>-0 [000] ..s3 18155.937869: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + matchbox-termin-1361 [001] ...1 18155.953667: kmalloc: call_site=ffffffff81614050 ptr=ffff88006d5f2000 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_KERNEL|GFP_REPEAT + Xorg-1264 [002] ...1 18155.953775: kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRY + Xorg-1264 [002] ...1 18155.953777: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO + Xorg-1264 [002] ...1 18155.953783: kmalloc: call_site=ffffffff81419edb ptr=ffff8800721a2f00 bytes_req=64 bytes_alloc=64 gfp_flags=GFP_KERNEL|GFP_ZERO + <idle>-0 [000] ..s3 18156.176053: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + dropbear-1465 [000] ...1 18156.176257: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL + <idle>-0 [000] ..s3 18156.177717: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + <idle>-0 [000] ..s3 18156.399229: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + dropbear-1465 [000] ...1 18156.399434: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_http://rostedt.homelinux.com/kernelshark/req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL + <idle>-0 [000] ..s3 18156.400660: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC + matchbox-termin-1361 [001] ...1 18156.552800: kmalloc: call_site=ffffffff81614050 ptr=ffff88006db34800 bytes_req=576 bytes_alloc=1024 gfp_flags=GFP_KERNEL|GFP_REPEAT + </literallayout> + To again disable the kmalloc event, we need to send 0 to the + enable file: + <literallayout class='monospaced'> + root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 0 > enable + </literallayout> + You can enable any number of events or complete subsystems + (by using the 'enable' file in the subsystem directory) and + get am arbitrarily fine-grained idea of what's going on in the + system by enabling as many of the appropriate tracepoints + as applicable. + </para> + + <para> + A number of the tools described in this HOWTO do just that, + including trace-cmd and kernelshark in the next section. + </para> + + <note> + Tying It Together: These tracepoints and their representation + are used not only by ftrace, but by many of the other tools + covered in this document and they form a central point of + integration for the various tracers available in Linux. + They form a central part of the instrumentation for the + following tools: perf, lttng, ftrace, blktrace and SystemTap + </note> + + <note> + Tying It Together: Eventually all the special-purpose tracers + currently available in /sys/kernel/debug/tracing will be + removed and replaced with equivalent tracers based on the + 'trace events' subsystem. + </note> + </section> + + <section id='trace-cmd-kernelshark'> + <title>trace-cmd/kernelshark</title> + + <para> + trace-cmd is essentially an extensive command-line 'wrapper' + interface that hides the details of all the individual files + in /sys/kernel/debug/tracing, allowing users to specify + specific particular events within the + /sys/kernel/debug/tracing/events/ subdirectory and to collect + traces and avoiding having to deal with those details directly. + </para> + + <para> + As yet another layer on top of that, kernelshark provides a GUI + that allows users to start and stop traces and specify sets + of events using an intuitive interface, and view the + output as both trace events and as a per-cpu graphical + display. It directly uses 'trace-cmd' as the plumbing + that accomplishes all that underneath the covers (and + actually displays the trace-cmd command it uses, as we'll see). + </para> + + <para> + To start a trace using kernelshark, first start kernelshark: + <literallayout class='monospaced'> + root@sugarbay:~# kernelshark + </literallayout> + The bring up the 'Capture' dialog by choosing from the + kernelshark menu: + <literallayout class='monospaced'> + Capture | Record + </literallayout> + That will display the following dialog, which allows you to + choose on or more events (or even one or more complete + subsystems) to trace: + </para> + + <para> + <imagedata fileref="figures/kernelshark-choose-events.png" width="6in" depth="7in" align="center" scalefit="1" /> + </para> + + <para> + Note that these are exactly the same set of events described + in the previous trace events subsystem section, and in fact + is where trace-cmd gets them for kernelshark. + </para> + + <para> + In the above screenshot, we've decided to explore the + graphics subsystem a bit and so have chosen to trace all + the tracepoints contained within the 'i915' and 'drm' + subsystems. + </para> + + <para> + After doing that, we can start and stop the trace using + the 'Run' and 'Stop' button on the lower right corner of + the dialog (the same button will turn into the 'Stop' + button after the trace has started): + </para> + + <para> + <imagedata fileref="figures/kernelshark-output-display.png" width="6in" depth="7in" align="center" scalefit="1" /> + </para> + + <para> + Notice that the right-hand pane shows the exact trace-cmd + command-line that's used to run the trace, along with the + results of the trace-cmd run. + </para> + + <para> + Once the 'Stop' button is pressed, the graphical view magically + fills up with a colorful per-cpu display of the trace data, + along with the detailed event listing below that: + </para> + + <para> + <imagedata fileref="figures/kernelshark-i915-display.png" width="6in" depth="7in" align="center" scalefit="1" /> + </para> + + <para> + Here's another example, this time a display resulting + from tracing 'all events': + </para> + + <para> + <imagedata fileref="figures/kernelshark-all.png" width="6in" depth="7in" align="center" scalefit="1" /> + </para> + + <para> + The tool is pretty self-explanatory, but for more detailed + information on navigating through the data, see the + <ulink url='http://rostedt.homelinux.com/kernelshark/'>kernelshark website</ulink>. + </para> + </section> + + <section id='ftrace-documentation'> + <title>Documentation</title> + + <para> + The documentation for ftrace can be found in the kernel + Documentation directory: + <literallayout class='monospaced'> + Documentation/trace/ftrace.txt + </literallayout> + The documentation for the trace event subsystem can also + be found in the kernel Documentation directory: + <literallayout class='monospaced'> + Documentation/trace/events.txt + </literallayout> + There are a nice series of articles on using + ftrace and trace-cmd at LWN: + <itemizedlist> + <listitem><para><ulink url='http://lwn.net/Articles/365835/'>Debugging the kernel using Ftrace - part 1</ulink> + </para></listitem> + <listitem><para><ulink url='http://lwn.net/Articles/366796/'>Debugging the kernel using Ftrace - part 2</ulink> + </para></listitem> + <listitem><para><ulink url='https://lwn.net/Articles/410200/'>trace-cmd: A front-end for Ftrace</ulink> + </para></listitem> + </itemizedlist> + </para> + + <para> + There's more detailed documentation kernelshark usage here: + <ulink url='http://rostedt.homelinux.com/kernelshark/'>KernelShark</ulink> + </para> + + <para> + An amusing yet useful README (a tracing mini-HOWTO) can be + found in /sys/kernel/debug/tracing/README. + </para> + </section> +</section> + </chapter> <!-- vim: expandtab tw=80 ts=4 |
