。

我们还可以使用系统范围的 -a 开关来进行系统范围的跟踪。在这里，我们将跟踪几个调度程序事件：

root@crownbay:~# perf record -a -e sched:sched_switch -e sched:sched_wakeup
^C[ perf record: Woken up 38 times to write data ]
[ perf record: Captured and wrote 9.780 MB perf.data (~427299 samples) ]

我们可以使用不带参数的“perf script”查看原始输出：

root@crownbay:~# perf scriptperf  1383 [001]  6171.460045: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001perf  1383 [001]  6171.460066: sched_switch: prev_comm=perf prev_pid=1383 prev_prio=120 prev_state=R+ ==> next_comm=kworker/1:1 next_pid=21 next_prio=120kworker/1:1    21 [001]  6171.460093: sched_switch: prev_comm=kworker/1:1 prev_pid=21 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=1383 next_prio=120swapper     0 [000]  6171.468063: sched_wakeup: comm=kworker/0:3 pid=1209 prio=120 success=1 target_cpu=000swapper     0 [000]  6171.468107: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:3 next_pid=1209 next_prio=120kworker/0:3  1209 [000]  6171.468143: sched_switch: prev_comm=kworker/0:3 prev_pid=1209 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120perf  1383 [001]  6171.470039: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001perf  1383 [001]  6171.470058: sched_switch: prev_comm=perf prev_pid=1383 prev_prio=120 prev_state=R+ ==> next_comm=kworker/1:1 next_pid=21 next_prio=120kworker/1:1    21 [001]  6171.470082: sched_switch: prev_comm=kworker/1:1 prev_pid=21 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=1383 next_prio=120perf  1383 [001]  6171.480035: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001

root@crownbay:~# perf record -a -e sched:sched_switch --filter 'next_comm != perf && prev_comm != perf' -e sched:sched_wakeup --filter 'comm != perf'
^C[ perf record: Woken up 38 times to write data ]
[ perf record: Captured and wrote 9.688 MB perf.data (~423279 samples) ]root@crownbay:~# perf scriptswapper     0 [000]  7932.162180: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:3 next_pid=1209 next_prio=120kworker/0:3  1209 [000]  7932.162236: sched_switch: prev_comm=kworker/0:3 prev_pid=1209 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120perf  1407 [001]  7932.170048: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001perf  1407 [001]  7932.180044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001perf  1407 [001]  7932.190038: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001perf  1407 [001]  7932.200044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001perf  1407 [001]  7932.210044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001perf  1407 [001]  7932.220044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001swapper     0 [001]  7932.230111: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001swapper     0 [001]  7932.230146: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/1:1 next_pid=21 next_prio=120kworker/1:1    21 [001]  7932.230205: sched_switch: prev_comm=kworker/1:1 prev_pid=21 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120swapper     0 [000]  7932.326109: sched_wakeup: comm=kworker/0:3 pid=1209 prio=120 success=1 target_cpu=000swapper     0 [000]  7932.326171: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:3 next_pid=1209 next_prio=120kworker/0:3  1209 [000]  7932.326214: sched_switch: prev_comm=kworker/0:3 prev_pid=1209 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120

3.1.2.4使用动态跟踪点

perf 不限于“perf list”列出的一组固定的静态跟踪点。用户还可以在内核中的任何位置添加他们自己的“动态”跟踪点。例如，假设我们想在 do_fork() 上定义我们自己的跟踪点。我们可以使用“perf probe” perf 子命令来做到这一点：

root@crownbay:~# perf probe do_fork
Added new event:probe:do_fork        (on do_fork)You can now use it in all perf tools, such as:perf record -e probe:do_fork -aR sleep 1

通过“perf probe”添加新的跟踪点会产生一个事件，其中包含 /sys/kernel/debug/tracing/events 中的所有预期文件和格式，与静态跟踪点相同（如跟踪事件子系统中更详细的讨论）部分：

root@crownbay:/sys/kernel/debug/tracing/events/probe/do_fork# ls -al
drwxr-xr-x    2 root     root             0 Oct 28 11:42 .
drwxr-xr-x    3 root     root             0 Oct 28 11:42 ..
-rw-r--r--    1 root     root             0 Oct 28 11:42 enable
-rw-r--r--    1 root     root             0 Oct 28 11:42 filter
-r--r--r--    1 root     root             0 Oct 28 11:42 format
-r--r--r--    1 root     root             0 Oct 28 11:42 idroot@crownbay:/sys/kernel/debug/tracing/events/probe/do_fork# cat format
name: do_fork
ID: 944
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 __probe_ip;      offset:12;      size:4; signed:0;print fmt: "(%lx)", REC->__probe_ip

我们可以列出当前存在的所有动态跟踪点：

root@crownbay:~# perf probe -lprobe:do_fork (on do_fork)probe:schedule (on schedule)

让我们记录系统范围（'sleep 30' 是记录系统范围的技巧，但基本上什么都不做，然后在 30 秒后唤醒）：

root@crownbay:~# perf record -g -a -e probe:do_fork sleep 30
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.087 MB perf.data (~3812 samples) ]

使用 'perf script' 我们可以看到触发的每个 do_fork 事件：

root@crownbay:~# perf script# ========
# captured on: Sun Oct 28 11:55:18 2012
# hostname : crownbay
# os release : 3.4.11-yocto-standard
# perf version : 3.4.11
# arch : i686
# nrcpus online : 2
# nrcpus avail : 2
# cpudesc : Intel(R) Atom(TM) CPU E660 @ 1.30GHz
# cpuid : GenuineIntel,6,38,1
# total memory : 1017184 kB
# cmdline : /usr/bin/perf record -g -a -e probe:do_fork sleep 30
# event : name = probe:do_fork, type = 2, config = 0x3b0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern= 0, id = { 5, 6 }
# HEADER_CPU_TOPOLOGY info available, use -I to display
# ========
#matchbox-deskto  1197 [001] 34211.378318: do_fork: (c1028460)matchbox-deskto  1295 [001] 34211.380388: do_fork: (c1028460)pcmanfm  1296 [000] 34211.632350: do_fork: (c1028460)pcmanfm  1296 [000] 34211.639917: do_fork: (c1028460)matchbox-deskto  1197 [001] 34217.541603: do_fork: (c1028460)matchbox-deskto  1299 [001] 34217.543584: do_fork: (c1028460)gthumb  1300 [001] 34217.697451: do_fork: (c1028460)gthumb  1300 [001] 34219.085734: do_fork: (c1028460)gthumb  1300 [000] 34219.121351: do_fork: (c1028460)gthumb  1300 [001] 34219.264551: do_fork: (c1028460)pcmanfm  1296 [000] 34219.590380: do_fork: (c1028460)matchbox-deskto  1197 [001] 34224.955965: do_fork: (c1028460)matchbox-deskto  1306 [001] 34224.957972: do_fork: (c1028460)matchbox-termin  1307 [000] 34225.038214: do_fork: (c1028460)matchbox-termin  1307 [001] 34225.044218: do_fork: (c1028460)matchbox-termin  1307 [000] 34225.046442: do_fork: (c1028460)matchbox-deskto  1197 [001] 34237.112138: do_fork: (c1028460)matchbox-deskto  1311 [001] 34237.114106: do_fork: (c1028460)gaku  1312 [000] 34237.202388: do_fork: (c1028460)

在同一个文件上使用“性能报告”，我们可以看到在这 30 秒内启动几个程序的调用图：

IMAGE_INSTALL:append = " perf perf-doc"
DISTRO_FEATURES:append = " api-documentation"

tools/perf/Documentation

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

root@sugarbay:/sys/kernel/debug/tracing# cat available_tracers
blk function_graph function nop

root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer
nop

root@sugarbay:/sys/kernel/debug/tracing# echo function > current_tracer
root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer
function

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...

捆绑在一起

ftrace 函数跟踪器也可以从 perf 中获得，作为 ftrace:function tracepoint。

root@sugarbay:/sys/kernel/debug/tracing# echo function_graph > current_tracer
root@sugarbay:/sys/kernel/debug/tracing# cat trace | lesstracer: function_graphCPU  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() {

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

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

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

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"

root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 1 > enable

root@sugarbay:/sys/kernel/debug/tracing# echo nop > current_tracer
root@sugarbay:/sys/kernel/debug/tracing# echo 1 > tracing_on

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_REPEATXorg-1264  [002] ...1 18154.755581: kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRYXorg-1264  [002] ...1 18154.755583: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZEROXorg-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_REPEATXorg-1264  [002] ...1 18155.354703: kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRYXorg-1264  [002] ...1 18155.354705: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZEROXorg-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_ATOMICdropbear-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_ATOMICdropbear-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_ATOMICdropbear-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_REPEATXorg-1264  [002] ...1 18155.953775: kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRYXorg-1264  [002] ...1 18155.953777: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZEROXorg-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_ATOMICdropbear-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_ATOMICdropbear-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

root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 0 > enable

捆绑在一起

这些跟踪点及其表示不仅被 ftrace 使用，而且被本文档中涵盖的许多其他工具使用，它们构成了 Linux 中各种可用跟踪器的中心集成点。它们构成了以下工具检测的核心部分：perf、lttng、ftrace、blktrace 和 SystemTap

捆绑在一起

最终，/sys/kernel/debug/tracing 中当前可用的所有专用跟踪器都将被删除并替换为基于“跟踪事件”子系统的等效跟踪器。

root@sugarbay:~# kernelshark

Capture | Record

Documentation/trace/ftrace.txt

Documentation/trace/events.txt

$ crosstap root@192.168.1.88 trace_open.stpError: No target kernel build found.
Did you forget to create a local build of your image?'crosstap' requires a local sdk build of the target system
(or a build that includes 'tools-profile') in order to build
kernel modules that can probe the target system.Practically speaking, that means you need to do the following:- If you're running a pre-built image, download the release
   and/or BSP tarballs used to build the image.
 - If you're working from git sources, just clone the metadataand BSP layers needed to build the image you'll be booting.
 - Make sure you're properly set up to build a new image (seethe BSP README and/or the widely available basic documentationthat discusses how to build images).- Build an -sdk version of the image e.g.:$ bitbake core-image-sato-sdkOR- Build a non-sdk image but include the profiling tools:[ edit local.conf and add 'tools-profile' to the end ofthe EXTRA_IMAGE_FEATURES variable ]$ bitbake core-image-satoOnce you've build the image on the host system, you're ready to
boot it (or the equivalent pre-built image) and use 'crosstap'
to probe it (you need to source the environment as usual first):$ source oe-init-build-env$ cd ~/my/systemtap/scripts$ crosstap root@192.168.1.xxx myscript.stp

注意

SystemTap 使用“crosstap”，假设您可以建立到远程目标的 ssh 连接。有关验证 ssh 连接的详细信息，请参阅 crosstap wiki 页面。此外，默认情况下，*-minimal 图像中未启用 ssh 进入目标系统的功能。

注意

如果您有一个包含多台机器的构建目录，您需要在 local.conf 中选择您要连接的 MACHINE，并且该机器构建目录中的内核必须与引导系统上的内核完全匹配，否则您将获得当您尝试调用脚本时，上面的“crosstap”消息。

$ cd /path/to/yocto
$ source oe-init-build-env### Shell environment set up for builds. ###You can now run 'bitbake <target>'Common targets are:core-image-minimalcore-image-satometa-toolchainmeta-ide-supportYou can also run generated QEMU images with a command like 'runqemu qemux86-64'

$ cd /path/to/my/systemap/script
$ crosstap root@192.168.7.2 trace_open.stp

$ crosstap root@192.168.7.2 trace_open.stp
error establishing ssh connection on remote 'root@192.168.7.2'

$ ssh root@192.168.7.2

$ crosstap root@192.168.7.2 trace_open.stp
root@192.168.7.2's password:
matchbox-termin(1036) open ("/tmp/vte3FS2LW", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600)
matchbox-termin(1036) open ("/tmp/vteJMC7LW", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600)

捆绑在一起

如果您喜欢 sysprof 的“面向呼叫者”的显示，您也可以在其他工具中对其进行近似处理。例如，'perf report' 有 -g (–call-graph) 选项，您可以试验；选项之一是“调用者”，用于基于调用者的反向调用图显示。

3.5.2.1收集和查看目标上的跟踪（外壳内）

首先，从主机，ssh 到目标：

$ ssh -l root 192.168.1.47
The authenticity of host '192.168.1.47 (192.168.1.47)' can't be established.
RSA key fingerprint is 23:bd:c8:b1:a8:71:52:00:ee:00:4f:64:9e:10:b9:7e.
Are you sure you want to continue connecting (yes/no)? yes
Warning: Permanently added '192.168.1.47' (RSA) to the list of known hosts.
root@192.168.1.47's password:

到达目标后，使用以下步骤创建跟踪：

root@crownbay:~# lttng create
Spawning a session daemon
Session auto-20121015-232120 created.
Traces will be written in /home/root/lttng-traces/auto-20121015-232120

启用要跟踪的事件（在本例中为所有内核事件）：

root@crownbay:~# lttng enable-event --kernel --all
All kernel events are enabled in channel channel0

开始跟踪：

root@crownbay:~# lttng start
Tracing started for session auto-20121015-232120

然后在一段时间后或在运行要跟踪的特定工作负载后停止跟踪：

root@crownbay:~# lttng stop
Tracing stopped for session auto-20121015-232120

您现在可以在目标上以文本形式查看跟踪：

root@crownbay:~# lttng view
[23:21:56.989270399] (+?.?????????) sys_geteuid: { 1 }, { }
[23:21:56.989278081] (+0.000007682) exit_syscall: { 1 }, { ret = 0 }
[23:21:56.989286043] (+0.000007962) sys_pipe: { 1 }, { fildes = 0xB77B9E8C }
[23:21:56.989321802] (+0.000035759) exit_syscall: { 1 }, { ret = 0 }
[23:21:56.989329345] (+0.000007543) sys_mmap_pgoff: { 1 }, { addr = 0x0, len = 10485760, prot = 3, flags = 131362, fd = 4294967295, pgoff = 0 }
[23:21:56.989351694] (+0.000022349) exit_syscall: { 1 }, { ret = -1247805440 }
[23:21:56.989432989] (+0.000081295) sys_clone: { 1 }, { clone_flags = 0x411, newsp = 0xB5EFFFE4, parent_tid = 0xFFFFFFFF, child_tid = 0x0 }
[23:21:56.989477129] (+0.000044140) sched_stat_runtime: { 1 }, { comm = "lttng-consumerd", tid = 1193, runtime = 681660, vruntime = 43367983388 }
[23:21:56.989486697] (+0.000009568) sched_migrate_task: { 1 }, { comm = "lttng-consumerd", tid = 1193, prio = 20, orig_cpu = 1, dest_cpu = 1 }
[23:21:56.989508418] (+0.000021721) hrtimer_init: { 1 }, { hrtimer = 3970832076, clockid = 1, mode = 1 }
[23:21:56.989770462] (+0.000262044) hrtimer_cancel: { 1 }, { hrtimer = 3993865440 }
[23:21:56.989771580] (+0.000001118) hrtimer_cancel: { 0 }, { hrtimer = 3993812192 }
[23:21:56.989776957] (+0.000005377) hrtimer_expire_entry: { 1 }, { hrtimer = 3993865440, now = 79815980007057, function = 3238465232 }
[23:21:56.989778145] (+0.000001188) hrtimer_expire_entry: { 0 }, { hrtimer = 3993812192, now = 79815980008174, function = 3238465232 }
[23:21:56.989791695] (+0.000013550) softirq_raise: { 1 }, { vec = 1 }
[23:21:56.989795396] (+0.000003701) softirq_raise: { 0 }, { vec = 1 }
[23:21:56.989800635] (+0.000005239) softirq_raise: { 0 }, { vec = 9 }
[23:21:56.989807130] (+0.000006495) sched_stat_runtime: { 1 }, { comm = "lttng-consumerd", tid = 1193, runtime = 330710, vruntime = 43368314098 }
[23:21:56.989809993] (+0.000002863) sched_stat_runtime: { 0 }, { comm = "lttng-sessiond", tid = 1181, runtime = 1015313, vruntime = 36976733240 }
[23:21:56.989818514] (+0.000008521) hrtimer_expire_exit: { 0 }, { hrtimer = 3993812192 }
[23:21:56.989819631] (+0.000001117) hrtimer_expire_exit: { 1 }, { hrtimer = 3993865440 }
[23:21:56.989821866] (+0.000002235) hrtimer_start: { 0 }, { hrtimer = 3993812192, function = 3238465232, expires = 79815981000000, softexpires = 79815981000000 }
[23:21:56.989822984] (+0.000001118) hrtimer_start: { 1 }, { hrtimer = 3993865440, function = 3238465232, expires = 79815981000000, softexpires = 79815981000000 }
[23:21:56.989832762] (+0.000009778) softirq_entry: { 1 }, { vec = 1 }
[23:21:56.989833879] (+0.000001117) softirq_entry: { 0 }, { vec = 1 }
[23:21:56.989838069] (+0.000004190) timer_cancel: { 1 }, { timer = 3993871956 }
[23:21:56.989839187] (+0.000001118) timer_cancel: { 0 }, { timer = 3993818708 }
[23:21:56.989841492] (+0.000002305) timer_expire_entry: { 1 }, { timer = 3993871956, now = 79515980, function = 3238277552 }
[23:21:56.989842819] (+0.000001327) timer_expire_entry: { 0 }, { timer = 3993818708, now = 79515980, function = 3238277552 }
[23:21:56.989854831] (+0.000012012) sched_stat_runtime: { 1 }, { comm = "lttng-consumerd", tid = 1193, runtime = 49237, vruntime = 43368363335 }
[23:21:56.989855949] (+0.000001118) sched_stat_runtime: { 0 }, { comm = "lttng-sessiond", tid = 1181, runtime = 45121, vruntime = 36976778361 }
[23:21:56.989861257] (+0.000005308) sched_stat_sleep: { 1 }, { comm = "kworker/1:1", tid = 21, delay = 9451318 }
[23:21:56.989862374] (+0.000001117) sched_stat_sleep: { 0 }, { comm = "kworker/0:0", tid = 4, delay = 9958820 }
[23:21:56.989868241] (+0.000005867) sched_wakeup: { 0 }, { comm = "kworker/0:0", tid = 4, prio = 120, success = 1, target_cpu = 0 }
[23:21:56.989869358] (+0.000001117) sched_wakeup: { 1 }, { comm = "kworker/1:1", tid = 21, prio = 120, success = 1, target_cpu = 1 }
[23:21:56.989877460] (+0.000008102) timer_expire_exit: { 1 }, { timer = 3993871956 }
[23:21:56.989878577] (+0.000001117) timer_expire_exit: { 0 }, { timer = 3993818708 }
.
.
.

您现在可以安全地销毁跟踪会话（请注意，这不会删除跟踪 - 它仍然存在于 ~/lttng-traces 中）：

root@crownbay:~# lttng destroy
Session auto-20121015-232120 destroyed at /home/root

请注意，跟踪保存在与 'lttng create' 返回的同名目录中，位于 ~/lttng-traces 目录下（请注意，您可以通过将自己的名称提供给 'lttng create' 来更改此名称）：

root@crownbay:~# ls -al ~/lttng-traces
drwxrwx---    3 root     root          1024 Oct 15 23:21 .
drwxr-xr-x    5 root     root          1024 Oct 15 23:57 ..
drwxrwx---    3 root     root          1024 Oct 15 23:21 auto-20121015-232120

3.5.2.2收集和查看目标上的用户空间跟踪（在 shell 内）

对于 LTTng 用户空间跟踪，您需要有一个正确检测的用户空间程序。对于此示例，我们将使用 lttng-ust 构建生成的“hello”测试程序。

'hello' 测试程序没有通过 lttng-ust 构建安装在 rootfs 上，所以我们需要手动复制它。首先 cd 进入包含 hello 可执行文件的构建目录：

$ cd build/tmp/work/core2_32-poky-linux/lttng-ust/2.0.5-r0/git/tests/hello/.libs

将其复制到目标机器上：

$ scp hello root@192.168.1.20:

您现在已经在目标上安装了已检测的 lttng 'hello world' 测试程序，可以进行测试了。

首先，从主机，ssh 到目标：

$ ssh -l root 192.168.1.47
The authenticity of host '192.168.1.47 (192.168.1.47)' can't be established.
RSA key fingerprint is 23:bd:c8:b1:a8:71:52:00:ee:00:4f:64:9e:10:b9:7e.
Are you sure you want to continue connecting (yes/no)? yes
Warning: Permanently added '192.168.1.47' (RSA) to the list of known hosts.
root@192.168.1.47's password:

到达目标后，使用以下步骤创建跟踪：

root@crownbay:~# lttng create
Session auto-20190303-021943 created.
Traces will be written in /home/root/lttng-traces/auto-20190303-021943

启用要跟踪的事件（在本例中为所有用户空间事件）：

root@crownbay:~# lttng enable-event --userspace --all
All UST events are enabled in channel channel0

开始跟踪：

root@crownbay:~# lttng start
Tracing started for session auto-20190303-021943

运行检测的 hello world 程序：

root@crownbay:~# ./hello
Hello, World!
Tracing... done.

然后在一段时间后或在运行要跟踪的特定工作负载后停止跟踪：

root@crownbay:~# lttng stop
Tracing stopped for session auto-20190303-021943

您现在可以在目标上以文本形式查看跟踪：

root@crownbay:~# lttng view
[02:31:14.906146544] (+?.?????????) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 0, intfield2 = 0x0, longfield = 0, netintfield = 0, netintfieldhex = 0x0, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4,  seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[02:31:14.906170360] (+0.000023816) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 1, intfield2 = 0x1, longfield = 1, netintfield = 1, netintfieldhex = 0x1, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[02:31:14.906183140] (+0.000012780) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 2, intfield2 = 0x2, longfield = 2, netintfield = 2, netintfieldhex = 0x2, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[02:31:14.906194385] (+0.000011245) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 3, intfield2 = 0x3, longfield = 3, netintfield = 3, netintfieldhex = 0x3, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
.
.
.

您现在可以安全地销毁跟踪会话（请注意，这不会删除跟踪 - 它仍然存在于 ~/lttng-traces 中）：

root@crownbay:~# lttng destroy
Session auto-20190303-021943 destroyed at /home/root

root@crownbay:~# blktrace /dev/sdc

root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2; sync
Connecting to downloads.yoctoproject.org (140.211.169.59:80)
linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA

^C=== sdc ===CPU  0:                 7082 events,      332 KiB dataCPU  1:                 1578 events,       74 KiB dataTotal:                  8660 events (dropped 0),      406 KiB data

root@crownbay:~# ls -al
drwxr-xr-x    6 root     root          1024 Oct 27 22:39 .
drwxr-sr-x    4 root     root          1024 Oct 26 18:24 ..
-rw-r--r--    1 root     root        339938 Oct 27 22:40 sdc.blktrace.0
-rw-r--r--    1 root     root         75753 Oct 27 22:40 sdc.blktrace.1

root@crownbay:~# blkparse sdc8,32   1        1     0.000000000  1225  Q  WS 3417048 + 8 [jbd2/sdc-8]8,32   1        2     0.000025213  1225  G  WS 3417048 + 8 [jbd2/sdc-8]8,32   1        3     0.000033384  1225  P   N [jbd2/sdc-8]8,32   1        4     0.000043301  1225  I  WS 3417048 + 8 [jbd2/sdc-8]8,32   1        0     0.000057270     0  m   N cfq1225 insert_request8,32   1        0     0.000064813     0  m   N cfq1225 add_to_rr8,32   1        5     0.000076336  1225  U   N [jbd2/sdc-8] 18,32   1        0     0.000088559     0  m   N cfq workload slice:1508,32   1        0     0.000097359     0  m   N cfq1225 set_active wl_prio:0 wl_type:18,32   1        0     0.000104063     0  m   N cfq1225 Not idling. st->count:18,32   1        0     0.000112584     0  m   N cfq1225 fifo=  (null)8,32   1        0     0.000118730     0  m   N cfq1225 dispatch_insert8,32   1        0     0.000127390     0  m   N cfq1225 dispatched a request8,32   1        0     0.000133536     0  m   N cfq1225 activate rq, drv=18,32   1        6     0.000136889  1225  D  WS 3417048 + 8 [jbd2/sdc-8]8,32   1        7     0.000360381  1225  Q  WS 3417056 + 8 [jbd2/sdc-8]8,32   1        8     0.000377422  1225  G  WS 3417056 + 8 [jbd2/sdc-8]8,32   1        9     0.000388876  1225  P   N [jbd2/sdc-8]8,32   1       10     0.000397886  1225  Q  WS 3417064 + 8 [jbd2/sdc-8]8,32   1       11     0.000404800  1225  M  WS 3417064 + 8 [jbd2/sdc-8]8,32   1       12     0.000412343  1225  Q  WS 3417072 + 8 [jbd2/sdc-8]8,32   1       13     0.000416533  1225  M  WS 3417072 + 8 [jbd2/sdc-8]8,32   1       14     0.000422121  1225  Q  WS 3417080 + 8 [jbd2/sdc-8]8,32   1       15     0.000425194  1225  M  WS 3417080 + 8 [jbd2/sdc-8]8,32   1       16     0.000431968  1225  Q  WS 3417088 + 8 [jbd2/sdc-8]8,32   1       17     0.000435251  1225  M  WS 3417088 + 8 [jbd2/sdc-8]8,32   1       18     0.000440279  1225  Q  WS 3417096 + 8 [jbd2/sdc-8]8,32   1       19     0.000443911  1225  M  WS 3417096 + 8 [jbd2/sdc-8]8,32   1       20     0.000450336  1225  Q  WS 3417104 + 8 [jbd2/sdc-8]8,32   1       21     0.000454038  1225  M  WS 3417104 + 8 [jbd2/sdc-8]8,32   1       22     0.000462070  1225  Q  WS 3417112 + 8 [jbd2/sdc-8]8,32   1       23     0.000465422  1225  M  WS 3417112 + 8 [jbd2/sdc-8]8,32   1       24     0.000474222  1225  I  WS 3417056 + 64 [jbd2/sdc-8]8,32   1        0     0.000483022     0  m   N cfq1225 insert_request8,32   1       25     0.000489727  1225  U   N [jbd2/sdc-8] 18,32   1        0     0.000498457     0  m   N cfq1225 Not idling. st->count:18,32   1        0     0.000503765     0  m   N cfq1225 dispatch_insert8,32   1        0     0.000512914     0  m   N cfq1225 dispatched a request8,32   1        0     0.000518851     0  m   N cfq1225 activate rq, drv=2...8,32   0        0    58.515006138     0  m   N cfq3551 complete rqnoidle 18,32   0     2024    58.516603269     3  C  WS 3156992 + 16 [0]8,32   0        0    58.516626736     0  m   N cfq3551 complete rqnoidle 18,32   0        0    58.516634558     0  m   N cfq3551 arm_idle: 8 group_idle: 08,32   0        0    58.516636933     0  m   N cfq schedule dispatch8,32   1        0    58.516971613     0  m   N cfq3551 slice expired t=08,32   1        0    58.516982089     0  m   N cfq3551 sl_used=13 disp=6 charge=13 iops=0 sect=808,32   1        0    58.516985511     0  m   N cfq3551 del_from_rr8,32   1        0    58.516990819     0  m   N cfq3551 put_queueCPU0 (sdc):Reads Queued:           0,        0KiB       Writes Queued:         331,   26,284KiBRead Dispatches:        0,        0KiB       Write Dispatches:      485,   40,484KiBReads Requeued:         0            Writes Requeued:         0Reads Completed:        0,        0KiB       Writes Completed:      511,   41,000KiBRead Merges:            0,        0KiB       Write Merges:           13,      160KiBRead depth:             0            Write depth:             2IO unplugs:            23            Timer unplugs:           0
CPU1 (sdc):Reads Queued:           0,        0KiB       Writes Queued:         249,   15,800KiBRead Dispatches:        0,        0KiB       Write Dispatches:       42,    1,600KiBReads Requeued:         0            Writes Requeued:         0Reads Completed:        0,        0KiB       Writes Completed:       16,    1,084KiBRead Merges:            0,        0KiB       Write Merges:           40,      276KiBRead depth:             0            Write depth:             2IO unplugs:            30            Timer unplugs:           1Total (sdc):Reads Queued:           0,        0KiB       Writes Queued:         580,   42,084KiBRead Dispatches:        0,        0KiB       Write Dispatches:      527,   42,084KiBReads Requeued:         0            Writes Requeued:         0Reads Completed:        0,        0KiB       Writes Completed:      527,   42,084KiBRead Merges:            0,        0KiB       Write Merges:           53,      436KiBIO unplugs:            53            Timer unplugs:           1Throughput (R/W): 0KiB/s / 719KiB/s
Events (sdc): 6,592 entries
Skips: 0 forward (0 -   0.0%)
Input file sdc.blktrace.0 added
Input file sdc.blktrace.1 added

3.6.2.1直播模式

blktrace 和 blkparse 是从头开始设计的，能够在“管道模式”下一起运行，其中 blktrace 的标准输出可以直接输入 blkparse 的标准输入：

root@crownbay:~# blktrace /dev/sdc -o - | blkparse -i -

这使长期跟踪会话能够运行而无需向磁盘写入任何内容，并允许用户通过在屏幕上滚动或传递跟踪输出时查看跟踪输出来“实时”查找跟踪数据中的某些条件以及管道中的另一个程序，例如 grep，可用于识别和捕获感兴趣的条件。

实际上还有另一个 blktrace 命令将上述管道实现为单个命令，因此用户不必费心输入上述命令序列：

root@crownbay:~# btrace /dev/sdc

3.6.2.2远程使用 blktrace

因为 blktrace 跟踪块 I/O 并同时通常将其跟踪数据写入块设备，并且通常因为使被跟踪的设备与跟踪器写入的设备相同并不是一个好主意，所以 blktrace 提供通过提供对通过网络发送所有跟踪数据的本机支持，一种在完全不干扰被跟踪设备的情况下进行跟踪的方法。

要让 blktrace 在此模式下运行，请在使用 -l 选项跟踪的目标系统以及要跟踪的设备上启动 blktrace：

root@crownbay:~# blktrace -l /dev/sdc
server: waiting for connections...

在主机系统上，使用 -h 选项连接到目标系统，并将设备传递给它以进行跟踪：

$ blktrace -d /dev/sdc -h 192.168.1.43
blktrace: connecting to 192.168.1.43
blktrace: connected!

在目标系统上，您应该看到：

server: connection from 192.168.1.43

在另一个 shell 中，执行要跟踪的工作负载。

root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2; sync
Connecting to downloads.yoctoproject.org (140.211.169.59:80)
linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA

完成后，在主机系统上执行 Ctrl-C 以停止跟踪：

^C=== sdc ===CPU  0:                 7691 events,      361 KiB dataCPU  1:                 4109 events,      193 KiB dataTotal:                 11800 events (dropped 0),      554 KiB data

在目标系统上，您还应该看到刚刚结束的跟踪的跟踪摘要：

server: end of run for 192.168.1.43:sdc
=== sdc ===CPU  0:                 7691 events,      361 KiB dataCPU  1:                 4109 events,      193 KiB dataTotal:                 11800 events (dropped 0),      554 KiB data

主机上的 blktrace 实例会将目标输出保存在主机名时间戳目录中：

$ ls -al
drwxr-xr-x   10 root     root          1024 Oct 28 02:40 .
drwxr-sr-x    4 root     root          1024 Oct 26 18:24 ..
drwxr-xr-x    2 root     root          1024 Oct 28 02:40 192.168.1.43-2012-10-28-02:40:56

cd 进入该目录以查看输出文件：

$ ls -l
-rw-r--r--    1 root     root        369193 Oct 28 02:44 sdc.blktrace.0
-rw-r--r--    1 root     root        197278 Oct 28 02:44 sdc.blktrace.1

并使用设备名称在主机系统上运行 blkparse：

$ blkparse sdc8,32   1        1     0.000000000  1263  Q  RM 6016 + 8 [ls]8,32   1        0     0.000036038     0  m   N cfq1263 alloced8,32   1        2     0.000039390  1263  G  RM 6016 + 8 [ls]8,32   1        3     0.000049168  1263  I  RM 6016 + 8 [ls]8,32   1        0     0.000056152     0  m   N cfq1263 insert_request8,32   1        0     0.000061600     0  m   N cfq1263 add_to_rr8,32   1        0     0.000075498     0  m   N cfq workload slice:300...8,32   0        0   177.266385696     0  m   N cfq1267 arm_idle: 8 group_idle: 08,32   0        0   177.266388140     0  m   N cfq schedule dispatch8,32   1        0   177.266679239     0  m   N cfq1267 slice expired t=08,32   1        0   177.266689297     0  m   N cfq1267 sl_used=9 disp=6 charge=9 iops=0 sect=568,32   1        0   177.266692649     0  m   N cfq1267 del_from_rr8,32   1        0   177.266696560     0  m   N cfq1267 put_queueCPU0 (sdc):Reads Queued:           0,        0KiB       Writes Queued:         270,   21,708KiBRead Dispatches:       59,    2,628KiB       Write Dispatches:      495,   39,964KiBReads Requeued:         0            Writes Requeued:         0Reads Completed:       90,    2,752KiB       Writes Completed:      543,   41,596KiBRead Merges:            0,        0KiB       Write Merges:            9,      344KiBRead depth:             2            Write depth:             2IO unplugs:            20            Timer unplugs:           1
CPU1 (sdc):Reads Queued:         688,    2,752KiB       Writes Queued:         381,   20,652KiBRead Dispatches:       31,      124KiB       Write Dispatches:       59,    2,396KiBReads Requeued:         0            Writes Requeued:         0Reads Completed:        0,        0KiB       Writes Completed:       11,      764KiBRead Merges:          598,    2,392KiB       Write Merges:           88,      448KiBRead depth:             2            Write depth:             2IO unplugs:            52            Timer unplugs:           0Total (sdc):Reads Queued:         688,    2,752KiB       Writes Queued:         651,   42,360KiBRead Dispatches:       90,    2,752KiB       Write Dispatches:      554,   42,360KiBReads Requeued:         0            Writes Requeued:         0Reads Completed:       90,    2,752KiB       Writes Completed:      554,   42,360KiBRead Merges:          598,    2,392KiB       Write Merges:           97,      792KiBIO unplugs:            72            Timer unplugs:           1Throughput (R/W): 15KiB/s / 238KiB/s
Events (sdc): 9,301 entries
Skips: 0 forward (0 -   0.0%)

您应该看到跟踪事件和摘要，就像在目标上运行相同的命令一样。

3.6.2.3通过“ftrace”跟踪块 I/O

也可以仅使用“跟踪事件”子系统来跟踪块 I/O ，如果您不想费心处理用户空间工具，这对于临时跟踪非常有用。

要为给定设备启用跟踪，请使用 /sys/block/xxx/trace/enable，其中 xxx 是设备名称。例如，这将启用对 /dev/sdc 的跟踪：

root@crownbay:/sys/kernel/debug/tracing# echo 1 > /sys/block/sdc/trace/enable

选择要跟踪的设备后，选择“blk”跟踪器将打开 blk 跟踪器：

root@crownbay:/sys/kernel/debug/tracing# cat available_tracers
blk function_graph function noproot@crownbay:/sys/kernel/debug/tracing# echo blk > current_tracer

执行您感兴趣的工作负载：

root@crownbay:/sys/kernel/debug/tracing# cat /media/sdc/testfile.txt

并查看输出（请注意，此处我们使用“trace_pipe”而不是 trace 来捕获此跟踪 - 这允许我们在管道上等待数据出现）：

root@crownbay:/sys/kernel/debug/tracing# cat trace_pipecat-3587  [001] d..1  3023.276361:   8,32   Q   R 1699848 + 8 [cat]cat-3587  [001] d..1  3023.276410:   8,32   m   N cfq3587 allocedcat-3587  [001] d..1  3023.276415:   8,32   G   R 1699848 + 8 [cat]cat-3587  [001] d..1  3023.276424:   8,32   P   N [cat]cat-3587  [001] d..2  3023.276432:   8,32   I   R 1699848 + 8 [cat]cat-3587  [001] d..1  3023.276439:   8,32   m   N cfq3587 insert_requestcat-3587  [001] d..1  3023.276445:   8,32   m   N cfq3587 add_to_rrcat-3587  [001] d..2  3023.276454:   8,32   U   N [cat] 1cat-3587  [001] d..1  3023.276464:   8,32   m   N cfq workload slice:150cat-3587  [001] d..1  3023.276471:   8,32   m   N cfq3587 set_active wl_prio:0 wl_type:2cat-3587  [001] d..1  3023.276478:   8,32   m   N cfq3587 fifo=  (null)cat-3587  [001] d..1  3023.276483:   8,32   m   N cfq3587 dispatch_insertcat-3587  [001] d..1  3023.276490:   8,32   m   N cfq3587 dispatched a requestcat-3587  [001] d..1  3023.276497:   8,32   m   N cfq3587 activate rq, drv=1cat-3587  [001] d..2  3023.276500:   8,32   D   R 1699848 + 8 [cat]

这将关闭对指定设备的跟踪：

root@crownbay:/sys/kernel/debug/tracing# echo 0 > /sys/block/sdc/trace/enable

$ git clone git://git.kernel.dk/blktrace.git